Replace timeGetTime() with std::chrono

Add performance related logs

avisynth_filter/src/frame_handler.h

@@ -37,7 +37,7 @@ class FrameHandler {
         std::unique_ptr<HDRSideData> hdrSideData;
     };
 
-    static auto RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, DWORD &checkpointTime, int &currentFrameRate) -> void;
+    static auto RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, std::chrono::steady_clock::time_point &checkpointTime, int &currentFrameRate) -> void;
 
     auto ResetInput() -> void;
     auto PrepareOutputSample(ATL::CComPtr<IMediaSample> &outSample, REFERENCE_TIME startTime, REFERENCE_TIME stopTime, DWORD sourceTypeSpecificFlags) -> bool;
@@ -74,11 +74,11 @@ class FrameHandler {
     std::atomic<bool> _isWorkerLatched = false;
 
     int _frameRateCheckpointInputSampleNb;
-    DWORD _frameRateCheckpointInputSampleTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointInputSampleTime;
     int _frameRateCheckpointOutputFrameNb;
-    DWORD _frameRateCheckpointOutputFrameTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointOutputFrameTime;
     int _frameRateCheckpointDeliveryFrameNb;
-    DWORD _frameRateCheckpointDeliveryFrameTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointDeliveryFrameTime;
     int _currentInputFrameRate;
     int _currentOutputFrameRate;
     int _currentDeliveryFrameRate;

filter_common/src/constants.h

@@ -43,7 +43,7 @@ static constexpr const int MAX_OUTPUT_FRAME_DURATION_PADDING         = 10;
  * Default to 25 FPS in such cases.
  */
 static constexpr const REFERENCE_TIME DEFAULT_AVG_TIME_PER_FRAME     = 400000;
-static constexpr const int STATUS_PAGE_TIMER_INTERVAL_MS             = 1000;
+static constexpr const std::chrono::milliseconds STATUS_PAGE_TIMER_INTERVAL(1000);
 static constexpr const WCHAR *UNAVAILABLE_SOURCE_PATH                = L"N/A";
 
 /*

filter_common/src/environment.cpp

@@ -33,7 +33,7 @@ Environment::Environment()
     if (!_logPath.empty()) {
         _logFile = _wfsopen(_logPath.c_str(), L"w", _SH_DENYNO);
         if (_logFile != nullptr) {
-            _logStartTime = timeGetTime();
+            _logStartTime = std::chrono::steady_clock::now();
 
             Log(L"Filter version: %hs", FILTER_VERSION_STRING);
             Log(L"Configured script file: %s", _scriptPath.filename().c_str());
@@ -48,6 +48,8 @@ Environment::Environment()
             Log(L"Loading process: %s", processName.c_str());
         }
     }
+
+    Log(L"Active CPU feature: %s", IsSupportAVX2() ? L"AVX2" : (IsSupportSSE4() ? L"SSE4" : L"Basic"));
 }
 
 Environment::~Environment() {

filter_common/src/environment.h

@@ -23,7 +23,8 @@ class Environment : public OnDemandSingleton<Environment> {
             return;
         }
 
-        const std::wstring logTemplate = std::format(L"T {:6d} @ {:8d}: {}\n", GetCurrentThreadId(), timeGetTime() - _logStartTime, format);
+        const std::chrono::steady_clock::duration elapsed = std::chrono::steady_clock::now() - _logStartTime;
+        const std::wstring logTemplate = std::format(L"T {:6d} @ {:11d}: {}\n", GetCurrentThreadId(), std::chrono::duration_cast<std::chrono::microseconds>(elapsed).count(), format);
 
         const std::unique_lock logLock(_logMutex);
 
@@ -69,7 +70,7 @@ class Environment : public OnDemandSingleton<Environment> {
 
     std::filesystem::path _logPath;
     FILE *_logFile = nullptr;
-    DWORD _logStartTime = 0;
+    std::chrono::steady_clock::time_point _logStartTime;
     std::mutex _logMutex;
 };
 

filter_common/src/format.h

@@ -2,6 +2,7 @@
 
 #pragma once
 
+#include "environment.h"
 #include "util.h"
 
 
@@ -160,6 +161,8 @@ class Format {
          * Much like 0, 2, 1, 3 -> 0, 1, 2, 3.
          */
 
+        Environment::GetInstance().Log(L"Deinterleave() start");
+
         // Input is the type for the input data each SIMD intrustion works on (__m128i, __m256i, etc.)
         using Input = std::conditional_t<intrinsicType == 1, __m128i
                     , std::conditional_t<intrinsicType == 2, __m256i
@@ -233,10 +236,14 @@ class Format {
                 dsts[p] += dstStrides[p];
             }
         }
