fix: SG-43367: eliminate EXR+WAV playback stuttering

docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-fourteen.md

@@ -150,7 +150,14 @@ When decoding EXR files, you have the option of setting both the number of reade
 
 If you want to stream EXR files you may want to reserve some of your cores for decoding. The number of EXR decoding threads can be changed from the Preferences > Formats > OpenEXR. Always check performances with **Automatic Threads** activated.
 
-If this doesn't work, deselect **Automatic Threads** and increase the number in Reader/Decoder Threads by 1. Check performances, and increase by thread count by 1. Repeat until performances are acceptable, but don't go over the number of logical cores of your workstation minus 1 (if you have 16 logical cores, don't go over 15) or your system will become unstable. If performances are still degraded, you need to look elsewhere, such as upgrading your hardware.
+When **Automatic Threads** is enabled, RV chooses the OpenEXR decoder thread count from the number of logical processors on your system:
+
+* On systems with **more than 16 logical processors**, RV uses **half** of the logical processors. All EXR decodes share a single OpenEXR thread pool, so dedicating every core to decoding can starve RV's playback/UI, audio, and caching threads and cause dropped frames — especially with DWA/DWAB-compressed EXRs. Reserving roughly half the cores (which is approximately the physical core count on hyper-threaded machines) leaves enough headroom for smooth playback.
+* On systems with **16 or fewer logical processors**, RV uses all but one logical processor.
+
+Advanced: you can override the Automatic value without changing the preference by setting the `RV_EXR_AUTO_MAX_THREADS` environment variable to the desired thread count.
+
+If this doesn't work, deselect **Automatic Threads** and increase the number in Reader/Decoder Threads by 1. Check performances, and increase the thread count by 1. Repeat until performance is acceptable. Note that on systems with many logical cores, using close to the maximum (logical cores minus 1) can make playback *worse*, not better: the decoder threads compete with RV's playback/UI threads, so the system may drop frames or become unstable. A good starting point on high-core machines is around half your logical cores. If performance is still degraded, you need to look elsewhere, such as upgrading your hardware.
 
 ### About File I/O and Decoding Latency
 

docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-sixteen.md

@@ -68,7 +68,7 @@ RVIO supports all of the same movie, image, and audio formats that RV does inclu
 | -copyright *string*       | Output copyright (movie files, default="")                                                                                                                   |
 | -debug *string*           | Debug category                                                                                                                                               |
 | -version                  | Show RVIO version number                                                                                                                                     |
-| -exrcpus *int*            | EXR thread count (default=*platform dependant*)                                                                                                              |
+| -exrcpus *int*            | EXR decoder thread count (default = number of logical cores)                                                                                                 |
 | -exrRGBA                  | EXR use basic RGBA interface (default=false)                                                                                                                 |
 | -exrInherit               | EXR guesses channel inheritance (default=false)                                                                                                              |
 | -exrIOMethod int [int]    | EXR I/O Method (0=standard, 1=buffered, 2=unbuffered, 3=MemoryMap, 4=AsyncBuffered, 5=AsyncUnbuffered, default=0) and optional chunk size (default=61440)    |

docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-three.md

@@ -168,7 +168,7 @@ You can control the size and number of log files kept by RV with the following e
 | -cmsTypes                         | Show all available Color Management Systems                                                                                                                                                                               |
 | -debug *string*                   | Debug category (events, threads, gpu, audio, audioverbose, dumpaudio, shaders, shadercode, profile, playback, playbackverbose, cache, mu, muc, compile, dtree, passes, imagefbo, nogpucache, imagefbolog, nodes, plugins) |
 | -cinalt                           | Use alternate Cineon/DPX readers                                                                                                                                                                                          |
-| -exrcpus *int*                    | EXR thread count (default=2)                                                                                                                                                                                              |
+| -exrcpus *int*                    | EXR decoder thread count (0 = automatic: half the logical cores when there are more than 16, else logical cores minus 1; default=0)                                                                                       |
 | -exrRGBA                          | EXR use basic RGBA interface (default=false)                                                                                                                                                                              |
 | -exrInherit                       | EXR guesses channel inheritance (default=false)                                                                                                                                                                           |
 | -exrIOMethod int [int]            | EXR I/O Method (0=standard, 1=buffered, 2=unbuffered, 3=MemoryMap, 4=AsyncBuffered, 5=AsyncUnbuffered, default=0) and optional chunk size (default=61440)                                                                 |

src/bin/apps/rv/main.cpp

@@ -575,7 +575,7 @@ int utf8Main(int argc, char* argv[])
     }
     else
     {
-        Imf::setGlobalThreadCount(TwkUtil::SystemInfo::numCPUs() > 1 ? (TwkUtil::SystemInfo::numCPUs() - 1) : 1);
+        Imf::setGlobalThreadCount(Rv::automaticExrThreadCount());
     }
 
     //

