diff --git a/QuickView/CompositionEngine.cpp b/QuickView/CompositionEngine.cpp index 3745e25..c106c41 100644 --- a/QuickView/CompositionEngine.cpp +++ b/QuickView/CompositionEngine.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "CompositionEngine.h" #include #include "TileManager.h" @@ -537,7 +538,7 @@ bool CompositionEngine::RefreshDisplayColorState(bool forceHdrSimulation) { m_surfaceFormat = m_isAdvancedColor ? DXGI_FORMAT_R16G16B16A16_FLOAT : DXGI_FORMAT_B8G8R8A8_UNORM; if (m_isAdvancedColor) { - OutputDebugStringW(L"[HDR] Advanced color active on current monitor. Using FP16 scRGB composition surfaces.\n"); + QV_LOG_INFO(L"[HDR] Advanced color active on current monitor. Using FP16 scRGB composition surfaces.\n"); } return changed; diff --git a/QuickView/ComputeEngine.cpp b/QuickView/ComputeEngine.cpp index 09bb274..46f305f 100644 --- a/QuickView/ComputeEngine.cpp +++ b/QuickView/ComputeEngine.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "ComputeEngine.h" #include #include @@ -291,7 +292,7 @@ HRESULT ComputeEngine::CompileShaders() { // 1. Format Convert HRESULT hr = D3DCompile(HLSL_FormatConvert, strlen(HLSL_FormatConvert), nullptr, nullptr, nullptr, "CSMain", "cs_5_0", D3DCOMPILE_OPTIMIZATION_LEVEL3, 0, &blob, &errorBlob); if (FAILED(hr)) { - if (errorBlob) OutputDebugStringA((char*)errorBlob->GetBufferPointer()); + if (errorBlob) QV_LOG(QV_LOG_LEVEL_ERROR, "ShaderError", TraceLoggingString((char*)errorBlob->GetBufferPointer(), "Error")); return hr; } hr = m_d3dDevice->CreateComputeShader(blob->GetBufferPointer(), blob->GetBufferSize(), nullptr, &m_csFormatConvert); @@ -308,7 +309,7 @@ HRESULT ComputeEngine::CompileShaders() { blob.Reset(); errorBlob.Reset(); hr = D3DCompile(HLSL_ToneMapHdrToSdr, strlen(HLSL_ToneMapHdrToSdr), nullptr, nullptr, nullptr, "CSToneMap", "cs_5_0", D3DCOMPILE_OPTIMIZATION_LEVEL3, 0, &blob, &errorBlob); if (FAILED(hr)) { - if (errorBlob) OutputDebugStringA((char*)errorBlob->GetBufferPointer()); + if (errorBlob) QV_LOG(QV_LOG_LEVEL_ERROR, "ShaderError", TraceLoggingString((char*)errorBlob->GetBufferPointer(), "Error")); return hr; } hr = m_d3dDevice->CreateComputeShader(blob->GetBufferPointer(), blob->GetBufferSize(), nullptr, &m_csToneMapHdrToSdr); @@ -318,7 +319,7 @@ HRESULT ComputeEngine::CompileShaders() { blob.Reset(); errorBlob.Reset(); hr = D3DCompile(HLSL_ToneMapHdrToHdr, strlen(HLSL_ToneMapHdrToHdr), nullptr, nullptr, nullptr, "CSToneMapHDR", "cs_5_0", D3DCOMPILE_OPTIMIZATION_LEVEL3, 0, &blob, &errorBlob); if (FAILED(hr)) { - if (errorBlob) OutputDebugStringA((char*)errorBlob->GetBufferPointer()); + if (errorBlob) QV_LOG(QV_LOG_LEVEL_ERROR, "ShaderError", TraceLoggingString((char*)errorBlob->GetBufferPointer(), "Error")); return hr; } hr = m_d3dDevice->CreateComputeShader(blob->GetBufferPointer(), blob->GetBufferSize(), nullptr, &m_csToneMapHdrToHdr); @@ -328,7 +329,7 @@ HRESULT ComputeEngine::CompileShaders() { blob.Reset(); errorBlob.Reset(); hr = D3DCompile(HLSL_ComposeGainMap, strlen(HLSL_ComposeGainMap), nullptr, nullptr, nullptr, "CSComposeGainMap", "cs_5_0", D3DCOMPILE_OPTIMIZATION_LEVEL3, 0, &blob, &errorBlob); if (FAILED(hr)) { - if (errorBlob) OutputDebugStringA((char*)errorBlob->GetBufferPointer()); + if (errorBlob) QV_LOG(QV_LOG_LEVEL_ERROR, "ShaderError", TraceLoggingString((char*)errorBlob->GetBufferPointer(), "Error")); return hr; } hr = m_d3dDevice->CreateComputeShader(blob->GetBufferPointer(), blob->GetBufferSize(), nullptr, &m_csComposeGainMap); @@ -653,11 +654,11 @@ HRESULT ComputeEngine::ComposeGainMap( ID3D11Texture2D** outTexture) { if (!m_valid || !sdrPixels || !gainPixels || !outTexture) { - OutputDebugStringW(L"[ComputeEngine] ComposeGainMap: Invalid arguments or engine state.\n"); + QV_LOG_INFO(L"[ComputeEngine] ComposeGainMap: Invalid arguments or engine state.\n"); return E_INVALIDARG; } if (sdrW <= 0 || sdrH <= 0 || gainW <= 0 || gainH <= 0) { - OutputDebugStringW(L"[ComputeEngine] ComposeGainMap: Invalid dimensions.\n"); + QV_LOG_INFO(L"[ComputeEngine] ComposeGainMap: Invalid dimensions.\n"); return E_INVALIDARG; } @@ -665,7 +666,7 @@ HRESULT ComputeEngine::ComposeGainMap( wchar_t logBuf[256]; swprintf_s(logBuf, L"[ComputeEngine] Compose: SDR %dx%d, Gain %dx%d, Headroom %.2f, MaxGain %.2f\n", sdrW, sdrH, gainW, gainH, payload.targetHeadroom, payload.gainMapMax[0]); - OutputDebugStringW(logBuf); + QV_LOG_INFO(logBuf); // 1. Upload SDR base layer (Can be BGRA8 or R32G32B32A32_FLOAT) D3D11_TEXTURE2D_DESC sdrDesc = {}; diff --git a/QuickView/HeavyLanePool.cpp b/QuickView/HeavyLanePool.cpp index 200b5f4..f0f9320 100644 --- a/QuickView/HeavyLanePool.cpp +++ b/QuickView/HeavyLanePool.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "HeavyLanePool.h" #include "ImageEngine.h" #include "ImageLoaderSimd.h" @@ -87,9 +88,9 @@ void HeavyLanePool::UpdateIOLimit(int newLimit) { } m_ioLimit.store(newLimit, std::memory_order_relaxed); - wchar_t buf[128]; - swprintf_s(buf, L"[HeavyPool] IO Limit set to %d (SSD=%s)\n", (int)m_ioLimit, newLimit > 2 ? L"Yes" : L"No"); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolIO", + TraceLoggingValue((int)m_ioLimit, "Limit"), + TraceLoggingWideString(newLimit > 2 ? L"Yes" : L"No", "SSD")); } void HeavyLanePool::SetTitanMode(bool enabled, int srcW, int srcH, const std::wstring& format) { @@ -115,10 +116,11 @@ void HeavyLanePool::SetTitanMode(bool enabled, int srcW, int srcH, const std::ws // Re-apply memory-aware concurrency (RAM may have changed) ApplyBaselineConcurrency(it->second.mps, srcW, srcH, it->second.isProgressive); - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Baseline CACHE HIT: %.2f MP/s → %d threads (%dx%d)\n", - it->second.mps, m_concurrencyLimit.load(), srcW, srcH); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolBaseline", + TraceLoggingValue(it->second.mps, "HIT"), + TraceLoggingValue(m_concurrencyLimit.load(), "threads"), + TraceLoggingValue(srcW, "srcW"), + TraceLoggingValue(srcH, "srcH")); TryExpand(); return; @@ -146,9 +148,8 @@ void HeavyLanePool::SetConcurrencyLimit(int limit) { TryExpand(); m_poolCv.notify_all(); - wchar_t buf[128]; - swprintf_s(buf, L"[HeavyPool] Concurrency Limit set to %d\n", limit); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolConcurrency", + TraceLoggingValue(limit, "to")); } void HeavyLanePool::SetUseThreadLocalHandle(bool use) { @@ -210,7 +211,7 @@ void HeavyLanePool::ResetBenchState() { m_lodCacheFailCount.store(0); // [B4] Reset fail counter on new image // IO type is set during Submit() via UpdateIOLimit - OutputDebugStringW(L"[HeavyPool] Baseline state RESET (Phase 5 Async GC). Phase: PENDING (2 threads).\n"); + QV_LOG_INFO(L"[HeavyPool] Baseline state RESET (Phase 5 Async GC). Phase: PENDING (2 threads).\n"); } // [Baseline Benchmark] Record performance from base layer decode @@ -221,11 +222,13 @@ void HeavyLanePool::RecordBaselineSample(double outPixels, double decodeMs, int double decodeMPS = (outPixels / 1000000.0) / (decodeMs / 1000.0); m_baselineMPS = decodeMPS; - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Baseline: %.2f MP/s (%.1f MP in %.0f ms, Src=%dx%d, %s)\n", - decodeMPS, outPixels / 1000000.0, decodeMs, srcWidth, srcHeight, - isProgressiveJPEG ? L"Progressive" : L"Baseline"); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolBaseline", + TraceLoggingValue(decodeMPS, "Baseline"), + TraceLoggingValue(outPixels / 1000000.0, "Arg1"), + TraceLoggingValue(decodeMs, "in"), + TraceLoggingValue(srcWidth, "Src"), + TraceLoggingValue(srcHeight, "Arg4"), + TraceLoggingWideString(isProgressiveJPEG ? L"Progressive" : L"Baseline", "Arg5")); ApplyBaselineConcurrency(decodeMPS, srcWidth, srcHeight, isProgressiveJPEG); } @@ -311,12 +314,12 @@ void HeavyLanePool::ApplyBaselineConcurrency(double decodeMPS, int srcWidth, int memoryLimitThreads = (perThreadMemory > 0) ? (int)(usableRAM / perThreadMemory) : 2; memoryLimitThreads = std::max(memoryLimitThreads, 2); // Floor: at least 2 - wchar_t memBuf[256]; - swprintf_s(memBuf, L"[HeavyPool] Memory: %.1f GB avail, %.1f GB/thread (%dx%d) → max %d threads\n", - (double)availableRAM / (1024.0 * 1024 * 1024), - (double)perThreadMemory / (1024.0 * 1024 * 1024), - srcWidth, srcHeight, memoryLimitThreads); - OutputDebugStringW(memBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolMemory", + TraceLoggingValue((double)availableRAM / (1024.0 * 1024 * 1024), "Memory"), + TraceLoggingValue((double)perThreadMemory / (1024.0 * 1024 * 1024), "avail"), + TraceLoggingValue(srcWidth, "Arg2"), + TraceLoggingValue(srcHeight, "Arg3"), + TraceLoggingValue(memoryLimitThreads, "max")); } } @@ -333,10 +336,10 @@ void HeavyLanePool::ApplyBaselineConcurrency(double decodeMPS, int srcWidth, int // Start at full capacity immediately — Regulator will throttle DOWN if needed. int initialLimit = bestThreads; - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Baseline Result: %.2f MP/s → Cap %d threads. Starting at %d via Regulator.\n", - decodeMPS, bestThreads, initialLimit); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolBaseline", + TraceLoggingValue(decodeMPS, "Result"), + TraceLoggingValue(bestThreads, "Cap"), + TraceLoggingValue(initialLimit, "at")); m_benchPhase = BenchPhase::DECIDED; SetConcurrencyLimit(initialLimit); @@ -391,10 +394,9 @@ void HeavyLanePool::UpdateConcurrency(int decodeMs, std::chrono::steady_clock::t m_regulator.avgLatency = 0; m_regulator.sampleCount = 0; - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Regulator: Latency High (%.0fms). Throttle DOWN to %d\n", - oldLatency, newLimit); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolRegulator", + TraceLoggingValue(oldLatency, "Arg0"), + TraceLoggingValue(newLimit, "to")); } } } else if (m_regulator.avgLatency < kLowLatencyThreshold) { @@ -414,10 +416,9 @@ void HeavyLanePool::UpdateConcurrency(int decodeMs, std::chrono::steady_clock::t m_regulator.avgLatency = 0; m_regulator.sampleCount = 0; - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Regulator: Latency Low (%.0fms). Throttle UP to %d\n", - oldLatency, newLimit); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolRegulator", + TraceLoggingValue(oldLatency, "Arg0"), + TraceLoggingValue(newLimit, "to")); } } } else { @@ -767,18 +768,17 @@ void HeavyLanePool::ResumeDeferredJobs(ImageID imageId, int lod) { m_activeTileJobs.fetch_add((int)toResume.size()); m_poolCv.notify_all(); - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Phase 4.1: Resumed %zu deferred tiles for LOD=%d\n", toResume.size(), lod); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolPhase", + TraceLoggingValue(toResume.size(), "Resumed"), + TraceLoggingValue(lod, "LOD")); } } void HeavyLanePool::WorkerLoop(int workerId, std::stop_token st) { Worker& self = m_workers[workerId]; - wchar_t buf[128]; - swprintf_s(buf, L"[HeavyPool] Worker %d started\n", workerId); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolWorker", + TraceLoggingValue(workerId, "Worker")); while (!st.stop_requested()) { JobInfo job; @@ -1205,7 +1205,7 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to bool warmupResolved = false; if (expectsMasterCache && m_masterWarmupImageId.load(std::memory_order_acquire) == job.imageId) { - OutputDebugStringW(L"[Phase4] Standard Job Waiting for Master Warmup...\n"); + QV_LOG_INFO(L"[Phase4] Standard Job Waiting for Master Warmup...\n"); std::unique_lock waitLock(m_lodCacheMutex); while (!m_masterWarmupReady.load(std::memory_order_acquire)) { if (cancelPred()) { @@ -1246,13 +1246,13 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to loaderName = L"MasterWarmup(MMF)"; hr = S_OK; warmupResolved = true; - OutputDebugStringW(L"[Phase4] Standard Job resolved via Master Warmup\n"); + QV_LOG_INFO(L"[Phase4] Standard Job resolved via Master Warmup\n"); } } } if (!warmupResolved) { - OutputDebugStringW(L"[Phase3] Titan Base Layer -> DecodeWorker subprocess\n"); + QV_LOG_INFO(L"[Phase3] Titan Base Layer -> DecodeWorker subprocess\n"); hr = LaunchDecodeWorker(self, job, targetW, targetH, rawFrame, meta, cancelPred); if (SUCCEEDED(hr)) { loaderName = L"DecodeWorker"; @@ -1322,7 +1322,7 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to // This would cause the auto-regulator to maliciously throttle the pool to < 3 threads, // crippling our N+1 Native Region Decoding. We simulate 100 MP/s to unlock full core usage! if (loaderName.contains(L"Fake Base")) { - OutputDebugStringW(L"[HeavyPool] Base Layer is Fake. Simulating 100.0 MP/s baseline to unlock Titan tiles.\n"); + QV_LOG_INFO(L"[HeavyPool] Base Layer is Fake. Simulating 100.0 MP/s baseline to unlock Titan tiles.\n"); RecordBaselineSample(10000000.0, 100.0, srcWidth, srcHeight, isProgressiveJPEG); } else { RecordBaselineSample(outPixels, (double)benchMs, srcWidth, srcHeight, isProgressiveJPEG); @@ -1334,7 +1334,7 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to if (m_titanFormat.load() == QuickView::TitanFormat::JXL) { if (loaderName.contains(L"Prog DC")) { m_isProgressiveJXL = true; - OutputDebugStringW(L"[HeavyPool] Detected Progressive JXL. Enabling native Region Decoding!\n"); + QV_LOG_INFO(L"[HeavyPool] Detected Progressive JXL. Enabling native Region Decoding!\n"); } else { m_isProgressiveJXL = false; } @@ -1345,7 +1345,7 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to // [Fix] If Base Layer decode aborted (e.g. Gigapixel JXL too massive for CPU), // MUST unlock concurrency so Native Region Decoding can blast through tiles! // We simulate a fast decode (100MP/s) to unlock ~14 threads. - OutputDebugStringW(L"[HeavyPool] Base Layer failed. Simulating 100MP/s baseline to unlock Titan tiles.\n"); + QV_LOG_INFO(L"[HeavyPool] Base Layer failed. Simulating 100MP/s baseline to unlock Titan tiles.\n"); RecordBaselineSample(10000000.0, 100.0, 10000, 10000, false); } } @@ -1354,10 +1354,13 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to // [Diagnostic] Trace missing tile (4,0) if (job.tileCoord.col == 4 && job.tileCoord.row == 0 && job.tileCoord.lod == 3) { float scale = 1.0f / (float)(1 << job.tileCoord.lod); - wchar_t diag[256]; - swprintf_s(diag, L"[HeavyPool] DIAGNOSTIC: Decoding Tile (4,0) LOD=%d. Region: x=%d y=%d w=%d h=%d Scale=%.4f\n", - job.tileCoord.lod, job.region.srcRect.x, job.region.srcRect.y, job.region.srcRect.w, job.region.srcRect.h, scale); - OutputDebugStringW(diag); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolDIAGNOSTIC", + TraceLoggingValue(job.tileCoord.lod, "LOD"), + TraceLoggingValue(job.region.srcRect.x, "x"), + TraceLoggingValue(job.region.srcRect.y, "y"), + TraceLoggingValue(job.region.srcRect.w, "w"), + TraceLoggingValue(job.region.srcRect.h, "h"), + TraceLoggingValue(scale, "Scale")); } { @@ -1416,19 +1419,15 @@ void HeavyLanePool::PerformDecode(int workerId, const JobInfo& job, std::stop_to uint64_t prev = s_lastStrategyLogMs.load(std::memory_order_relaxed); if (nowMs - prev > 500 && s_lastStrategyLogMs.compare_exchange_strong(prev, nowMs, std::memory_order_relaxed)) { - wchar_t strat[256]; - swprintf_s( - strat, - L"[HeavyPool] Strategy: fmt=%s lod=%d single=%s nativeROI=%s mandatory=%s webpOnce=%s jpgProgOnce=%s progressiveJXL=%s\n", - QuickView::TitanFormatToString(m_titanFormat.load()), - job.tileCoord.lod, - wantsSingleDecode ? L"Y" : L"N", - hasNativeRegionDecoder ? L"Y" : L"N", - isSingleDecodeMandatory ? L"Y" : L"N", - webpSingleDecode ? L"Y" : L"N", - jpegProgressiveSingleDecode ? L"Y" : L"N", - m_isProgressiveJXL ? L"Y" : L"N"); - OutputDebugStringW(strat); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolStrategy", + TraceLoggingWideString(QuickView::TitanFormatToString(m_titanFormat.load()), "fmt"), + TraceLoggingValue(job.tileCoord.lod, "lod"), + TraceLoggingWideString(wantsSingleDecode ? L"Y" : L"N", "single"), + TraceLoggingWideString(hasNativeRegionDecoder ? L"Y" : L"N", "nativeROI"), + TraceLoggingWideString(isSingleDecodeMandatory ? L"Y" : L"N", "mandatory"), + TraceLoggingWideString(webpSingleDecode ? L"Y" : L"N", "webpOnce"), + TraceLoggingWideString(jpegProgressiveSingleDecode ? L"Y" : L"N", "jpgProgOnce"), + TraceLoggingWideString(m_isProgressiveJXL ? L"Y" : L"N", "progressiveJXL")); } } @@ -1596,13 +1595,19 @@ tile_decode_done: ; // [P14] Jump target for fast path (skip legacy TJ decode) self.isCopyOnly = isCopyOnly; // Diagnostic: Result - wchar_t resultLog[256]; const wchar_t* opMode = (job.type == JobType::Tile) ? (isCopyOnly ? L"COPY" : L"DECODE") : L"DECODE"; - swprintf_s(resultLog, L"[HeavyPool] Worker %d: %s %s in %d ms (Wait: %lld ms, Concurrency: %d, Mode: %s, Loader: %s, hr=0x%08X)\n", - workerId, SUCCEEDED(hr) ? L"DONE" : L"FAIL", (job.type == JobType::Tile ? L"Tile" : L"Std"), (int)decodeMs, waitMs, activeWorkers, opMode, loaderName.c_str(), (uint32_t)hr); - OutputDebugStringW(resultLog); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolWorker", + TraceLoggingValue(workerId, "Worker"), + TraceLoggingWideString(SUCCEEDED(hr) ? L"DONE" : L"FAIL", "Arg1"), + TraceLoggingWideString((job.type == JobType::Tile ? L"Tile" : L"Std"), "Arg2"), + TraceLoggingValue((int)decodeMs, "in"), + TraceLoggingValue(waitMs, "Wait"), + TraceLoggingValue(activeWorkers, "Concurrency"), + TraceLoggingWideString(opMode, "Mode"), + TraceLoggingWideString(loaderName.c_str(), "Loader"), + TraceLoggingValue((uint32_t)hr, "hr0x")); @@ -1722,10 +1727,12 @@ tile_decode_done: ; // [P14] Jump target for fast path (skip legacy TJ decode) evt.rawFrame = safeFrame; // [Diagnostic] Trace Standard Job Output - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] Standard Job Done: W=%d H=%d Stride=%d Buffer=%zu Pixels=%p\n", - safeFrame->width, safeFrame->height, safeFrame->stride, bufferSize, safeFrame->pixels); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolStdJob", + TraceLoggingValue(safeFrame->width, "W"), + TraceLoggingValue(safeFrame->height, "H"), + TraceLoggingValue(safeFrame->stride, "Stride"), + TraceLoggingValue(bufferSize, "Buffer"), + TraceLoggingPointer(safeFrame->pixels, "Pixels")); } // [Fix] Compute histogram for HeavyLane results @@ -1746,10 +1753,11 @@ tile_decode_done: ; // [P14] Jump target for fast path (skip legacy TJ decode) tm->OnTileCancelled(key); // Reset to Empty -> Retry next frame // Log failure - wchar_t failLog[128]; - swprintf_s(failLog, L"[HeavyPool] Failed/Invalid Tile: (%d,%d) LOD=%d. HR=0x%X\n", - job.tileCoord.col, job.tileCoord.row, job.tileCoord.lod, hr); - OutputDebugStringW(failLog); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolFailedInvalid", + TraceLoggingValue(job.tileCoord.col, "Arg0"), + TraceLoggingValue(job.tileCoord.row, "Arg1"), + TraceLoggingValue(job.tileCoord.lod, "LOD"), + TraceLoggingValue(hr, "HR0x")); } } else { // [HEIC Fix] Explicitly notify Engine of Standard Load Failures @@ -1917,7 +1925,7 @@ void HeavyLanePool::WaitForTileJobs() { int active = m_activeTileJobs.load(); if (active == 0) return; - OutputDebugStringW(L"[HeavyPool] WaitForTileJobs: Waiting for workers to finish...\n"); + QV_LOG_INFO(L"[HeavyPool] WaitForTileJobs: Waiting for workers to finish...\n"); // Spin-wait with timeout (to prevent total freeze if bug) auto start = std::chrono::steady_clock::now(); @@ -1926,7 +1934,7 @@ void HeavyLanePool::WaitForTileJobs() { auto now = std::chrono::steady_clock::now(); if (std::chrono::duration_cast(now - start).count() > 5000) { - OutputDebugStringW(L"[HeavyPool] WaitForTileJobs: TIMEOUT! Forced continue. (Possible Leak)\n"); + QV_LOG_INFO(L"[HeavyPool] WaitForTileJobs: TIMEOUT! Forced continue. (Possible Leak)\n"); break; } } @@ -2030,16 +2038,15 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId int imgStride = imgW * 4; // BGRA packed if (imgW <= 0 || imgH <= 0) { - OutputDebugStringW(L"[MMF] Warmup aborted: unknown image dimensions\n"); + QV_LOG_INFO(L"[MMF] Warmup aborted: unknown image dimensions\n"); return; } // [Direct-to-MMF] Step 2: Pre-create empty MMF file HRESULT hr = BuildMasterBackingStoreEmpty(imgW, imgH, imgStride, imageId); if (FAILED(hr)) { - wchar_t fail[192]; - swprintf_s(fail, L"[MMF] Warmup: BuildMasterBackingStoreEmpty failed: hr=0x%X\n", hr); - OutputDebugStringW(fail); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFWarmup", + TraceLoggingValue(hr, "hr0x")); // Fallback to old heap-based path goto fallback_heap; } @@ -2085,9 +2092,10 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId std::lock_guard lock(m_lodCacheMutex); m_masterLOD0Cache = {}; - wchar_t ok[192]; - swprintf_s(ok, L"[MMF] Master warmup direct-to-MMF ready: %dx%d (%s)\n", decW, decH, QuickView::TitanFormatToString(m_titanFormat.load())); - OutputDebugStringW(ok); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFMaster", + TraceLoggingValue(decW, "ready"), + TraceLoggingValue(decH, "Arg1"), + TraceLoggingWideString(QuickView::TitanFormatToString(m_titanFormat.load()), "Arg2")); m_masterWarmupReady.store(true, std::memory_order_release); m_lodCacheCond.notify_all(); @@ -2098,7 +2106,7 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId fallback_heap: // Fallback: old heap-based FullDecodeFromMemory + BuildMasterBackingStore (memcpy) { - OutputDebugStringW(L"[MMF] Direct-to-MMF failed, fallback to heap decode\n"); + QV_LOG_INFO(L"[MMF] Direct-to-MMF failed, fallback to heap decode\n"); ResetMasterBackingStore(); // Clean up any partial empty MMF QuickView::RawImageFrame fullFrame; @@ -2127,9 +2135,9 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId if (st.stop_requested()) return; if (m_generationID.load(std::memory_order_acquire) != warmupGen) return; if (FAILED(hr) || !fullFrame.IsValid()) { - wchar_t fail[192]; - swprintf_s(fail, L"[HeavyPool] Master warmup failed: hr=0x%X (%s)\n", hr, QuickView::TitanFormatToString(m_titanFormat.load())); - OutputDebugStringW(fail); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolMaster", + TraceLoggingValue(hr, "hr0x"), + TraceLoggingWideString(QuickView::TitanFormatToString(m_titanFormat.load()), "Arg1")); return; } @@ -2138,16 +2146,17 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId std::lock_guard lock(m_lodCacheMutex); m_masterLOD0Cache = {}; - wchar_t ok[192]; - swprintf_s(ok, L"[HeavyPool] Master warmup ready (heap fallback): %dx%d (%s)\n", fullFrame.width, fullFrame.height, QuickView::TitanFormatToString(m_titanFormat.load())); - OutputDebugStringW(ok); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolMaster", + TraceLoggingValue(fullFrame.width, "fallback"), + TraceLoggingValue(fullFrame.height, "Arg1"), + TraceLoggingWideString(QuickView::TitanFormatToString(m_titanFormat.load()), "Arg2")); m_masterWarmupReady.store(true, std::memory_order_release); m_lodCacheCond.notify_all(); } else { - wchar_t fail[192]; - swprintf_s(fail, L"[HeavyPool] Master warmup MMF build failed: hr=0x%X (%s)\n", hr, QuickView::TitanFormatToString(m_titanFormat.load())); - OutputDebugStringW(fail); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolMaster", + TraceLoggingValue(hr, "hr0x"), + TraceLoggingWideString(QuickView::TitanFormatToString(m_titanFormat.load()), "Arg1")); } } }); @@ -2160,7 +2169,7 @@ void HeavyLanePool::EnsureMasterWarmup(const std::wstring& path, ImageID imageId void HeavyLanePool::GCThreadFunc(std::stop_token st) { // [Phase 5] Set low priority so GC never starves decode threads SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_BELOW_NORMAL); - OutputDebugStringW(L"[GC] Garbage Collector thread started (BELOW_NORMAL priority)\n"); + QV_LOG_INFO(L"[GC] Garbage Collector thread started (BELOW_NORMAL priority)\n"); std::vector localBatch; // Double-buffer: swap under lock, destroy outside lock @@ -2194,13 +2203,13 @@ void HeavyLanePool::GCThreadFunc(std::stop_token st) { auto t1 = std::chrono::high_resolution_clock::now(); int ms = (int)std::chrono::duration_cast(t1 - t0).count(); - wchar_t buf[128]; - swprintf_s(buf, L"[GC] Collected %d bags in %d ms\n", count, ms); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "GCCollected", + TraceLoggingValue(count, "Collected"), + TraceLoggingValue(ms, "in")); } } - OutputDebugStringW(L"[GC] Garbage Collector thread exiting\n"); + QV_LOG_INFO(L"[GC] Garbage Collector thread exiting\n"); } void HeavyLanePool::EnqueueTrash(TrashBag&& bag) { @@ -2231,7 +2240,7 @@ void HeavyLanePool::EnqueueTrash(TrashBag&& bag) { } } if (!localBatch.empty()) { - OutputDebugStringW(L"[GC] CRITICAL: Trash backlog exceeded threshold. Performing synchronous recovery.\n"); + QV_LOG_INFO(L"[GC] CRITICAL: Trash backlog exceeded threshold. Performing synchronous recovery.\n"); for (auto& bag : localBatch) { if (bag.backing.isPooled) { RelinquishToPool(std::move(bag.backing)); @@ -2265,9 +2274,9 @@ void HeavyLanePool::RelinquishToPool(MasterBackingStore&& store) { std::lock_guard lock(m_mmfPoolMutex); if (m_reservePool.size() < kMasterPoolCapacity) { m_reservePool.push_back(std::move(store)); - OutputDebugStringW(L"[MMFPool] Store returned to reserve pool (View kept mapped).\n"); + QV_LOG_INFO(L"[MMFPool] Store returned to reserve pool (View kept mapped).\n"); } else { - OutputDebugStringW(L"[MMFPool] Reserve pool full, destroying store.\n"); + QV_LOG_INFO(L"[MMFPool] Reserve pool full, destroying store.\n"); } } @@ -2403,11 +2412,10 @@ HRESULT HeavyLanePool::BuildMasterBackingStoreEmpty(int width, int height, int s // Do NOT clear the entire 5GB buffer to save ~100-300ms of CPU time. ZeroMemory(m_masterBacking.view, requiredBytes); - wchar_t msg[128]; - swprintf_s(msg, L"[MMFPool] REUSE Blackboard SUCCESS (View=%p, Size=%zu MB, CachedView=%s)\n", - m_masterBacking.view, requiredBytes / (1024*1024), - m_masterBacking.view ? L"YES" : L"NO"); - OutputDebugStringW(msg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFPoolREUSE", + TraceLoggingPointer(m_masterBacking.view, "View"), + TraceLoggingValue(requiredBytes / (1024*1024), "Size"), + TraceLoggingWideString(m_masterBacking.view ? L"YES" : L"NO", "CachedView")); return S_OK; } } @@ -2433,7 +2441,7 @@ HRESULT HeavyLanePool::BuildMasterBackingStoreEmpty(int width, int height, int s DWORD dwTemp = 0; if (!DeviceIoControl(hFile, FSCTL_SET_SPARSE, NULL, 0, NULL, 0, &dwTemp, NULL)) { // Fallback to normal if sparse fails for some reason (e.g. non-NTFS) - OutputDebugStringW(L"[MMFPool] WARNING: FSCTL_SET_SPARSE failed.\n"); + QV_LOG_INFO(L"[MMFPool] WARNING: FSCTL_SET_SPARSE failed.\n"); } // Step 2: Set file size (instantaneous on sparse files) @@ -2446,7 +2454,7 @@ HRESULT HeavyLanePool::BuildMasterBackingStoreEmpty(int width, int height, int s } // SE_MANAGE_VOLUME_NAME / SetFileValidData logic removed (Simplified) - OutputDebugStringW(L"[MMFPool] Sparse Allocation initialized.\n"); + QV_LOG_INFO(L"[MMFPool] Sparse Allocation initialized.\n"); HANDLE hMap = CreateFileMappingW(hFile, nullptr, PAGE_READWRITE, 0, 0, nullptr); if (!hMap) { @@ -2481,10 +2489,11 @@ HRESULT HeavyLanePool::BuildMasterBackingStoreEmpty(int width, int height, int s m_masterBacking.isPooled = usePool; } - wchar_t dbg[256]; - swprintf_s(dbg, L"[MMFPool] Global Master created: %s, Capacity=%zu MB, Initial=%dx%d\n", - usePool ? L"POOLED" : L"DYNAMIC", allocationSize / (1024*1024), width, height); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFPoolGlobal", + TraceLoggingWideString(usePool ? L"POOLED" : L"DYNAMIC", "created"), + TraceLoggingValue(allocationSize / (1024*1024), "Capacity"), + TraceLoggingValue(width, "Initial"), + TraceLoggingValue(height, "Arg3")); return S_OK; } @@ -2557,15 +2566,22 @@ bool HeavyLanePool::ShouldUseSingleDecode(int lod) const { if (lod != expected || lastLoggedLOD.compare_exchange_strong(expected, lod)) { lastLogTime.store(nowMs, std::memory_order_relaxed); lastLoggedLOD.store(lod, std::memory_order_relaxed); - wchar_t buf[256]; if (!fits) { - swprintf_s(buf, L"[HeavyPool] P14: LOD=%d fmt=%s SKIPPED (peak=%zu MB, avail=%zu MB)\n", - lod, QuickView::TitanFormatToString(singleFmt), peakBytes / (1024*1024), (size_t)(available / (1024*1024))); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingString("SKIPPED", "Status"), + TraceLoggingValue(lod, "LOD"), + TraceLoggingWideString(QuickView::TitanFormatToString(singleFmt), "fmt"), + TraceLoggingValue(peakBytes / (1024*1024), "peakMB"), + TraceLoggingValue((size_t)(available / (1024*1024)), "availMB")); } else { - swprintf_s(buf, L"[HeavyPool] P14: LOD=%d fmt=%s OK (output=%zu MB, peak=%zu MB, avail=%zu MB)\n", - lod, QuickView::TitanFormatToString(singleFmt), outputBytes / (1024*1024), peakBytes / (1024*1024), (size_t)(available / (1024*1024))); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingString("OK", "Status"), + TraceLoggingValue(lod, "LOD"), + TraceLoggingWideString(QuickView::TitanFormatToString(singleFmt), "fmt"), + TraceLoggingValue(outputBytes / (1024*1024), "outputMB"), + TraceLoggingValue(peakBytes / (1024*1024), "peakMB"), + TraceLoggingValue((size_t)(available / (1024*1024)), "availMB")); } - OutputDebugStringW(buf); } } @@ -2593,11 +2609,12 @@ bool HeavyLanePool::ShouldUseSingleDecodeForWebP(int lod) const { uint64_t prev = s_lastLogMs.load(std::memory_order_relaxed); if (nowMs - prev > 1000 && s_lastLogMs.compare_exchange_strong(prev, nowMs, std::memory_order_relaxed)) { - wchar_t buf[256]; - swprintf_s(buf, - L"[HeavyPool] WebP SingleDecode Guard: LOD=%d req=%.1fMB avail=%.1fMB limit=%.1fMB -> %s\n", - lod, requiredRamMB, availableRamMB, availableRamMB * 0.40, canSingleDecode ? L"Y" : L"N"); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolWebP", + TraceLoggingValue(lod, "LOD"), + TraceLoggingValue(requiredRamMB, "req"), + TraceLoggingValue(availableRamMB, "avail"), + TraceLoggingValue(availableRamMB * 0.40, "limit"), + TraceLoggingWideString(canSingleDecode ? L"Y" : L"N", "Arg4")); } return canSingleDecode; @@ -2691,7 +2708,7 @@ HRESULT HeavyLanePool::LaunchDecodeWorker( WaitForSingleObject(worker.activeWorkerProcess, 500); CloseHandle(worker.activeWorkerProcess); worker.activeWorkerProcess = nullptr; - OutputDebugStringW(L"[Phase4] Killed lingering old DecodeWorker\n"); + QV_LOG_INFO(L"[Phase4] Killed lingering old DecodeWorker\n"); } STARTUPINFOW si{}; @@ -2716,7 +2733,7 @@ HRESULT HeavyLanePool::LaunchDecodeWorker( // [Phase 4.1] Double check cancel immediately AFTER creating process if (checkCancel && checkCancel()) { - OutputDebugStringW(L"[Phase4.1] Instantly killed new DecodeWorker due to cancel\n"); + QV_LOG_INFO(L"[Phase4.1] Instantly killed new DecodeWorker due to cancel\n"); TerminateProcess(pi.hProcess, static_cast(E_ABORT)); // We let the wait loop handle cleanup } @@ -2730,10 +2747,10 @@ HRESULT HeavyLanePool::LaunchDecodeWorker( worker.activeWorkerProcess = pi.hProcess; { - wchar_t dbg[256]; - swprintf_s(dbg, L"[Phase4] DecodeWorker launched: PID=%lu target=%dx%d\n", - pi.dwProcessId, targetW, targetH); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "Phase4DecodeWorker", + TraceLoggingValue(pi.dwProcessId, "PID"), + TraceLoggingValue(targetW, "target"), + TraceLoggingValue(targetH, "Arg2")); } // Poll loop: 15ms intervals, check for cancellation @@ -2745,7 +2762,7 @@ HRESULT HeavyLanePool::LaunchDecodeWorker( if (waitRes == WAIT_TIMEOUT) { if (checkCancel && checkCancel()) { - OutputDebugStringW(L"[Phase3] DecodeWorker KILLED by cancel\n"); + QV_LOG_INFO(L"[Phase3] DecodeWorker KILLED by cancel\n"); TerminateProcess(pi.hProcess, static_cast(E_ABORT)); WaitForSingleObject(pi.hProcess, 1000); waitHr = E_ABORT; @@ -2822,10 +2839,11 @@ HRESULT HeavyLanePool::LaunchDecodeWorker( outMeta.Height = static_cast(header->originalHeight); { - wchar_t dbg[256]; - swprintf_s(dbg, L"[Phase4] DecodeWorker OK (ZeroCopy): %dx%d stride=%d exif=%d\n", - outFrame.width, outFrame.height, outFrame.stride, header->exifOrientation); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "Phase4DecodeWorker", + TraceLoggingValue(outFrame.width, "ZeroCopy"), + TraceLoggingValue(outFrame.height, "Arg1"), + TraceLoggingValue(outFrame.stride, "stride"), + TraceLoggingValue(header->exifOrientation, "exif")); } return S_OK; @@ -2872,10 +2890,11 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, m_lodCache = {}; } - wchar_t buf[256]; - swprintf_s(buf, L"[HeavyPool] P14: Full decode LOD=%d (scale=%.4f, src=%dx%d)...\n", - lod, scale, m_titanSrcW, m_titanSrcH); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingValue(lod, "LOD"), + TraceLoggingValue(scale, "scale"), + TraceLoggingValue(m_titanSrcW, "src"), + TraceLoggingValue(m_titanSrcH, "Arg3")); auto t0 = std::chrono::high_resolution_clock::now(); @@ -2937,9 +2956,10 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; hr = S_OK; - wchar_t dbg[128]; - swprintf_s(dbg, L"[P15] Master built + Instant software downscale → %dx%d (LOD=%d)\n", targetW, targetH, lod); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15Master", + TraceLoggingValue(targetW, "Arg0"), + TraceLoggingValue(targetH, "Arg1"), + TraceLoggingValue(lod, "LOD")); } } else { if (masterFromRam) { @@ -2951,7 +2971,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.format = QuickView::PixelFormat::BGRA8888; fullFrame.memoryDeleter = [masterPixels](uint8_t* p) mutable { masterPixels.reset(); }; hr = S_OK; - OutputDebugStringW(L"[P15] Master built + Instant Zero-Copy for LOD 0\n"); + QV_LOG_INFO(L"[P15] Master built + Instant Zero-Copy for LOD 0\n"); } else { // MMF-backed cache: keep stable ownership by copying out for this one request. size_t dstSize = dstStride * targetH; @@ -2971,7 +2991,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.format = QuickView::PixelFormat::BGRA8888; fullFrame.memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; hr = S_OK; - OutputDebugStringW(L"[P15] Master MMF + Copy-out for LOD 0\n"); + QV_LOG_INFO(L"[P15] Master MMF + Copy-out for LOD 0\n"); } } } @@ -2985,7 +3005,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, if (expectsMasterCache && m_masterWarmupImageId.load(std::memory_order_acquire) == job.imageId) { // Warmup is building the Master Cache — wait for it - OutputDebugStringW(L"[Phase4] Waiting for Master Warmup (Direct-to-MMF) instead of launching subprocess...\n"); + QV_LOG_INFO(L"[Phase4] Waiting for Master Warmup (Direct-to-MMF) instead of launching subprocess...\n"); std::unique_lock waitLock(m_lodCacheMutex); while (!m_masterWarmupReady.load(std::memory_order_acquire)) { @@ -2997,7 +3017,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, // Check if image changed while waiting if (m_masterWarmupImageId.load(std::memory_order_acquire) != job.imageId) { - OutputDebugStringW(L"[Phase4] Warmup image changed while waiting, aborting\n"); + QV_LOG_INFO(L"[Phase4] Warmup image changed while waiting, aborting\n"); guard.countFailure = false; return E_ABORT; } @@ -3033,14 +3053,15 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; hr = S_OK; - wchar_t dbg[128]; - swprintf_s(dbg, L"[P15] Master built + Software downscale → %dx%d (LOD=%d)\n", targetW, targetH, lod); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15Master", + TraceLoggingValue(targetW, "Arg0"), + TraceLoggingValue(targetH, "Arg1"), + TraceLoggingValue(lod, "LOD")); } else { hr = E_OUTOFMEMORY; } } else { - OutputDebugStringW(L"[Phase4] Warmup completed but no Master Cache available — fallback to subprocess\n"); + QV_LOG_INFO(L"[Phase4] Warmup completed but no Master Cache available — fallback to subprocess\n"); hr = E_FAIL; // Will fall through to subprocess below } if (SUCCEEDED(hr)) warmupResolved = true; @@ -3056,7 +3077,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, if (!expectsMasterCache) { reqW = targetW; reqH = targetH; - OutputDebugStringW(L"[Phase4] Skipping Master cache construction. Requesting LOD size directly from DecodeWorker.\n"); + QV_LOG_INFO(L"[Phase4] Skipping Master cache construction. Requesting LOD size directly from DecodeWorker.\n"); } CImageLoader::ImageMetadata lodMeta; @@ -3084,7 +3105,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, hr = m_loader->LoadToFrame(job.path.c_str(), &fullFrame, nullptr, targetW, targetH, &loader, checkCancel, nullptr, true, false, job.targetHdrHeadroomStops); if (SUCCEEDED(hr)) { loader = L"WIC(LOD-Fallback)"; - OutputDebugStringW(L"[Phase4] Inline WIC fallback succeeded\n"); + QV_LOG_INFO(L"[Phase4] Inline WIC fallback succeeded\n"); } } @@ -3112,7 +3133,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, if (shouldBuildBacking) { if (SUCCEEDED(BuildMasterBackingStore(frameSharedPtr.get(), fullFrame.width, fullFrame.height, fullFrame.stride, job.imageId))) { backedByMmf = true; - OutputDebugStringW(L"[Phase4] Master cache persisted to MMF backing store\n"); + QV_LOG_INFO(L"[Phase4] Master cache persisted to MMF backing store\n"); } } @@ -3149,9 +3170,10 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.stride = (int)dstStride; fullFrame.memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; - wchar_t dbg[128]; - swprintf_s(dbg, L"[P15] Master built + Software downscale → %dx%d (LOD=%d)\n", targetW, targetH, lod); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15Master", + TraceLoggingValue(targetW, "Arg0"), + TraceLoggingValue(targetH, "Arg1"), + TraceLoggingValue(lod, "LOD")); } } else { fullFrame.pixels = frameSharedPtr.get(); @@ -3160,7 +3182,7 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.stride = (int)dstStride; fullFrame.memoryDeleter = [frameSharedPtr](uint8_t* p) mutable { frameSharedPtr.reset(); }; - OutputDebugStringW(L"[P15] Master built + Zero-Copy for LOD 0\n"); + QV_LOG_INFO(L"[P15] Master built + Zero-Copy for LOD 0\n"); } } else { // [Direct LOD] Bypassed Master Cache. Subprocess already returned exact LOD target size. @@ -3170,9 +3192,9 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, fullFrame.stride = fullFrame.stride; fullFrame.memoryDeleter = [frameSharedPtr](uint8_t* p) mutable { frameSharedPtr.reset(); }; - wchar_t dbg[128]; - swprintf_s(dbg, L"[Phase4] Subprocess rendered directly to LOD size: %dx%d. Applied instantly.\n", fullFrame.width, fullFrame.height); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "Phase4Subprocess", + TraceLoggingValue(fullFrame.width, "size"), + TraceLoggingValue(fullFrame.height, "Arg1")); } } } @@ -3184,8 +3206,8 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, } if (FAILED(hr) || !fullFrame.IsValid()) { - swprintf_s(buf, L"[HeavyPool] P14: Full decode FAILED (hr=0x%X)\n", hr); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingValue(hr, "hr0x")); return hr; } @@ -3195,19 +3217,22 @@ HRESULT HeavyLanePool::FullDecodeAndCacheLOD(Worker& worker, const JobInfo& job, const int expectedW = (m_titanSrcW + (1 << lod) - 1) / (1 << lod); const int expectedH = (m_titanSrcH + (1 << lod) - 1) / (1 << lod); if (fullFrame.width + 1 < expectedW || fullFrame.height + 1 < expectedH) { - swprintf_s(buf, - L"[HeavyPool] P14: Full decode INVALID size %dx%d (< expected %dx%d). Rejecting cache.\n", - fullFrame.width, fullFrame.height, expectedW, expectedH); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingValue(fullFrame.width, "size"), + TraceLoggingValue(fullFrame.height, "Arg1"), + TraceLoggingValue(expectedW, "expected"), + TraceLoggingValue(expectedH, "Arg3")); return E_FAIL; } auto t1 = std::chrono::high_resolution_clock::now(); int decodeMs = (int)std::chrono::duration_cast(t1 - t0).count(); - swprintf_s(buf, L"[HeavyPool] P14: Full decode DONE in %d ms → %dx%d (%zu MB cached)\n", - decodeMs, fullFrame.width, fullFrame.height, fullFrame.GetBufferSize() / (1024*1024)); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "HeavyPoolP14", + TraceLoggingValue(decodeMs, "in"), + TraceLoggingValue(fullFrame.width, "Arg1"), + TraceLoggingValue(fullFrame.height, "Arg2"), + TraceLoggingValue(fullFrame.GetBufferSize() / (1024*1024), "Arg3")); // Cache the full decoded buffer { diff --git a/QuickView/ImageEngine.cpp b/QuickView/ImageEngine.cpp index f766d94..7bd4e39 100644 --- a/QuickView/ImageEngine.cpp +++ b/QuickView/ImageEngine.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "ImageEngine.h" #include "FileNavigator.h" #include "HeavyLanePool.h" // [N+1] Include pool implementation @@ -40,12 +41,10 @@ ImageEngine::ImageEngine(CImageLoader* loader) m_tileManager = std::make_shared(); // Debug output - wchar_t buf[256]; - swprintf_s(buf, L"[ImageEngine] N+1 Pool: Tier=%s (Arena: %s), MaxWorkers=%d\n", - m_engineConfig.GetTierName(), - m_pool.GetConfig().GetModeName(), - m_engineConfig.maxHeavyWorkers); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "ImageEngineN1", + TraceLoggingWideString(m_engineConfig.GetTierName(), "Tier"), + TraceLoggingWideString(m_pool.GetConfig().GetModeName(), "Arena"), + TraceLoggingValue(m_engineConfig.maxHeavyWorkers, "MaxWorkers")); } ImageEngine::~ImageEngine() { @@ -100,7 +99,7 @@ void ImageEngine::RequestFullDecode(const std::wstring& path, ImageID imageId) { // Only proceed if this is still the current image if (imageId != m_currentImageId.load()) { - OutputDebugStringW(L"[FullDecode] RequestFullDecode cancelled - image changed\n"); + QV_LOG_INFO(L"[FullDecode] RequestFullDecode cancelled - image changed\n"); return; } @@ -108,7 +107,7 @@ void ImageEngine::RequestFullDecode(const std::wstring& path, ImageID imageId) { // The Base Layer is already loaded (Scaled). We do NOT want a Full Decode // because it causes OOM/Seconds-long stall and logic issue. if (m_mmf && m_mmf->IsValid()) { - OutputDebugStringW(L"[FullDecode] RequestFullDecode skipped - Titan Mode Active (Tiles Handle Detail)\n"); + QV_LOG_INFO(L"[FullDecode] RequestFullDecode skipped - Titan Mode Active (Tiles Handle Detail)\n"); return; } @@ -118,9 +117,8 @@ void ImageEngine::RequestFullDecode(const std::wstring& path, ImageID imageId) { // It's safe to pass m_mmf (member) here. m_heavyPool->SubmitFullDecode(path, imageId, m_mmf); - wchar_t buf[256]; - swprintf_s(buf, L"[FullDecode] Full decode requested: ImageID=%zu\n", imageId); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "FullDecodeFull", + TraceLoggingValue(imageId, "ImageID")); } // [Phase 2] Dispatcher Implementation @@ -195,10 +193,11 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u m_tileManager->InvalidateAll(); // Reset generation wchar_t debugBuf[256]; - swprintf_s(debugBuf, L"[Dispatch] Titan Mode ENABLED (%dx%d, %s) MMF=%s\n", - info.width, info.height, fmtUpper.c_str(), - (m_mmf && m_mmf->IsValid()) ? L"OK" : L"FAIL"); - OutputDebugStringW(debugBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "DispatchTitan", + TraceLoggingValue(info.width, "Arg0"), + TraceLoggingValue(info.height, "Arg1"), + TraceLoggingWideString(fmtUpper.c_str(), "Arg2"), + TraceLoggingWideString((m_mmf && m_mmf->IsValid()) ? L"OK" : L"FAIL", "MMF")); // [Scientific 2.0] Enable Titan Mode - pool handles dynamic concurrency via Scout phase. // SetTitanMode(true) resets scout state, sets initial concurrency to 2, @@ -247,12 +246,12 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u const int cacheH = frameUsable ? cachedFrame->height : 0; InvalidateCache(path); cachedFrame.reset(); - wchar_t dbg[256]; - swprintf_s(dbg, - L"[Dispatch] JXL cache bypass: frame=%dx%d meta=%dx%d titan=%d\n", - cacheW, cacheH, - info.width, info.height, enableTitan ? 1 : 0); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "DispatchJXL", + TraceLoggingValue(cacheW, "frame"), + TraceLoggingValue(cacheH, "Arg1"), + TraceLoggingValue(info.width, "meta"), + TraceLoggingValue(info.height, "Arg3"), + TraceLoggingValue(enableTitan ? 1 : 0, "titan")); } } @@ -319,13 +318,13 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u const wchar_t* typeName = L"Invalid"; if (info.type == CImageLoader::ImageType::TypeA_Sprint) typeName = L"TypeA_Sprint"; else if (info.type == CImageLoader::ImageType::TypeB_Heavy) typeName = L"TypeB_Heavy"; - swprintf_s(buf, L"[Dispatch] %s: %dx%d (%.1f MP), Format=%s, Type=%s\n", - path.substr(path.find_last_of(L"\\/") + 1).c_str(), - info.width, info.height, - (double)(info.width * info.height) / 1000000.0, - info.format.c_str(), - typeName); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "Dispatchs", + TraceLoggingWideString(path.substr(path.find_last_of(L"\\/") + 1).c_str(), "LDispatch"), + TraceLoggingValue(info.width, "Arg1"), + TraceLoggingValue(info.height, "Arg2"), + TraceLoggingValue((double)(info.width * info.height) / 1000000.0, "Arg3"), + TraceLoggingWideString(info.format.c_str(), "Format"), + TraceLoggingWideString(typeName, "Type")); } // Update State for UI @@ -344,7 +343,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u // IDCT 1/8 scaling produces ~3-8MP preview (sufficient for 4K screens). // Tiles are triggered by main.cpp OnPaint only when zoom > basePreviewRatio. - OutputDebugStringW(L"[Dispatch] Titan Active: Routing Base Layer to Heavy Lane\n"); + QV_LOG_INFO(L"[Dispatch] Titan Active: Routing Base Layer to Heavy Lane\n"); } // 2. Recursive RAW Check @@ -368,7 +367,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u // Threshold: 2.5 MP (Conservative) // If embedded preview is huge, it will block FastLane. Force Heavy Lane. if (embPixels > 2500000) { - OutputDebugStringW(L"[Dispatch] RAW Embedded Preview TOO LARGE -> Force Heavy Lane\n"); + QV_LOG_INFO(L"[Dispatch] RAW Embedded Preview TOO LARGE -> Force Heavy Lane\n"); // Override Classification: Treat as Heavy info.type = CImageLoader::ImageType::TypeB_Heavy; } @@ -398,7 +397,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u useHeavy = false; } else { // [v7.2 Fix] Large WebP -> Force Heavy Direct (non-Titan is full decode). - OutputDebugStringW(L"[Dispatch] -> WebP Large: Heavy Direct\n"); + QV_LOG_INFO(L"[Dispatch] -> WebP Large: Heavy Direct\n"); m_heavyPool->Submit(path, imageId, primaryMMF); return; } @@ -413,7 +412,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u std::transform(fmtLower.begin(), fmtLower.end(), fmtLower.begin(), ::towlower); if (fmtLower == L"webp") { - OutputDebugStringW(L"[Dispatch] -> WebP Heavy: Heavy Direct\n"); + QV_LOG_INFO(L"[Dispatch] -> WebP Heavy: Heavy Direct\n"); m_heavyPool->Submit(path, imageId, primaryMMF); // Base Layer Scaled return; } @@ -435,7 +434,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u ((uint64_t)info.width * info.height < 2000000); if (isSmall) { - OutputDebugStringW(L"[Dispatch] -> JXL Small: FastLane Direct Full\n"); + QV_LOG_INFO(L"[Dispatch] -> JXL Small: FastLane Direct Full\n"); // FastLane will use target=0 if detected as small m_fastLane.Push(path, imageId, m_targetHdrHeadroomStops.load(std::memory_order_relaxed)); } @@ -443,7 +442,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u if (enableTitan) { // [v8.5] Hard Dispatch: Large JXL (>2MP or >3MB) // Skip FastLane entirely. HeavyLane handles everything (Deep Cancel Relay). - OutputDebugStringW(L"[Dispatch] -> JXL Titan: Heavy Direct (Skip FastLane)\n"); + QV_LOG_INFO(L"[Dispatch] -> JXL Titan: Heavy Direct (Skip FastLane)\n"); // [Fix] Stage 2 Trigger explicitly needs these to be set for the pending heavy decode m_pendingJxlHeavyPath = path; @@ -453,7 +452,7 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u } else { // [v3.2.5 Restore] 普通非Titan大型大图,像旧版一样直接跑 FullDecode // 免去 300ms 延迟,速度最快,并天然由解码端展示自带预览图! - OutputDebugStringW(L"[Dispatch] -> JXL Large: Heavy SubmitFullDecode (Skip FastLane)\n"); + QV_LOG_INFO(L"[Dispatch] -> JXL Large: Heavy SubmitFullDecode (Skip FastLane)\n"); m_heavyPool->SubmitFullDecode(path, imageId, primaryMMF); } } @@ -502,14 +501,12 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u } if (isSmall) { - wchar_t dbgBuf[128]; - swprintf_s(dbgBuf, L"[Dispatch] -> %s Small (<30ms): FastLane\n", info.format.c_str()); - OutputDebugStringW(dbgBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "Dispatch", + TraceLoggingWideString(info.format.c_str(), "Arg0")); m_fastLane.Push(path, imageId, m_targetHdrHeadroomStops.load(std::memory_order_relaxed)); } else { - wchar_t dbgBuf[128]; - swprintf_s(dbgBuf, L"[Dispatch] -> %s Large: Heavy Lane\n", info.format.c_str()); - OutputDebugStringW(dbgBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "Dispatch", + TraceLoggingWideString(info.format.c_str(), "Arg0")); m_heavyPool->Submit(path, imageId, primaryMMF); } return; @@ -517,14 +514,14 @@ void ImageEngine::DispatchImageLoad(const std::wstring& path, ImageID imageId, u // 7. Standard Routing if (useHeavy) { - OutputDebugStringW(L"[Dispatch] -> Heavy Lane\n"); + QV_LOG_INFO(L"[Dispatch] -> Heavy Lane\n"); m_heavyPool->Submit(path, imageId, primaryMMF); } if (useFastLane) { // Avoid parallel duplicate work if Heavy is already taking it? // Logic: TypeA -> FastLane only. TypeB -> Heavy only. // Unknown type -> Parallel (Both). - OutputDebugStringW(L"[Dispatch] -> FastLane\n"); + QV_LOG_INFO(L"[Dispatch] -> FastLane\n"); m_fastLane.Push(path, imageId, m_targetHdrHeadroomStops.load(std::memory_order_relaxed)); } } @@ -628,7 +625,7 @@ std::vector ImageEngine::PollState() { // [JXL Serial] Trigger Stage 2 IMMEDIATELY for JXL (No 300ms wait) if (m_pendingJxlHeavyId == e.imageId && m_pendingJxlHeavyId != 0) { - OutputDebugStringW(L"[PollState] JXL Preview Ready -> Triggering Heavy Immediate\n"); + QV_LOG_INFO(L"[PollState] JXL Preview Ready -> Triggering Heavy Immediate\n"); RequestFullDecode(m_pendingJxlHeavyPath, m_pendingJxlHeavyId); m_stage2Requested = true; m_pendingJxlHeavyId = 0; @@ -643,7 +640,7 @@ std::vector ImageEngine::PollState() { // [JXL Scene C] FastLane Aborted (Modular?) -> Trigger Heavy Immediately if (m_pendingJxlHeavyId == e.imageId && m_pendingJxlHeavyId != 0) { - OutputDebugStringW(L"[PollState] FastLane Failed (Modular?) -> Triggering Heavy Immediate\n"); + QV_LOG_INFO(L"[PollState] FastLane Failed (Modular?) -> Triggering Heavy Immediate\n"); RequestFullDecode(m_pendingJxlHeavyPath, m_pendingJxlHeavyId); m_stage2Requested = true; // Mark as requested m_pendingJxlHeavyId = 0; // Consumed @@ -657,9 +654,8 @@ std::vector ImageEngine::PollState() { if (e.type == EventType::LoadError) { // [HEIC] Special handling for missing codec: Trigger install prompt on UI thread if (CImageLoader::ImageMetadata::IsWicCodecMissing(e.hr)) { - wchar_t dbg[128]; - swprintf_s(dbg, L"[ImageEngine] Detected missing HEVC codec: 0x%08X. Prompting user.\n", (uint32_t)e.hr); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "ImageEngineDetected", + TraceLoggingValue((uint32_t)e.hr, "0x")); PostMessage(m_hwnd, WM_APP + 99, 0, 0); } std::lock_guard lock(m_pendingMutex); @@ -981,10 +977,9 @@ void ImageEngine::FastLane::Push(const std::wstring& path, ImageID id, float tar // [DEBUG] Log Push notification { - wchar_t buf[512]; - swprintf_s(buf, L"[FastLane] Push: %s (queue size=%d)\n", - path.substr(path.find_last_of(L"\\/") + 1).c_str(), (int)m_queue.size()); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "FastLanePush", + TraceLoggingWideString(path.substr(path.find_last_of(L"\\/") + 1).c_str(), "Push"), + TraceLoggingValue((int)m_queue.size(), "size")); } // [Phase 10] Reset timer logic @@ -1024,7 +1019,7 @@ int ImageEngine::FastLane::GetResultsSize() const { } void ImageEngine::FastLane::QueueWorker() { - OutputDebugStringW(L"[FastLane] Worker Thread Started\n"); + QV_LOG_INFO(L"[FastLane] Worker Thread Started\n"); while (!m_stopSignal) { FastLaneCommand cmd; @@ -1048,7 +1043,7 @@ void ImageEngine::FastLane::QueueWorker() { m_isWorking = true; // [HUD V4] Active std::wstring debugMsg = L"[FastLane] Processing: " + cmd.path.substr(cmd.path.find_last_of(L"\\/") + 1) + L"\n"; - OutputDebugStringW(debugMsg.c_str()); + QV_LOG_INFO(debugMsg.c_str()); // --- Work Stage (Unified RawImageFrame Architecture) --- auto start = std::chrono::high_resolution_clock::now(); @@ -1193,8 +1188,8 @@ void ImageEngine::FastLane::QueueWorker() { // Signal main thread m_parent->QueueEvent(EngineEvent{}); // Dummy event, just for notification - if (isClear) OutputDebugStringW(L"[FastLane] Output: FullReady (Final)\n"); - else { wchar_t buf[128]; swprintf_s(buf, L"[FastLane] Output: PreviewReady (Blurry) - targetW=%d, rawW=%d\n", targetW, rawFrame.width); OutputDebugStringW(buf); } + if (isClear) QV_LOG_INFO(L"[FastLane] Output: FullReady (Final)\n"); + else { wchar_t buf[128]; swprintf_s(buf, L"[FastLane] Output: PreviewReady (Blurry) - targetW=%d, rawW=%d\n", targetW, rawFrame.width); QV_LOG_INFO(buf); } // [v3.1] If Fast Pass produced clear image, cancel Heavy Lane if (isClear) { @@ -1229,14 +1224,14 @@ void ImageEngine::FastLane::QueueWorker() { } catch (const std::exception& ex) { m_isWorking = false; // [HUD V4] Safety reset - OutputDebugStringW(L"[FastLane] CRITICAL EXCEPTION in QueueWorker: "); - OutputDebugStringA(ex.what()); - OutputDebugStringW(L"\n"); + QV_LOG_INFO(L"[FastLane] CRITICAL EXCEPTION in QueueWorker: "); + QV_LOG(QV_LOG_LEVEL_ERROR, "ImageEngine", TraceLoggingString(ex.what(), "Message")); + QV_LOG_INFO(L"\n"); } catch (...) { - OutputDebugStringW(L"[FastLane] CRITICAL UNKNOWN EXCEPTION in QueueWorker\n"); + QV_LOG_INFO(L"[FastLane] CRITICAL UNKNOWN EXCEPTION in QueueWorker\n"); } } - OutputDebugStringW(L"[FastLane] Worker Thread Exiting\n"); + QV_LOG_INFO(L"[FastLane] Worker Thread Exiting\n"); } void ImageEngine::SetPrefetchPolicy(const PrefetchPolicy& policy) { @@ -1245,7 +1240,7 @@ void ImageEngine::SetPrefetchPolicy(const PrefetchPolicy& policy) { void ImageEngine::TriggerPendingJxlHeavy() { if (!m_pendingJxlHeavyPath.empty() && m_pendingJxlHeavyId != 0) { - OutputDebugStringW(L"[JXL Sequential] FastLane done, triggering Heavy\n"); + QV_LOG_INFO(L"[JXL Sequential] FastLane done, triggering Heavy\n"); m_heavyPool->Submit(m_pendingJxlHeavyPath, m_pendingJxlHeavyId); m_pendingJxlHeavyPath.clear(); m_pendingJxlHeavyId = 0; @@ -1278,9 +1273,9 @@ void ImageEngine::UpdateView(int currentIndex, QuickView::BrowseDirection dir) { (dir == QuickView::BrowseDirection::BACKWARD) ? -1 : 0; m_lastDirectionInt.store(dirInt); - wchar_t buf[128]; - swprintf_s(buf, L"[ImageEngine] UpdateView: Idx=%d Dir=%d\n", currentIndex, dirInt); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "ImageEngineUpdateView", + TraceLoggingValue(currentIndex, "Idx"), + TraceLoggingValue(dirInt, "Dir")); // 1. Prune: Cancel old tasks not in visible range PruneQueue(currentIndex, dir); @@ -1366,11 +1361,10 @@ void ImageEngine::ScheduleJob(int index, QuickView::Priority pri) { // Allow a 10% margin just in case, but strictly reject if it consumes > 90% of ENTIRE cache if (predictedSize > m_prefetchPolicy.maxCacheMemory) { wchar_t skipBuf[256]; - swprintf_s(skipBuf, L"[ImageEngine] Smart Skip: %s (%.1f MB) > Cache Cap (%.1f MB) -> Skipped\n", - path.substr(path.find_last_of(L"\\/") + 1).c_str(), - predictedSize / 1048576.0, - m_prefetchPolicy.maxCacheMemory / 1048576.0); - OutputDebugStringW(skipBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "ImageEngineSmart", + TraceLoggingWideString(path.substr(path.find_last_of(L"\\/") + 1).c_str(), "Skip"), + TraceLoggingValue(predictedSize / 1048576.0, "Arg1"), + TraceLoggingValue(m_prefetchPolicy.maxCacheMemory / 1048576.0, "Arg2")); return; } } @@ -1632,7 +1626,7 @@ void ImageEngine::RequestFullMetadata() { tempLoader.Initialize(pFactory.Get()); factoryOk = true; } else { - OutputDebugStringW(L"[ImageEngine] Failed to create WIC Factory for async metadata!\n"); + QV_LOG_INFO(L"[ImageEngine] Failed to create WIC Factory for async metadata!\n"); } } @@ -1662,7 +1656,7 @@ void ImageEngine::RequestFullMetadata() { if (SUCCEEDED(hr)) CoUninitialize(); } catch (...) { - OutputDebugStringW(L"[ImageEngine] Critical Exception in Async Metadata Thread!\n"); + QV_LOG_INFO(L"[ImageEngine] Critical Exception in Async Metadata Thread!\n"); } // Destructor of 'cleaner' runs here, removing ID from pending set. diff --git a/QuickView/ImageLoader.cpp b/QuickView/ImageLoader.cpp index d08467a..8450d74 100644 --- a/QuickView/ImageLoader.cpp +++ b/QuickView/ImageLoader.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include #include #include @@ -198,9 +199,9 @@ static void FindHeifGainMapManual(const uint8_t* data, size_t size, uint64_t* ou if (auxlCount == 0) return; { - wchar_t dbg[128]; - swprintf_s(dbg, L"[Scanner] Found %d auxl candidates (infe=%u)\n", auxlCount, infeItemID); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "ScannerFound", + TraceLoggingValue(auxlCount, "Found"), + TraceLoggingValue(infeItemID, "infe")); } // iloc resolver: returns offset+length for a given itemID @@ -284,10 +285,12 @@ static void FindHeifGainMapManual(const uint8_t* data, size_t size, uint64_t* ou *outOffset = bestOff; *outLength = bestLen; if (outBestID) *outBestID = bestID; - wchar_t sdbg[256]; - swprintf_s(sdbg, L"[Scanner] SOLVED! ItemID %u -> Offset %llu, Length %llu. PitmOff=%u PitmSize=%u\n", - bestID, bestOff, bestLen, outPitmOffset ? *outPitmOffset : 0, outPitmSize ? *outPitmSize : 0); - OutputDebugStringW(sdbg); + QV_LOG(QV_LOG_LEVEL_INFO, "ScannerSOLVED", + TraceLoggingValue(bestID, "ItemID"), + TraceLoggingValue(bestOff, "Offset"), + TraceLoggingValue(bestLen, "Length"), + TraceLoggingValue(outPitmOffset ? *outPitmOffset : 0, "PitmOff"), + TraceLoggingValue(outPitmSize ? *outPitmSize : 0, "PitmSize")); } } @@ -332,7 +335,7 @@ static void ProbeHdrMetadataNative(LPCWSTR filePath, QuickView::HdrStaticMetadat // Default headroom: 1.5 stops (Apple standard when no explicit tag found) if (pHdr->gainMapAlternateHeadroom <= 0.0f) pHdr->gainMapAlternateHeadroom = 1.5f; - OutputDebugStringW(L"[Metadata] Apple HDR Gain Map detected.\n"); + QV_LOG_INFO(L"[Metadata] Apple HDR Gain Map detected.\n"); break; } } @@ -349,7 +352,7 @@ void* CImageLoader::GetJxlRunner() { size_t threads = std::thread::hardware_concurrency(); if (threads == 0) threads = 4; s_jxlRunner = JxlThreadParallelRunnerCreate(NULL, threads); - OutputDebugStringW(L"[JXL] Global ThreadRunner created\n"); + QV_LOG_INFO(L"[JXL] Global ThreadRunner created\n"); } return s_jxlRunner; } @@ -359,7 +362,7 @@ void CImageLoader::ReleaseJxlRunner() { if (s_jxlRunner) { JxlThreadParallelRunnerDestroy(s_jxlRunner); s_jxlRunner = nullptr; - OutputDebugStringW(L"[JXL] Global ThreadRunner destroyed\n"); + QV_LOG_INFO(L"[JXL] Global ThreadRunner destroyed\n"); } } @@ -1675,7 +1678,7 @@ static HRESULT SafeLoadJpegRegion( return LoadJpegRegion_V3(data, size, rect, scale, out, tileManager, arena, explicitTargetW, explicitTargetH); } __except (GetExceptionCode() == EXCEPTION_IN_PAGE_ERROR ? EXCEPTION_EXECUTE_HANDLER : EXCEPTION_CONTINUE_SEARCH) { - OutputDebugStringW(L"[ImageLoader] CRITICAL: ReadFile fault (Network lost?)\n"); + QV_LOG_INFO(L"[ImageLoader] CRITICAL: ReadFile fault (Network lost?)\n"); return HRESULT_FROM_WIN32(ERROR_READ_FAULT); } } @@ -1710,7 +1713,7 @@ HRESULT CImageLoader::LoadTileFromMemory( return LoadJpegRegion_V3(sourceData, sourceSize, region, scale, outFrame, tileManager, nullptr /*arena*/, targetWidth, targetHeight); } __except (GetExceptionCode() == EXCEPTION_IN_PAGE_ERROR ? EXCEPTION_EXECUTE_HANDLER : EXCEPTION_CONTINUE_SEARCH) { - OutputDebugStringW(L"[ImageLoader] CRITICAL: ReadFile fault during Tile Decode\n"); + QV_LOG_INFO(L"[ImageLoader] CRITICAL: ReadFile fault during Tile Decode\n"); return HRESULT_FROM_WIN32(ERROR_READ_FAULT); } } @@ -1751,10 +1754,9 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, if (!WuffsLoader::DecodePNG(data, size, &w, &h, allocator, nullptr)) { if (directBuf) _aligned_free(directBuf); - wchar_t dbg[128]; size_t neededMB = ((size_t)w * h * 4) / (1024 * 1024); - swprintf_s(dbg, L"[P15] Wuffs PNG decode failed (need ~%zu MB BGRA)\n", neededMB); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15Wuffs", + TraceLoggingValue(neededMB, "Arg0")); return E_FAIL; } @@ -1766,7 +1768,7 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, outFrame->stride = (int)((size_t)w * 4); outFrame->memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; - OutputDebugStringW(L"[P15] PNG decoded via Wuffs OK\n"); + QV_LOG_INFO(L"[P15] PNG decoded via Wuffs OK\n"); return S_OK; } @@ -1838,10 +1840,9 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, // Only abort if we are truly hitting system-wide exhaustion (85% committed) // instead of just checking a relative percentage of physical RAM. if (outBufSize > ms.ullAvailPageFile && outBufSize > (ms.ullAvailPhys * 9 / 10)) { - wchar_t dbg[192]; - swprintf_s(dbg, L"[P15] JXL heap decode aborted (CRITICAL): need %zu MB, only %llu MB pagefile available\n", - outBufSize / (1024*1024), ms.ullAvailPageFile / (1024*1024)); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15JXL", + TraceLoggingValue(outBufSize / (1024*1024), "need"), + TraceLoggingValue(ms.ullAvailPageFile / (1024*1024), "only")); JxlDecoderDestroy(dec); JxlThreadParallelRunnerDestroy(runner); return E_OUTOFMEMORY; @@ -1866,13 +1867,12 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, JxlThreadParallelRunnerDestroy(runner); if (FAILED(hr)) { - wchar_t failLog[128]; - swprintf_s(failLog, L"[JXL] FullDecodeFromMemory failed: hr=0x%08X\n", (uint32_t)hr); - OutputDebugStringW(failLog); + QV_LOG(QV_LOG_LEVEL_INFO, "JXLFullDecodeFromMemory", + TraceLoggingValue((uint32_t)hr, "hr0x")); } if (FAILED(hr) || !outBuf) { if (outBuf) _aligned_free(outBuf); - OutputDebugStringW(L"[P15] JXL decode failed\n"); + QV_LOG_INFO(L"[P15] JXL decode failed\n"); return FAILED(hr) ? hr : E_FAIL; } @@ -1885,9 +1885,9 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, outFrame->stride = (int)(info.xsize * 4); outFrame->memoryDeleter = [](uint8_t* p) { _aligned_free(p); }; - wchar_t dbg[128]; - swprintf_s(dbg, L"[P15] JXL decoded via libjxl OK (%ux%u)\n", info.xsize, info.ysize); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "P15JXL", + TraceLoggingValue(info.xsize, "Arg0"), + TraceLoggingValue(info.ysize, "Arg1")); return S_OK; } @@ -1895,7 +1895,7 @@ HRESULT CImageLoader::FullDecodeFromMemory(const uint8_t* data, size_t size, // --------------------------------------------------------------- // Fallback: unsupported format for tile decode // --------------------------------------------------------------- - OutputDebugStringW(L"[P15] FullDecodeFromMemory: unsupported format\n"); + QV_LOG_INFO(L"[P15] FullDecodeFromMemory: unsupported format\n"); return E_NOTIMPL; } @@ -1989,10 +1989,9 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, if (JXL_DEC_SUCCESS != JxlDecoderImageOutBufferSize(dec, &pixFmt, &needed)) break; if (needed > mmfBufSize) { - wchar_t dbg[192]; - swprintf_s(dbg, L"[MMF] JXL needs %zu MB but MMF is %zu MB\n", - needed / (1024*1024), mmfBufSize / (1024*1024)); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFJXL", + TraceLoggingValue(needed / (1024*1024), "needs"), + TraceLoggingValue(mmfBufSize / (1024*1024), "is")); JxlDecoderDestroy(dec); JxlThreadParallelRunnerDestroy(runner); return E_OUTOFMEMORY; @@ -2015,10 +2014,10 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, // The safe path: let the full decode complete, swizzle once at the end. size_t ratio = JxlDecoderGetIntendedDownsamplingRatio(dec); - wchar_t dbg[192]; - swprintf_s(dbg, L"[MMF] JXL FRAME_PROGRESSION: ratio=%zu, image=%ux%u (logged only, no flush)\n", - ratio, info.xsize, info.ysize); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFJXL", + TraceLoggingValue(ratio, "ratio"), + TraceLoggingValue(info.xsize, "image"), + TraceLoggingValue(info.ysize, "Arg2")); // Continue decode loop for full quality } else if (st == JXL_DEC_FULL_IMAGE) { @@ -2031,7 +2030,7 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, JxlThreadParallelRunnerDestroy(runner); if (FAILED(hr) || !bufferSet) { - OutputDebugStringW(L"[MMF] JXL decode to MMF failed\n"); + QV_LOG_INFO(L"[MMF] JXL decode to MMF failed\n"); return FAILED(hr) ? hr : E_FAIL; } @@ -2043,9 +2042,9 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, *outH = (int)info.ysize; *outStride = (int)(info.xsize * 4); - wchar_t dbg[128]; - swprintf_s(dbg, L"[MMF] JXL decoded direct-to-MMF OK (%ux%u)\n", info.xsize, info.ysize); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFJXL", + TraceLoggingValue(info.xsize, "Arg0"), + TraceLoggingValue(info.ysize, "Arg1")); return S_OK; } @@ -2062,7 +2061,7 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, }; if (!WuffsLoader::DecodePNG(data, size, &w, &h, allocator, nullptr) || !allocOK) { - OutputDebugStringW(L"[MMF] Wuffs PNG decode to MMF failed\n"); + QV_LOG_INFO(L"[MMF] Wuffs PNG decode to MMF failed\n"); return E_FAIL; } @@ -2070,9 +2069,9 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, *outH = (int)h; *outStride = (int)((size_t)w * 4); - wchar_t dbg[128]; - swprintf_s(dbg, L"[MMF] PNG decoded direct-to-MMF OK (%ux%u)\n", w, h); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFPNG", + TraceLoggingValue(w, "Arg0"), + TraceLoggingValue(h, "Arg1")); return S_OK; } @@ -2086,10 +2085,9 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, size_t needed = (size_t)heapFrame.stride * (size_t)heapFrame.height; if (needed > mmfBufSize) { - wchar_t dbg[192]; - swprintf_s(dbg, L"[MMF] Fallback: need %zu MB but MMF is %zu MB\n", - needed / (1024*1024), mmfBufSize / (1024*1024)); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFFallback", + TraceLoggingValue(needed / (1024*1024), "need"), + TraceLoggingValue(mmfBufSize / (1024*1024), "is")); return E_OUTOFMEMORY; } @@ -2099,10 +2097,10 @@ HRESULT CImageLoader::FullDecodeToMMF(const uint8_t* data, size_t size, *outH = heapFrame.height; *outStride = heapFrame.stride; - wchar_t dbg[128]; - swprintf_s(dbg, L"[MMF] %ls decoded via fallback+copy OK (%dx%d)\n", - fmt.c_str(), heapFrame.width, heapFrame.height); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "MMFls", + TraceLoggingWideString(fmt.c_str(), "LMMF"), + TraceLoggingValue(heapFrame.width, "Arg1"), + TraceLoggingValue(heapFrame.height, "Arg2")); return S_OK; } @@ -2442,14 +2440,14 @@ HRESULT CImageLoader::LoadJxlRegionToFrame(LPCWSTR filePath, QuickView::RegionRe JxlDecoderStatus st = JxlDecoderProcessInput(dec); if (st == JXL_DEC_ERROR) { - OutputDebugStringW(L"[JXL_ROI] Decoder Error during ProcessInput\n"); + QV_LOG_INFO(L"[JXL_ROI] Decoder Error during ProcessInput\n"); break; } if (st == JXL_DEC_SUCCESS) { hr = S_OK; break; } if (st == JXL_DEC_BASIC_INFO) { if (JXL_DEC_SUCCESS != JxlDecoderGetBasicInfo(dec, &info)) { - OutputDebugStringW(L"[JXL_ROI] Failed to get Basic Info\n"); + QV_LOG_INFO(L"[JXL_ROI] Failed to get Basic Info\n"); break; } @@ -2466,7 +2464,7 @@ HRESULT CImageLoader::LoadJxlRegionToFrame(LPCWSTR filePath, QuickView::RegionRe if (!BuildRegionScalePlan(srcRect, (int)info.xsize, (int)info.ysize, scale, explicitTargetW, explicitTargetH, &plan)) { - OutputDebugStringW(L"[JXL_ROI] Failed to Build Region Scale Plan\n"); + QV_LOG_INFO(L"[JXL_ROI] Failed to Build Region Scale Plan\n"); hr = E_FAIL; break; } @@ -2493,7 +2491,7 @@ HRESULT CImageLoader::LoadJxlRegionToFrame(LPCWSTR filePath, QuickView::RegionRe ctx.cropH = plan.cropH; if (JXL_DEC_SUCCESS != JxlDecoderSetImageOutCallback(dec, &pixFmt, JxlCropCallback, &ctx)) { - OutputDebugStringW(L"[JXL_ROI] Failed to Set Image Out Callback\n"); + QV_LOG_INFO(L"[JXL_ROI] Failed to Set Image Out Callback\n"); hr = E_FAIL; break; } } @@ -2502,15 +2500,16 @@ HRESULT CImageLoader::LoadJxlRegionToFrame(LPCWSTR filePath, QuickView::RegionRe break; } else if (st == JXL_DEC_NEED_MORE_INPUT) { - OutputDebugStringW(L"[JXL_ROI] Need more input but input is closed!\n"); + QV_LOG_INFO(L"[JXL_ROI] Need more input but input is closed!\n"); break; } } if (FAILED(hr) || !tempBuf || !planReady) { - wchar_t errObj[256]; - swprintf_s(errObj, L"[JXL_ROI] Failure Exit: hr=0x%08X, tempBuf=%p, planReady=%d\n", hr, tempBuf, planReady); - OutputDebugStringW(errObj); + QV_LOG(QV_LOG_LEVEL_INFO, "JXL_ROIFailure", + TraceLoggingValue(hr, "hr0x"), + TraceLoggingPointer(tempBuf, "tempBuf"), + TraceLoggingValue(planReady, "planReady")); if (tempBuf && (!arena || !arena->Owns(tempBuf))) _aligned_free(tempBuf); return hr == S_OK ? E_FAIL : hr; } @@ -4064,8 +4063,8 @@ HRESULT CImageLoader::LoadAVIF(LPCWSTR filePath, IWICBitmap** ppBitmap, ImageMet // Set Memory Source avifResult result = avifDecoderSetIOMemory(decoder, avifBuf.data(), avifBuf.size()); if (result != AVIF_RESULT_OK) { - wchar_t buf[128]; swprintf_s(buf, L"[LoadAVIF] SetIOMemory failed: %hs\n", avifResultToString(result)); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "LoadAVIFSetIOMemory", + TraceLoggingString(avifResultToString(result), "failed")); avifDecoderDestroy(decoder); return E_FAIL; } @@ -4073,9 +4072,9 @@ HRESULT CImageLoader::LoadAVIF(LPCWSTR filePath, IWICBitmap** ppBitmap, ImageMet // Parse result = avifDecoderParse(decoder); if (result != AVIF_RESULT_OK) { - wchar_t buf[256]; - swprintf_s(buf, L"[LoadAVIF] Parse failed: %hs | Diag: %hs\n", avifResultToString(result), decoder->diag.error); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "LoadAVIFParse", + TraceLoggingString(avifResultToString(result), "failed"), + TraceLoggingString(decoder->diag.error, "Diag")); avifDecoderDestroy(decoder); return E_FAIL; } @@ -4083,8 +4082,8 @@ HRESULT CImageLoader::LoadAVIF(LPCWSTR filePath, IWICBitmap** ppBitmap, ImageMet // Next Image (Frame 0) result = avifDecoderNextImage(decoder); if (result != AVIF_RESULT_OK) { - wchar_t buf[128]; swprintf_s(buf, L"[LoadAVIF] NextImage failed: %hs\n", avifResultToString(result)); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "LoadAVIFNextImage", + TraceLoggingString(avifResultToString(result), "failed")); avifDecoderDestroy(decoder); return E_FAIL; } @@ -4129,8 +4128,8 @@ HRESULT CImageLoader::LoadAVIF(LPCWSTR filePath, IWICBitmap** ppBitmap, ImageMet pLock.Reset(); // Unlock if (result != AVIF_RESULT_OK) { - wchar_t buf[128]; swprintf_s(buf, L"[LoadAVIF] YUVToRGB failed: %hs\n", avifResultToString(result)); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "LoadAVIFYUVToRGB", + TraceLoggingString(avifResultToString(result), "failed")); avifDecoderDestroy(decoder); return E_FAIL; } @@ -4920,13 +4919,13 @@ namespace QuickView { // Found an SOI. *outData = buf + i; *outSize = bufSize - i; - wchar_t logBuf[128]; - swprintf_s(logBuf, L"[UltraHDR] Found potential second JPEG SOI at offset %zu, size %zu\n", i, *outSize); - OutputDebugStringW(logBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "UltraHDRFound", + TraceLoggingValue(i, "offset"), + TraceLoggingValue(*outSize, "size")); return true; } } - OutputDebugStringW(L"[UltraHDR] Second JPEG SOI NOT found in MPF scan.\n"); + QV_LOG_INFO(L"[UltraHDR] Second JPEG SOI NOT found in MPF scan.\n"); return false; } @@ -4939,7 +4938,7 @@ namespace QuickView { struct jpeg_error_mgr jerr; cinfo.err = jpeg_std_error(&jerr); jerr.error_exit = [](j_common_ptr ci) { - OutputDebugStringW(L"[UltraHDR] Gain Map JPEG decode fatal error.\n"); + QV_LOG_INFO(L"[UltraHDR] Gain Map JPEG decode fatal error.\n"); longjmp(*static_cast(ci->client_data), 1); }; @@ -4953,7 +4952,7 @@ namespace QuickView { jpeg_create_decompress(&cinfo); jpeg_mem_src(&cinfo, data, (unsigned long)size); if (jpeg_read_header(&cinfo, TRUE) != JPEG_HEADER_OK) { - OutputDebugStringW(L"[UltraHDR] Gain Map JPEG read_header failed.\n"); + QV_LOG_INFO(L"[UltraHDR] Gain Map JPEG read_header failed.\n"); jpeg_destroy_decompress(&cinfo); return nullptr; } @@ -5040,14 +5039,13 @@ namespace QuickView { for (jpeg_saved_marker_ptr marker = cinfo.marker_list; marker; marker = marker->next) { // [UltraHDR Diagnostic] if (marker->marker == JPEG_APP0 + 1 || marker->marker == JPEG_APP0 + 2) { - wchar_t logBuf[256]; swprintf_s(logBuf, L"[UltraHDR] Found Marker APP%d (0x%02X), Len=%d, Data[0..3]=%02X %02X %02X %02X\n", marker->marker - JPEG_APP0, marker->marker, (int)marker->data_length, marker->data_length > 0 ? marker->data[0] : 0, marker->data_length > 1 ? marker->data[1] : 0, marker->data_length > 2 ? marker->data[2] : 0, marker->data_length > 3 ? marker->data[3] : 0); - OutputDebugStringW(logBuf); + QV_LOG_INFO(logBuf); } // [UltraHDR Phase 1] Parse XMP while marker_list is alive @@ -5070,9 +5068,9 @@ namespace QuickView { ultraHdrPayload.sdrWidth = (uint32_t)cinfo.image_width; ultraHdrPayload.sdrHeight = (uint32_t)cinfo.image_height; ultraHdrPayloadParsed = true; - OutputDebugStringW(L"[UltraHDR] XMP Gain Map parameters found and parsed (Early stage).\n"); + QV_LOG_INFO(L"[UltraHDR] XMP Gain Map parameters found and parsed (Early stage).\n"); } else { - OutputDebugStringW(L"[UltraHDR] APP1 XMP found but ParseXmpToPayload failed.\n"); + QV_LOG_INFO(L"[UltraHDR] APP1 XMP found but ParseXmpToPayload failed.\n"); } } } @@ -5086,9 +5084,9 @@ namespace QuickView { } { - wchar_t logBuf[128]; - swprintf_s(logBuf, L"[Loader] JPEG Markers Check: Found %d ICC segments. Total size: %zu\n", iccNumMarkers, iccTotalSize); - OutputDebugStringW(logBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "LoaderJPEG", + TraceLoggingValue(iccNumMarkers, "Found"), + TraceLoggingValue(iccTotalSize, "size")); } if (iccNumMarkers > 0) { @@ -5315,7 +5313,7 @@ namespace QuickView { size_t gainJpegSize = 0; if (ultraHdrPayloadParsed && UltraHdr::FindMpfSecondImage(pBuf, bufSize, &gainJpegData, &gainJpegSize)) { - OutputDebugStringW(L"[UltraHDR] MPF Secondary Image (Gain Map) found.\n"); + QV_LOG_INFO(L"[UltraHDR] MPF Secondary Image (Gain Map) found.\n"); auto auxLayer = UltraHdr::DecodeGainMapJpeg(gainJpegData, gainJpegSize, ctx); if (auxLayer) { result.blendOp = GpuBlendOp::UltraHdrGainMap; @@ -5812,7 +5810,7 @@ namespace QuickView { // [Fix] Prevent massive memory allocation stalls (e.g. 4.8GB for 1.2 GigaPixel JXL) // This prevents the OS from thrashing the page file for 15 seconds before crashing. if (ctx.allowFakeBase && bufferSize > 1024ULL * 1024ULL * 1024ULL) { // 1 GB limit - OutputDebugStringW(L"[JXL_DC] Image too large for base layer. Faking transparent stub but PRESERVING original dimensions for Titan Mode.\n"); + QV_LOG_INFO(L"[JXL_DC] Image too large for base layer. Faking transparent stub but PRESERVING original dimensions for Titan Mode.\n"); // We fake a 1x1 transparent pixel to satisfy the pipeline, // BUT we return the TRUE image dimensions to out results. // This ensures the Tile Engine correctly calculates regions. @@ -6207,7 +6205,7 @@ namespace QuickView { LibRaw RawProcessor; // Debug: Entry point - OutputDebugStringW(L"[RawCodec] Entering RawCodec::Load\n"); + QV_LOG_INFO(L"[RawCodec] Entering RawCodec::Load\n"); // [v9.3] Use wide-char path directly on Windows (fixes -100009 error) // LibRaw on Windows supports open_file(const wchar_t*) overload @@ -6225,12 +6223,11 @@ namespace QuickView { int openResult = RawProcessor.open_file(pathUtf8.c_str()); #endif if (openResult != LIBRAW_SUCCESS) { - wchar_t dbg[128]; - swprintf_s(dbg, L"[RawCodec] open_file FAILED: %d\n", openResult); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "RawCodecopen_file", + TraceLoggingValue(openResult, "FAILED")); return E_FAIL; } - OutputDebugStringW(L"[RawCodec] open_file OK\n"); + QV_LOG_INFO(L"[RawCodec] open_file OK\n"); // [v10.1] Capture RAW orientation early int flip = RawProcessor.imgdata.sizes.flip; @@ -6260,16 +6257,16 @@ namespace QuickView { int unpackResult = RawProcessor.unpack_thumb(); // Debug logging - wchar_t dbg[256]; - swprintf_s(dbg, L"[RawCodec] unpack_thumb: %d\n", unpackResult); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "RawCodecunpack_thumb", + TraceLoggingValue(unpackResult, "unpack_thumb")); if (unpackResult == LIBRAW_SUCCESS) { libraw_processed_image_t* thumb = RawProcessor.dcraw_make_mem_thumb(); - swprintf_s(dbg, L"[RawCodec] thumb=%p, type=%d, size=%d\n", - thumb, thumb ? thumb->type : -1, thumb ? thumb->data_size : 0); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "RawCodec", + TraceLoggingPointer(thumb, "thumb"), + TraceLoggingValue(thumb ? (int)thumb->type : -1, "type"), + TraceLoggingValue(thumb ? thumb->data_size : 0, "size")); if (thumb) { if (thumb->type == LIBRAW_IMAGE_JPEG) { @@ -6281,10 +6278,10 @@ namespace QuickView { result.metadata.LoaderName = L"LibRaw (Preview)"; // We keep the ExifOrientation from JPEG::Load or the one we captured above if (result.metadata.ExifOrientation <= 1) result.metadata.ExifOrientation = exifOrientation; - OutputDebugStringW(L"[RawCodec] Preview JPEG decoded OK\n"); + QV_LOG_INFO(L"[RawCodec] Preview JPEG decoded OK\n"); return S_OK; } - OutputDebugStringW(L"[RawCodec] Preview JPEG decode FAILED\n"); + QV_LOG_INFO(L"[RawCodec] Preview JPEG decode FAILED\n"); } else if (thumb->type == LIBRAW_IMAGE_BITMAP) { // RGB Bitmap @@ -7066,18 +7063,18 @@ HRESULT CImageLoader::LoadImageUnified(LPCWSTR filePath, const DecodeContext& ct result.frameMeta = firstFrame->frameMeta; result.animator = std::move(animator); result.metadata.LoaderName = fmt == L"WebP" ? L"WebPAnimator" : (fmt == L"AVIF" ? L"AvifAnimator" : (fmt == L"JXL" ? L"JxlAnimator" : L"WuffsAnimator")); - OutputDebugStringW(L"[Anim] Animation hijack SUCCESS\n"); + QV_LOG_INFO(L"[Anim] Animation hijack SUCCESS\n"); return S_OK; } else { - OutputDebugStringW(L"[Anim] GetNextFrame() returned null or no pixels\n"); + QV_LOG_INFO(L"[Anim] GetNextFrame() returned null or no pixels\n"); } - // OutputDebugStringW(L"[Anim] IsAnimated() returned false, falling through to static decode\n"); + // QV_LOG_INFO(L"[Anim] IsAnimated() returned false, falling through to static decode\n"); } } else { - // OutputDebugStringW(L"[Anim] Initialize() FAILED, falling through to static decode\n"); + // QV_LOG_INFO(L"[Anim] Initialize() FAILED, falling through to static decode\n"); } } else { - OutputDebugStringW(L"[Anim] MappedFile invalid for animation\n"); + QV_LOG_INFO(L"[Anim] MappedFile invalid for animation\n"); } } @@ -9178,12 +9175,13 @@ static bool TryReadMetadataNative(LPCWSTR filePath, CImageLoader::ImageMetadata* JxlBasicInfo info = {}; if (JXL_DEC_SUCCESS == JxlDecoderGetBasicInfo(dec, &info)) { // Debug logging - wchar_t buf[128]; - swprintf_s(buf, L"[JXL] BasicInfo: %ux%u, Bits=%u, Exp=%u, Alpha=%u, P3=%u\n", - info.xsize, info.ysize, info.bits_per_sample, - info.exponent_bits_per_sample, info.num_extra_channels, - info.uses_original_profile); - OutputDebugStringW(buf); + QV_LOG(QV_LOG_LEVEL_INFO, "JXLBasicInfo", + TraceLoggingValue(info.xsize, "BasicInfo"), + TraceLoggingValue(info.ysize, "Arg1"), + TraceLoggingValue(info.bits_per_sample, "Bits"), + TraceLoggingValue(info.exponent_bits_per_sample, "Exp"), + TraceLoggingValue(info.num_extra_channels, "Alpha"), + TraceLoggingValue(info.uses_original_profile, "P3")); pMetadata->Width = info.xsize; pMetadata->Height = info.ysize; @@ -9999,13 +9997,13 @@ HRESULT CImageLoader::LoadThumbJXL_DC(const uint8_t* pFile, size_t fileSize, Thu // [Diagnostic] Log encoding mode to help debug DC detection failures { - wchar_t diagBuf[256]; - swprintf_s(diagBuf, L"[JXL_DC] BasicInfo: %ux%u, %d-bit, uses_original_profile=%d (Modular=%s), have_preview=%d\n", - info.xsize, info.ysize, info.bits_per_sample, - info.uses_original_profile, - info.uses_original_profile ? L"YES→No DC Layer" : L"NO→VarDCT→DC possible", - info.have_preview); - OutputDebugStringW(diagBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "JXL_DCBasicInfo", + TraceLoggingValue(info.xsize, "BasicInfo"), + TraceLoggingValue(info.ysize, "Arg1"), + TraceLoggingValue(info.bits_per_sample, "Arg2"), + TraceLoggingValue(info.uses_original_profile, "uses_original_profile"), + TraceLoggingWideString(info.uses_original_profile ? L"YES→No DC Layer" : L"NO→VarDCT→DC possible", "Modular"), + TraceLoggingValue(info.have_preview, "have_preview")); } } else if (status == JXL_DEC_FRAME_PROGRESSION) { @@ -10095,10 +10093,9 @@ HRESULT CImageLoader::LoadThumbJXL_DC(const uint8_t* pFile, size_t fileSize, Thu return cleanup(E_FAIL); } - wchar_t dbg[160]; - swprintf_s(dbg, L"[JXL_DC] Using Preview fallback: %ux%u (no 1:8 DC)\n", - info.preview.xsize, info.preview.ysize); - OutputDebugStringW(dbg); + QV_LOG(QV_LOG_LEVEL_INFO, "JXL_DCUsing", + TraceLoggingValue(info.preview.xsize, "fallback"), + TraceLoggingValue(info.preview.ysize, "Arg1")); continue; } } @@ -10111,11 +10108,12 @@ HRESULT CImageLoader::LoadThumbJXL_DC(const uint8_t* pFile, size_t fileSize, Thu // 2. Non-progressive lossy encoding → No progressive passes at all // 3. Progressive but ratio not in [4,16] range { - wchar_t diagBuf[256]; - swprintf_s(diagBuf, L"[JXL_DC] No 1:8 DC. isProgressive=%d, uses_original_profile=%d, have_preview=%d, image=%ux%u\n", - isProgressive ? 1 : 0, info.uses_original_profile, info.have_preview, - info.xsize, info.ysize); - OutputDebugStringW(diagBuf); + QV_LOG(QV_LOG_LEVEL_INFO, "JXL_DCNo", + TraceLoggingValue(isProgressive ? 1 : 0, "isProgressive"), + TraceLoggingValue(info.uses_original_profile, "uses_original_profile"), + TraceLoggingValue(info.have_preview, "have_preview"), + TraceLoggingValue(info.xsize, "image"), + TraceLoggingValue(info.ysize, "Arg4")); } bool isSmallEnough = ((uint64_t)info.xsize * info.ysize) < 2000000; // 2MP @@ -10142,7 +10140,7 @@ HRESULT CImageLoader::LoadThumbJXL_DC(const uint8_t* pFile, size_t fileSize, Thu } else if (allowFakeBase) { // Too large for FastLane full decode or too massive for HeavyLane CPU decoding. // We fake a 1x1 transparent pixel to satisfy the pipeline and unlock Titan Mode. - OutputDebugStringW(L"[JXL_DC] No 1:8 found and image too large. Faking 1x1 base layer for Region Decoder.\n"); + QV_LOG_INFO(L"[JXL_DC] No 1:8 found and image too large. Faking 1x1 base layer for Region Decoder.\n"); try { pData->pixels.assign(4, 0); // 1 pixel, 4 channels (RGBA), all 0 (transparent) @@ -11236,12 +11234,11 @@ HRESULT CImageLoader::LoadToFrame(LPCWSTR filePath, QuickView::RawImageFrame* ou // Apply ID Replacements if (!replacements.empty()) { MultiReplace(svgContent, replacements); - wchar_t msg[128]; - swprintf_s(msg, L"[SVG] Sanitized %d Unsafe IDs.\n", (int)replacements.size()); - OutputDebugStringW(msg); + QV_LOG(QV_LOG_LEVEL_INFO, "SVGSanitized", + TraceLoggingValue((int)replacements.size(), "Sanitized")); } } catch (...) { - OutputDebugStringW(L"[SVG] ID Sanitizer Pattern Failure\n"); + QV_LOG_INFO(L"[SVG] ID Sanitizer Pattern Failure\n"); } // ========================================================= @@ -11461,12 +11458,11 @@ HRESULT CImageLoader::LoadToFrame(LPCWSTR filePath, QuickView::RawImageFrame* ou } if (inlinedCount > 0) { - wchar_t msg[128]; - swprintf_s(msg, L"[SVG] Inlined %d Styles (Fixed Black Silhouette).\n", inlinedCount); - OutputDebugStringW(msg); + QV_LOG(QV_LOG_LEVEL_INFO, "SVGInlined", + TraceLoggingValue(inlinedCount, "Inlined")); } } catch (...) { - OutputDebugStringW(L"[SVG] Style Inliner Failure\n"); + QV_LOG_INFO(L"[SVG] Style Inliner Failure\n"); } // Commit changes @@ -11503,7 +11499,7 @@ HRESULT CImageLoader::LoadToFrame(LPCWSTR filePath, QuickView::RawImageFrame* ou } } } catch (...) { - OutputDebugStringW(L"[SVG] Dimension parse failed, using default\n"); + QV_LOG_INFO(L"[SVG] Dimension parse failed, using default\n"); } if (svgW <= 0) svgW = 512; diff --git a/QuickView/QuickView.vcxproj b/QuickView/QuickView.vcxproj index 0c7ccfa..8d0f5fe 100644 --- a/QuickView/QuickView.vcxproj +++ b/QuickView/QuickView.vcxproj @@ -218,6 +218,7 @@ + @@ -279,6 +280,7 @@ NotUsing + diff --git a/QuickView/QuickViewETW.cpp b/QuickView/QuickViewETW.cpp new file mode 100644 index 0000000..65574d2 --- /dev/null +++ b/QuickView/QuickViewETW.cpp @@ -0,0 +1,18 @@ +#include "pch.h" +#include "QuickViewETW.h" + +// 使用固定名称,系统会自动生成稳定的 GUID (Microsoft.QuickView) +TRACELOGGING_DEFINE_PROVIDER( + g_hQuickViewProvider, + "Microsoft.QuickView", + // {9E9234A5-0D4A-5A7D-A7F4-D7F607248C5B} + (0x9e9234a5, 0x0d4a, 0x5a7d, 0xa7, 0xf4, 0xd7, 0xf6, 0x07, 0x24, 0x8c, 0x5b)); + +namespace QuickView::Logging { + void Initialize() { + TraceLoggingRegister(g_hQuickViewProvider); + } + void Shutdown() { + TraceLoggingUnregister(g_hQuickViewProvider); + } +} diff --git a/QuickView/QuickViewETW.h b/QuickView/QuickViewETW.h new file mode 100644 index 0000000..b6e882b --- /dev/null +++ b/QuickView/QuickViewETW.h @@ -0,0 +1,32 @@ +#pragma once +#include +#include +#include +#include + +// {A7F4B3C5-1234-4A3D-B7E9-D7F607248C5B} - 示例 GUID,实际将使用基于名称的哈希或静态生成 +TRACELOGGING_DECLARE_PROVIDER(g_hQuickViewProvider); + +namespace QuickView::Logging { + void Initialize(); + void Shutdown(); +} + +// 定义日志级别映射 +#define QV_LOG_LEVEL_CRITICAL 1 +#define QV_LOG_LEVEL_ERROR 2 +#define QV_LOG_LEVEL_WARNING 3 +#define QV_LOG_LEVEL_INFO 4 +#define QV_LOG_LEVEL_VERBOSE 5 + +// 核心宏:极致性能路径,利用模板和 C++23 静态特性 +#define QV_LOG(level, name, ...) \ + TraceLoggingWrite(g_hQuickViewProvider, name, \ + TraceLoggingLevel(level), \ + __VA_ARGS__) + +// 快慢路径宏封装 +#define QV_LOG_INFO(msg) QV_LOG(QV_LOG_LEVEL_INFO, "Info", TraceLoggingWideString(msg, "Message")) +#define QV_LOG_WARN(msg) QV_LOG(QV_LOG_LEVEL_WARNING, "Warning", TraceLoggingWideString(msg, "Message")) +#define QV_LOG_ERR(msg) QV_LOG(QV_LOG_LEVEL_ERROR, "Error", TraceLoggingWideString(msg, "Message")) +#define QV_LOG_VERBOSE(msg) QV_LOG(QV_LOG_LEVEL_VERBOSE, "Verbose", TraceLoggingWideString(msg, "Message")) diff --git a/QuickView/RenderEngine.cpp b/QuickView/RenderEngine.cpp index 3a539f7..6286569 100644 --- a/QuickView/RenderEngine.cpp +++ b/QuickView/RenderEngine.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include #include #include @@ -302,7 +303,7 @@ HRESULT CRenderEngine::Initialize(HWND hwnd) { m_computeEngine = std::make_unique(); hr = m_computeEngine->Initialize(m_d3dDevice.Get()); if (FAILED(hr)) { - OutputDebugStringA("Warning: Failed to initialize ComputeEngine.\n"); + QV_LOG(QV_LOG_LEVEL_WARNING, "RenderEngine", TraceLoggingString("Warning: Failed to initialize ComputeEngine.\n", "Message")); } return S_OK; @@ -648,7 +649,7 @@ CRenderEngine::UploadRawFrameToGPU(const QuickView::RawImageFrame &frame, wchar_t dbg[256]; swprintf_s(dbg, L"[RenderEngine] GPU Bake Triggered (UltraHDR). Target Headroom: %.2f stops.\n", payload.targetHeadroom); - OutputDebugStringW(dbg); + QV_LOG_INFO(dbg); ComPtr pBaked; HRESULT hrBake = m_computeEngine->ComposeGainMap( @@ -695,7 +696,7 @@ CRenderEngine::UploadRawFrameToGPU(const QuickView::RawImageFrame &frame, wchar_t dbgUpload[256]; swprintf_s(dbgUpload, L"[RenderEngine] Upload: %dx%d, Format=%d, BlendOp=%d, AdvColor=%d\n", (int)frame.width, (int)frame.height, (int)frame.format, (int)frame.blendOp, (int)m_isAdvancedColor); - OutputDebugStringW(dbgUpload); + QV_LOG_INFO(dbgUpload); switch (frame.format) { case QuickView::PixelFormat::BGRA8888: diff --git a/QuickView/TinyExrLoader.cpp b/QuickView/TinyExrLoader.cpp index a7e6c47..5b5351d 100644 --- a/QuickView/TinyExrLoader.cpp +++ b/QuickView/TinyExrLoader.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "TinyExrLoader.h" #include #include "StbLoader.h" // For ZlibDecode @@ -64,13 +65,13 @@ namespace TinyExrLoader { if (ret != TINYEXR_SUCCESS) { if (err) { - OutputDebugStringA("TinyEXR Error: "); - OutputDebugStringA(err); - OutputDebugStringA("\n"); + QV_LOG(QV_LOG_LEVEL_ERROR, "TinyEXRError", TraceLoggingString("TinyEXR Error: ", "Message")); + QV_LOG(QV_LOG_LEVEL_ERROR, "TinyEXRError", TraceLoggingString(err, "Message")); + QV_LOG(QV_LOG_LEVEL_ERROR, "TinyEXRError", TraceLoggingString("\n", "Message")); MessageBoxA(nullptr, err, "TinyEXR Error", MB_OK | MB_ICONERROR); ::FreeEXRErrorMessage(err); } else { - OutputDebugStringA("TinyEXR Error: Unknown error (ret code check needed)\n"); + QV_LOG(QV_LOG_LEVEL_ERROR, "TinyEXRError", TraceLoggingString("TinyEXR Error: Unknown error (ret code check needed)\n", "Message")); } return false; } diff --git a/QuickView/main.cpp b/QuickView/main.cpp index 1d98ad8..beca6bc 100644 --- a/QuickView/main.cpp +++ b/QuickView/main.cpp @@ -1,4 +1,5 @@ #include "pch.h" +#include "QuickViewETW.h" #include "CoroutineTypes.h" #include "CompositionEngine.h" #include "QuickView.h" @@ -5661,7 +5662,7 @@ static HRESULT SafeFullDecodeFromMemory(const uint8_t* data, size_t size, QuickV return InternalFullDecodeWrapper(data, size, outFrame); } __except (GetExceptionCode() == EXCEPTION_ACCESS_VIOLATION ? EXCEPTION_EXECUTE_HANDLER : EXCEPTION_CONTINUE_SEARCH) { - OutputDebugStringW(L"[Phase4] SEH: ACCESS_VIOLATION in FullDecodeFromMemory (caught)\n"); + QV_LOG_INFO(L"[Phase4] SEH: ACCESS_VIOLATION in FullDecodeFromMemory (caught)\n"); return E_OUTOFMEMORY; } } @@ -5834,6 +5835,11 @@ static void ForceForegroundWindow(HWND hwnd) { } int WINAPI wWinMain(HINSTANCE hInstance, HINSTANCE, LPWSTR lpCmdLine, int nCmdShow) { + + struct EtwScope { + EtwScope() { QuickView::Logging::Initialize(); } + ~EtwScope() { QuickView::Logging::Shutdown(); } + } etwScope; // === Priority 0: Tool subprocess dispatch (must be first) === int toolExitCode = 0; if (TryRunToolProcessFromCommandLine(&toolExitCode)) { @@ -6296,7 +6302,7 @@ LRESULT CALLBACK WndProc(HWND hwnd, UINT message, WPARAM wParam, LPARAM lParam) auto nextFrame = g_imageResource.animator->GetNextFrame(); if (!nextFrame || !nextFrame->pixels) { // EOF: Loop back to frame 0 - OutputDebugStringW(L"[Anim] EOF reached, looping to frame 0\n"); + QV_LOG_INFO(L"[Anim] EOF reached, looping to frame 0\n"); nextFrame = g_imageResource.animator->SeekToFrame(0); } @@ -6319,10 +6325,10 @@ LRESULT CALLBACK WndProc(HWND hwnd, UINT message, WPARAM wParam, LPARAM lParam) RenderImageToDComp(hwnd, g_imageResource, true); RequestRepaint(PaintLayer::Image | PaintLayer::Dynamic); } else { - OutputDebugStringW(L"[Anim] UploadRawFrameToGPU FAILED\n"); + QV_LOG_INFO(L"[Anim] UploadRawFrameToGPU FAILED\n"); } } else { - OutputDebugStringW(L"[Anim] SeekToFrame(0) also returned null, stopping\n"); + QV_LOG_INFO(L"[Anim] SeekToFrame(0) also returned null, stopping\n"); KillTimer(hwnd, IDT_ANIMATION); } return 0; @@ -8047,7 +8053,7 @@ SKIP_EDGE_NAV:; // [Debug OSD] wchar_t dbg[256]; swprintf_s(dbg, L"[OSD] VisualW=%.0f MetaW=%.0f NewScale=%.4f OSD=%.4f\n", visualSize.width, originalDim, newTotalScale, osdScale); - OutputDebugStringW(dbg); + QV_LOG_INFO(dbg); } } @@ -8112,13 +8118,13 @@ SKIP_EDGE_NAV:; case '3': g_slowMotionMode = !g_slowMotionMode; handled = true; break; case '4': g_showTileGrid = !g_showTileGrid; - OutputDebugStringW(g_showTileGrid ? L"Tile Grid: ON\n" : L"Tile Grid: OFF\n"); + QV_LOG_INFO(g_showTileGrid ? L"Tile Grid: ON\n" : L"Tile Grid: OFF\n"); if (g_uiRenderer) g_uiRenderer->SetTileGridVisible(g_showTileGrid); handled = true; break; case '5': g_runtime.ForceHdrSimulation = !g_runtime.ForceHdrSimulation; - OutputDebugStringW(g_runtime.ForceHdrSimulation ? L"Force HDR Sim: ON\n" : L"Force HDR Sim: OFF\n"); + QV_LOG_INFO(g_runtime.ForceHdrSimulation ? L"Force HDR Sim: ON\n" : L"Force HDR Sim: OFF\n"); handled = true; // Re-evaluate display color state to trigger FP16/8-bit UNORM surface swap in CompositionEngine RefreshDisplayColorPipeline(hwnd, false); @@ -10044,7 +10050,7 @@ void ProcessEngineEvents(HWND hwnd) { wchar_t debugBuf[256]; swprintf_s(debugBuf, L"[Main] AuxLayerReady: Gain Map applied via Auto-Gate and GPU Bake triggered\n"); - OutputDebugStringW(debugBuf); + QV_LOG_INFO(debugBuf); } } break; @@ -10056,7 +10062,7 @@ void ProcessEngineEvents(HWND hwnd) { wchar_t debugBuf[256]; swprintf_s(debugBuf, L"[Main] TileReady: LOD=%d (%d,%d) ID=%llu\n", evt.tileCoord->lod, evt.tileCoord->col, evt.tileCoord->row, evt.imageId); - OutputDebugStringW(debugBuf); + QV_LOG_INFO(debugBuf); if (g_imageEngine) { // [Infinity Engine] TileManager already updated by ImageEngine::PollState @@ -10067,7 +10073,7 @@ void ProcessEngineEvents(HWND hwnd) { wchar_t debugBuf[256]; swprintf_s(debugBuf, L"[Main] TileReady IGNORED: MatchID=%d HasCoord=%d HasFrame=%d\n", (evt.imageId == g_currentImageId.load()), evt.tileCoord.has_value(), (bool)evt.rawFrame); - OutputDebugStringW(debugBuf); + QV_LOG_INFO(debugBuf); } break; @@ -10342,7 +10348,7 @@ static void PrimePhase1Placeholder(HWND hwnd, const std::wstring& path, ImageID { bool isTitan = g_isNavigatingToTitan; if (!isTitan) { - OutputDebugStringW(L"[Phase1] Non-Titan: Skip Phase 1 completely.\n"); + QV_LOG_INFO(L"[Phase1] Non-Titan: Skip Phase 1 completely.\n"); // [Fix] Do not apply skeleton. Leave current image intact for visual continuity. // Do not update metadata early to avoid DComp scaling artifacts on the old layer. return; // No Shell/WIC extraction and NO skeleton for non-Titan images @@ -10476,7 +10482,7 @@ static FireAndForget RunPhase2DispatchLoop() { if (task.imageId != g_currentImageId.load() || task.navToken != g_currentNavToken.load() || g_imagePath != task.path) { - OutputDebugStringW(L"[Phase2] QueueDispatch skipped stale task.\n"); + QV_LOG_INFO(L"[Phase2] QueueDispatch skipped stale task.\n"); g_isPhase2Debouncing.store(false, std::memory_order_release); co_await ResumeBackground{}; continue; @@ -10488,7 +10494,7 @@ static FireAndForget RunPhase2DispatchLoop() { static_cast(task.imageId), static_cast(GetTickCount64() - task.enqueueTick), task.navigatorIndex); - OutputDebugStringW(dbg); + QV_LOG_INFO(dbg); DispatchNavigationToEngine( task.path, @@ -10545,7 +10551,7 @@ static void EnqueuePhase2NavigationTask( static_cast(droppedId), static_cast(droppedSerial), static_cast(g_phase2DroppedNavTasks.load())); - OutputDebugStringW(dropBuf); + QV_LOG_INFO(dropBuf); } wchar_t pushBuf[256]; @@ -10555,7 +10561,7 @@ static void EnqueuePhase2NavigationTask( static_cast(g_phase2NavSerial.load()), static_cast(kPhase2DebounceWindowMs), navigatorIndex); - OutputDebugStringW(pushBuf); + QV_LOG_INFO(pushBuf); g_isPhase2Debouncing.store(true, std::memory_order_release); @@ -11165,7 +11171,7 @@ void OnPaint(HWND hwnd) { previewW, baseRatio, absoluteZoom); - OutputDebugStringW(tileDbg); + QV_LOG_INFO(tileDbg); } g_imageEngine->UpdateTileViewport(vp, absoluteZoom, titanMeta.Width, titanMeta.Height, baseRatio, 0.0f, 0.0f); lastVP = vp;