+
+        Environment::GetInstance().Log(L"Deinterleave() end");
     }
 
     template <int intrinsicType, int componentSize>
     static constexpr auto InterleaveUV(const BYTE *src1, const BYTE *src2, int srcStride1, int srcStride2, BYTE *dst, int dstStride, int rowSize, int height) -> void {
+        Environment::GetInstance().Log(L"InterleaveUV() start");
+
         using Vector = std::conditional_t<intrinsicType == 1, __m128i
                      , std::conditional_t<intrinsicType == 2, __m256i
                      , std::array<BYTE, componentSize>>>;
@@ -281,12 +288,16 @@ class Format {
             src2 += srcStride2;
             dst += dstStride;
         }
+
+        Environment::GetInstance().Log(L"InterleaveUV() end");
     }
 
     template <int colorFamily>
     constexpr static auto InterleaveThree(std::array<const BYTE *, 3> srcs, const std::array<int, 3> &srcStrides, BYTE *dst, int dstStride, int rowSize, int height) -> void {
         // Extract 32-bit integers from each sources and form 128-bit integer, then shuffle to the correct order
 
+        Environment::GetInstance().Log(L"InterleaveThree() start");
+
         using Input = uint32_t;
         using Output = __m128i;
 
@@ -319,10 +330,14 @@ class Format {
             }
             dst += dstStride;
         }
+
+        Environment::GetInstance().Log(L"InterleaveThree() end");
     }
 
     template <int intrinsicType, int shiftSize, bool isRightShift>
     constexpr static auto BitShiftEach16BitInt(BYTE *src, BYTE *dst, int stride, int rowSize, int height) -> void {
+        Environment::GetInstance().Log(L"BitShiftEach16BitInt(%d) start", isRightShift);
+
         using Vector = std::conditional_t<intrinsicType == 1, __m128i
                      , std::conditional_t<intrinsicType == 2, __m256i
                      , uint16_t>>;
@@ -358,6 +373,8 @@ class Format {
             src += stride;
             dst += stride;
         }
+
+        Environment::GetInstance().Log(L"BitShiftEach16BitInt(%d) end", isRightShift);
     }
 
     static auto DeinterleaveY410(const BYTE *src, int srcStride, std::array<BYTE *, 3> dsts, const std::array<int, 3> &dstStrides, int rowSize, int height) -> void;

filter_common/src/format_common.cpp

@@ -139,6 +139,8 @@ auto Format::GetStrideAlignedMediaSampleSize(const AM_MEDIA_TYPE &mediaType, int
 auto Format::DeinterleaveY410(const BYTE *src, int srcStride, std::array<BYTE *, 3> dsts, const std::array<int, 3> &dstStrides, int rowSize, int height) -> void {
     // process one plane at a time by zeroing all other planes, shuffle it from different pixels together, and fix the position by right shifting
 
+    Environment::GetInstance().Log(L"DeinterleaveY410() start");
+
     using Input = __m128i;
     using Output = uint64_t;
 
@@ -166,12 +168,16 @@ auto Format::DeinterleaveY410(const BYTE *src, int srcStride, std::array<BYTE *,
             dsts[p] += dstStrides[p];
         }
     }
+
+    Environment::GetInstance().Log(L"DeinterleaveY410() end");
 }
 
 auto Format::InterleaveY410(std::array<const BYTE *, 3> srcs, const std::array<int, 3> &srcStrides, BYTE *dst, int dstStride, int rowSize, int height) -> void {
     // expand each 16-bit integer to 32-bit, left shift to right position and OR them all
     // due the expansion, only half the size for each source vector is used, therefore we need to cast
 
+    Environment::GetInstance().Log(L"InterleaveY410() start");
+
     using Input = uint64_t;
     using Output = __m128i;
 
@@ -194,6 +200,8 @@ auto Format::InterleaveY410(std::array<const BYTE *, 3> srcs, const std::array<i
         }
         dst += dstStride;
     }
+
+    Environment::GetInstance().Log(L"InterleaveY410() end");
 }
 
 }