src/bin/nsapps/RV/main.cpp

@@ -542,7 +542,7 @@ int main(int argc, char* argv[])
     }
     else
     {
-        Imf::setGlobalThreadCount(TwkUtil::SystemInfo::numCPUs() > 1 ? (TwkUtil::SystemInfo::numCPUs() - 1) : 1);
+        Imf::setGlobalThreadCount(Rv::automaticExrThreadCount());
     }
 
     //

src/lib/app/RvApp/Options.cpp

@@ -39,6 +39,7 @@
 #include <TwkUtil/Timer.h>
 #include <TwkAudio/Audio.h>
 #include <algorithm>
+#include <cstdlib>
 #include <fstream>
 #include <iostream>
 #include <stl_ext/string_algo.h>
@@ -163,6 +164,32 @@ namespace Rv
                "plugins";
     }
 
+    int automaticExrThreadCount()
+    {
+        //  Explicit override wins (for tuning without a rebuild).
+        if (const char* v = getenv("RV_EXR_AUTO_MAX_THREADS"))
+        {
+            const int n = atoi(v);
+            if (n > 0)
+                return n;
+        }
+
+        const int cores = static_cast<int>(TwkUtil::SystemInfo::numCPUs());
+        if (cores <= 1)
+            return 1;
+
+        //  On high-core machines, reserve ~half the logical cores for the
+        //  main/UI, audio, caching and compositor threads so EXR decode (which
+        //  shares one global OpenEXR pool) cannot starve them and drop frames.
+        //  numCPUs() is the logical count, so on hyper-threaded systems this is
+        //  roughly the physical core count. Smaller machines keep the previous
+        //  behavior (all but one core).
+        if (cores > 16)
+            return cores / 2;
+
+        return cores - 1;
+    }
+
     int collectParams(Options::Params& p, const Options::Files& inputFiles, int index)
     {
         int count = -1;

src/lib/app/RvApp/RvApp/Options.h

@@ -360,6 +360,17 @@ namespace Rv
     int parseSendEvents(int, char**);
     const char* getDebugCategories();
 
+    //
+    //  The OpenEXR global thread-pool size to use when the "Automatic" EXR
+    //  thread count is selected (opts.exrcpus == 0). On high-core machines this
+    //  caps the pool at half the logical cores so decode threads cannot starve
+    //  the main/UI, audio and caching threads (which caused dropped frames,
+    //  especially with slow DWA/DWAB frames). Overridable via the
+    //  RV_EXR_AUTO_MAX_THREADS environment variable.
+    //
+
+    int automaticExrThreadCount();
+
 } // namespace Rv
 
 //

src/lib/app/RvCommon/GLView.cpp

@@ -19,7 +19,10 @@
 #include <RvCommon/RvDocument.h>
 #include <RvApp/Options.h>
 #include <iostream>
+#include <sstream>
 #include <TwkApp/Event.h>
+#include <TwkUtil/PlaybackDiagnostics.h>
+#include <TwkUtil/Clock.h>
 #include <boost/thread/thread.hpp>
 #include <boost/thread/mutex.hpp>
 #include <boost/thread/condition_variable.hpp>
@@ -361,6 +364,35 @@ namespace Rv
         IPCore::Session* session = m_doc->session();
         bool debug = IPCore::debugProfile && session;
 
+        //  Playback present-path diagnostics. The Session-side "outsideGap"
+        //  measures render_v2-end -> next render_v2-start, which lumps together
+        //  the Qt composite/swapBuffers and the event-loop work (notably the
+        //  per-render-event-processing handler). Here we time the whole paintGL
+        //  and the gap between successive paints so the analyzer can split that
+        //  bucket into swap/composite vs event-loop handlers.
+        static double s_diagPaintEntry = 0.0;
+        static double s_diagPrevPaintExit = 0.0;
+        double diagPaintGap = 0.0;
+        const bool diagOn = session && session->isPlaying() && TwkUtil::PlaybackDiagnostics::enabled();
+        if (diagOn)
+        {
+            s_diagPaintEntry = TwkUtil::SystemClock().now();
+            if (s_diagPrevPaintExit > 0.0)
+                diagPaintGap = (s_diagPaintEntry - s_diagPrevPaintExit) * 1000.0;
+        }
+
+        //  Optional GPU-completion probe (RV_DIAG_GLFINISH). session->render()
+        //  only submits GL commands (texture upload + shaders); the GPU runs
+        //  them asynchronously and the present later blocks until they finish.
+        //  glFinish() here attributes that GPU time: if it is large on new
+        //  frames the stall is the synchronous GPU upload/render; if it stays
+        //  small while the present still stalls, the block is the compositor/
+        //  present path, not the GPU.
+        static int s_diagGlFinish = -1;
+        if (s_diagGlFinish < 0)
+            s_diagGlFinish = (getenv("RV_DIAG_GLFINISH") != nullptr) ? 1 : 0;
+        double diagGpuMs = -1.0;
+
         if (!m_postFirstNonEmptyRender && session && session->postFirstNonEmptyRender())
         {
             m_postFirstNonEmptyRender = true;
@@ -423,6 +455,13 @@ namespace Rv
             session->render();
             TWK_GLDEBUG;
 
+            if (diagOn && s_diagGlFinish)
+            {
+                const double t0 = TwkUtil::SystemClock().now();
+                glFinish();
+                diagGpuMs = (TwkUtil::SystemClock().now() - t0) * 1000.0;
+            }
+
             m_firstPaintCompleted = true;
 
             // Starting with Qt 5.12.1, the resulting texture is later
@@ -551,12 +590,44 @@ namespace Rv
 
         session->postRender();
 
+        if (diagOn)
+        {
+            const double nowSecs = TwkUtil::SystemClock().now();
+            const double paintMs = (nowSecs - s_diagPaintEntry) * 1000.0;
+            s_diagPrevPaintExit = nowSecs;
+            std::ostringstream extra;
+            //  paint = whole paintGL (render_v2 + glClear tail + postRender)
+            //  gap   = previous paint-exit -> this paint-entry, i.e. the Qt
+            //          composite + swapBuffers/vsync + event loop between paints
+            extra << "paint=" << paintMs << ";gap=" << diagPaintGap << ";gpuFinish=" << diagGpuMs;
+            TwkUtil::PlaybackDiagnostics::instance().record("paint", -1, session->currentFrame(), paintMs, extra.str());
+        }
+
         m_eventProcessingTimer.start();
 
         TWK_GLDEBUG;
     }
 