filter_common/src/frame_handler_common.cpp

@@ -52,12 +52,12 @@ auto FrameHandler::GetInputBufferSize() const -> int {
     return static_cast<int>(_sourceFrames.size());
 }
 
-auto FrameHandler::RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, DWORD &checkpointTime, int &currentFrameRate) -> void {
-    const DWORD currentTime = timeGetTime();
-    bool reachCheckpoint = checkpointTime == 0;
+auto FrameHandler::RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, std::chrono::steady_clock::time_point &checkpointTime, int &currentFrameRate) -> void {
+    const std::chrono::steady_clock::time_point currentTime = std::chrono::steady_clock::now();
+    bool reachCheckpoint = checkpointTime.time_since_epoch().count() == 0;
 
-    if (const REFERENCE_TIME elapsedRefTime = currentTime - checkpointTime; elapsedRefTime >= STATUS_PAGE_TIMER_INTERVAL_MS) {
-        currentFrameRate = static_cast<int>(llMulDiv((static_cast<LONGLONG>(sampleNb) - checkpointSampleNb) * FRAME_RATE_SCALE_FACTOR, MILLISECONDS, elapsedRefTime, 0));
+    if (const std::chrono::steady_clock::duration elapsed = currentTime - checkpointTime; elapsed >= STATUS_PAGE_TIMER_INTERVAL) {
+        currentFrameRate = static_cast<int>(llMulDiv((static_cast<LONGLONG>(sampleNb) - checkpointSampleNb) * FRAME_RATE_SCALE_FACTOR, NANOSECONDS, std::chrono::duration_cast<std::chrono::nanoseconds>(elapsed).count(), 0));
         reachCheckpoint = true;
     }
 

filter_common/src/pch.h

@@ -6,6 +6,7 @@
 
 #include <algorithm>
 #include <array>
+#include <chrono>
 #include <clocale>
 #include <condition_variable>
 #include <filesystem>

filter_common/src/prop_status.cpp

@@ -28,7 +28,12 @@ auto CSynthFilterPropStatus::OnDisconnect() -> HRESULT {
 }
 
 auto CSynthFilterPropStatus::OnActivate() -> HRESULT {
-    if (SetTimer(m_hwnd, IDT_TIMER_STATUS, STATUS_PAGE_TIMER_INTERVAL_MS, nullptr) == 0) {
+    constexpr UINT timeIntervalMs = static_cast<UINT>(std::chrono::duration_cast<std::chrono::milliseconds>(STATUS_PAGE_TIMER_INTERVAL).count());
+    if constexpr (timeIntervalMs == 0) {
+        return E_FAIL;
+    }
+
+    if (SetTimer(m_hwnd, IDT_TIMER_STATUS, timeIntervalMs, nullptr) == 0) {
         return E_FAIL;
     }
 

vapoursynth_filter/src/frame_handler.h

@@ -38,7 +38,7 @@ class FrameHandler {
     };
 
     static auto VS_CC VpsGetFrameCallback(void *userData, const VSFrame *f, int n, VSNode *node, const char *errorMsg) -> void;
-    static auto RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, DWORD &checkpointStartTime, int &currentFrameRate) -> void;
+    static auto RefreshFrameRatesTemplate(int sampleNb, int &checkpointSampleNb, std::chrono::steady_clock::time_point &checkpointTime, int &currentFrameRate) -> void;
 
     auto ResetInput() -> void;
     auto PrepareOutputSample(ATL::CComPtr<IMediaSample> &outSample, int outputFrameNb, const VSFrame *outputFrame, int sourceFrameNb) -> bool;
@@ -81,11 +81,11 @@ class FrameHandler {
     std::atomic<bool> _isWorkerLatched = false;
 
     int _frameRateCheckpointInputSampleNb;
-    DWORD _frameRateCheckpointInputSampleTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointInputSampleTime;
     int _frameRateCheckpointOutputFrameNb;
-    DWORD _frameRateCheckpointOutputFrameTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointOutputFrameTime;
     int _frameRateCheckpointDeliveryFrameNb;
-    DWORD _frameRateCheckpointDeliveryFrameTime;
+    std::chrono::steady_clock::time_point _frameRateCheckpointDeliveryFrameTime;
     int _currentInputFrameRate;
     int _currentOutputFrameRate;
     int _currentDeliveryFrameRate;