-    void GLView::eventProcessingTimeout() { m_doc->session()->userGenericEvent("per-render-event-processing", ""); }
+    void GLView::eventProcessingTimeout()
+    {
+        IPCore::Session* session = m_doc->session();
+
+        //  Time the synchronous per-render event processing (Mu/Python handlers)
+        //  that runs on the GUI thread after each paint. If this is large during
+        //  stalls it is the event-loop half of the "outside render_v2" time; if
+        //  it is small, the stall is the composite/swapBuffers present path.
+        if (session && session->isPlaying() && TwkUtil::PlaybackDiagnostics::enabled())
+        {
+            const double t0 = TwkUtil::SystemClock().now();
+            session->userGenericEvent("per-render-event-processing", "");
+            const double perRenderMs = (TwkUtil::SystemClock().now() - t0) * 1000.0;
+            TwkUtil::PlaybackDiagnostics::instance().record("perrender", -1, session->currentFrame(), perRenderMs);
+        }
+        else if (session)
+        {
+            session->userGenericEvent("per-render-event-processing", "");
+        }
+    }
 
     bool GLView::event(QEvent* event)
     {

src/lib/app/RvCommon/RvPreferences.cpp

@@ -38,6 +38,7 @@
 #include <QtWidgets/QMessageBox>
 #include <QtWidgets/QFileDialog>
 #include <TwkQtCoreUtil/QtConvert.h>
+#include <RvApp/Options.h>
 #include <RvApp/RvSession.h>
 #include <TwkApp/Bundle.h>
 #include <TwkApp/VideoDevice.h>
@@ -1870,7 +1871,7 @@ namespace Rv
     {
         if (m_ui.exrNumThreadsEdit->text() == "0")
         {
-            Imf::setGlobalThreadCount(TwkUtil::SystemInfo::numCPUs() > 1 ? (TwkUtil::SystemInfo::numCPUs() - 1) : 1);
+            Imf::setGlobalThreadCount(Rv::automaticExrThreadCount());
         }
         else
         {
@@ -1885,7 +1886,7 @@ namespace Rv
             m_ui.exrNumThreadsEdit->setText("0");
             m_ui.exrNumThreadsEdit->setEnabled(false);
             m_ui.exrThreadsLabel->setEnabled(false);
-            Imf::setGlobalThreadCount(TwkUtil::SystemInfo::numCPUs() > 1 ? (TwkUtil::SystemInfo::numCPUs() - 1) : 1);
+            Imf::setGlobalThreadCount(Rv::automaticExrThreadCount());
         }
         else
         {

src/lib/audio/ALSASafeAudioModule/ALSASafeAudioRenderer.cpp

@@ -15,6 +15,7 @@
 #include <TwkAudio/Audio.h>
 #include <TwkAudio/AudioFormats.h>
 #include <TwkMovie/Movie.h>
+#include <TwkUtil/PlaybackDiagnostics.h>
 #include <iostream>
 #include <sstream>
 
@@ -1091,6 +1092,16 @@ namespace IPCore
                         cerr << endl;
                     }
 
+                    //  Record ALSA-level audio underruns independently of the
+                    //  -debug audio flag so they show up in the consolidated
+                    //  diagnostic log. -EPIPE is the classic hardware underrun.
+                    if (TwkUtil::PlaybackDiagnostics::enabled())
+                    {
+                        std::ostringstream extra;
+                        extra << "err=" << snd_strerror((int)frames);
+                        TwkUtil::PlaybackDiagnostics::instance().record("underrun", -1, -1, 0.0, extra.str());
+                    }
+
                     if (!m_pcm)
                         return;
 #ifdef USE_SAFE_ALSA
@@ -1115,6 +1126,11 @@ namespace IPCore
 
             if (pcmState == SND_PCM_STATE_XRUN)
             {
+                if (TwkUtil::PlaybackDiagnostics::enabled())
+                {
+                    TwkUtil::PlaybackDiagnostics::instance().record("underrun", -1, -1, 0.0, "state=xrun");
+                }
+
                 if (!m_pcm)
                     return;
                 if (snd_pcm_prepare(m_pcm) < 0)

src/lib/audio/ALSASafeAudioModule/CMakeLists.txt

@@ -24,7 +24,7 @@ ADD_LIBRARY(
 TARGET_INCLUDE_DIRECTORIES(
   ${_target}
   PUBLIC ${CMAKE_CURRENT_SOURCE_DIR} "$<TARGET_PROPERTY:IPCore,INTERFACE_INCLUDE_DIRECTORIES>" "$<TARGET_PROPERTY:IPBaseNodes,INTERFACE_INCLUDE_DIRECTORIES>"
-         "$<TARGET_PROPERTY:RvApp,INTERFACE_INCLUDE_DIRECTORIES>"
+         "$<TARGET_PROPERTY:RvApp,INTERFACE_INCLUDE_DIRECTORIES>" "$<TARGET_PROPERTY:TwkUtil,INTERFACE_INCLUDE_DIRECTORIES>"
 )
 
 TARGET_LINK_LIBRARIES(

src/lib/base/TwkUtil/CMakeLists.txt

@@ -41,6 +41,7 @@ SET(_sources
     MemPool.cpp
     FNV1a.cpp
     Log.cpp
+    PlaybackDiagnostics.cpp
     Clock.cpp
     sgcHopImplementation.cpp
     sgcHopTools.cpp