From 64c554889c4ce129040b65ec58c8a5be3aec6742 Mon Sep 17 00:00:00 2001 From: Bernard Laberge Date: Wed, 15 Jul 2026 22:47:23 -0400 Subject: [PATCH 1/2] fix: eliminate EXR+WAV playback stutter on Linux (GPU upload, decode, OpenEXR) Fixes stuttering during playback of high-resolution multi-part EXR sequences with WAV/MOV audio on Linux. The image was correct but playback dropped well below the target frame rate even with frames fully resident in cache. Root causes were in the GPU texture-upload path, the EXR decode scheduling, and an OpenEXR 3.3 I/O regression. Playback now holds 24 fps with ~100% of large frames on the DMA fast path and per-frame present stalls effectively gone. GPU texture upload (primary fix) -- src/lib/ip/IPCore/ImageRenderer.{cpp,h}: - Make the staging PBO transient. It was allocated in initializeTexture() and pinned to the cached TextureDescription for the texture's entire cache life (~10+ frames), so with a large look-ahead cache the small fixed PBO pool was permanently occupied and most large frames fell back to the slow synchronous glTexImage2D-from-client-memory path (~72 ms, ~1.4 GB/s). The PBO is now acquired inside uploadPlane() for a single upload and released back to the pool immediately after the transfer is issued, so a handful of buffers serve an unbounded stream. Result: PBO fast-path use went ~64% -> 99.9% and CPU submit ~72 ms -> ~14 ms (~6.8 GB/s) for 4546x2864 frames. - Upload 3-channel RGB half/float frames via a native RGBA path: allocate the texture as GL_RGBA16F/RGBA32F and expand RGB->RGBA on the CPU during upload (GL_TEXTURE_RECTANGLE only). GL_RGB16F/RGB32F have no native DMA path; the driver was expanding per-pixel on upload, which is far slower. - Fix a texture cross-reuse corruption: an expanded 3ch->RGBA texture and a genuine 4ch RGBA texture produce identical destination geometry/format, so the getTexture() Compatible-reuse path could recycle one for the other and run the wrong upload path (wrong channel stride), causing image artifacts. compatible() now also compares expandRGBToRGBA so the two are never reused across each other. RGB->RGBA expanders -- src/lib/image/TwkFB/FastMemcpy.{cpp,h}: - Add parallel (task-pool) expand_rgb_to_rgba_16bit/32bit(_MP) helpers used by the upload path. EXR decode scheduling -- src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp, src/lib/ip/IPCore/IPGraph.{cpp,h}, src/lib/ip/IPCore/IPCore/IPNode.h: - When a source mixes slow-random-access media (e.g. a MOV used only for audio) with fast EXR image media, no longer serialize the whole source onto a single caching thread. testEvaluate() now inspects only the media component actually supplying the displayed image and reports hasFastVideoSource, and the caching scheduler only forces single-threaded slow-media handling when the frame has no fast image source to parallelize. This restores concurrent EXR decoding for the common "EXR + MOV-for-audio" layout. OpenEXR 3.3 I/O regression -- src/lib/image/IOexr/FileStreamIStream.{cpp,h}, src/lib/image/IOexr/IOMultiPartEXR.cpp: - OpenEXR 3.3.x is much slower for custom Imf::IStream subclasses that do not implement size()/stateless read(). RV's default memory-mapped I/O uses such a stream. Implement size(), isStatelessRead() and the stateless read() overload (guarded by IOEXR_HAS_STATELESS_ISTREAM) so 3.3+ takes the fast, concurrent read path from RV's mapped buffers. Playback diagnostics (opt-in, env-gated) -- src/lib/base/TwkUtil/ PlaybackDiagnostics.{cpp,h} (+ CMakeLists), and instrumentation in Session.{cpp,h}, Application.cpp, GLView.cpp, FBCache.{cpp,h}, IPGraph.cpp, FileSourceIPNode.cpp, ImageRenderer.cpp, ALSASafeAudioModule/ALSASafeAudioRenderer.cpp (+ CMakeLists): - Add a thread-safe, RV_PLAYBACK_DIAG-gated CSV logger capturing background decode times/concurrency/compression, audio cache-miss/underrun events, buffering pauses and frame skips, display pacing (interval/dframe/refreshes), cache hit/miss and runway, per-plane GPU upload cost/PBO usage, and a stall anatomy split (present/composite/swap vs in-graph work). All timing is behind the env gate and has no cost when disabled. - tools/analyze_playback_diag.py: analyzer that summarizes the log and reports a bottleneck verdict (decode vs audio vs cache vs present). Co-authored-by: Cursor --- src/lib/app/RvCommon/GLView.cpp | 73 +- .../ALSASafeAudioRenderer.cpp | 16 + .../audio/ALSASafeAudioModule/CMakeLists.txt | 2 +- src/lib/base/TwkUtil/CMakeLists.txt | 1 + src/lib/base/TwkUtil/PlaybackDiagnostics.cpp | 103 ++ .../TwkUtil/TwkUtil/PlaybackDiagnostics.h | 73 + src/lib/image/IOexr/FileStreamIStream.cpp | 36 + src/lib/image/IOexr/IOMultiPartEXR.cpp | 22 + src/lib/image/IOexr/IOexr/FileStreamIStream.h | 26 + src/lib/image/TwkFB/FastMemcpy.cpp | 114 ++ src/lib/image/TwkFB/TwkFB/FastMemcpy.h | 27 + src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp | 144 +- src/lib/ip/IPCore/Application.cpp | 37 +- src/lib/ip/IPCore/FBCache.cpp | 42 + src/lib/ip/IPCore/IPCore/FBCache.h | 10 + src/lib/ip/IPCore/IPCore/IPGraph.h | 10 + src/lib/ip/IPCore/IPCore/IPNode.h | 12 + src/lib/ip/IPCore/IPCore/ImageRenderer.h | 8 + src/lib/ip/IPCore/IPCore/Session.h | 6 + src/lib/ip/IPCore/IPGraph.cpp | 150 +- src/lib/ip/IPCore/ImageRenderer.cpp | 193 ++- src/lib/ip/IPCore/Session.cpp | 142 ++ tools/analyze_playback_diag.py | 1494 +++++++++++++++++ 23 files changed, 2703 insertions(+), 38 deletions(-) create mode 100644 src/lib/base/TwkUtil/PlaybackDiagnostics.cpp create mode 100644 src/lib/base/TwkUtil/TwkUtil/PlaybackDiagnostics.h create mode 100644 tools/analyze_playback_diag.py diff --git a/src/lib/app/RvCommon/GLView.cpp b/src/lib/app/RvCommon/GLView.cpp index 617f29581..4dcd8663b 100644 --- a/src/lib/app/RvCommon/GLView.cpp +++ b/src/lib/app/RvCommon/GLView.cpp @@ -19,7 +19,10 @@ #include #include #include +#include #include +#include +#include #include #include #include @@ -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) { diff --git a/src/lib/audio/ALSASafeAudioModule/ALSASafeAudioRenderer.cpp b/src/lib/audio/ALSASafeAudioModule/ALSASafeAudioRenderer.cpp index f3b464358..6bb4dcf1f 100644 --- a/src/lib/audio/ALSASafeAudioModule/ALSASafeAudioRenderer.cpp +++ b/src/lib/audio/ALSASafeAudioModule/ALSASafeAudioRenderer.cpp @@ -15,6 +15,7 @@ #include #include #include +#include #include #include @@ -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) diff --git a/src/lib/audio/ALSASafeAudioModule/CMakeLists.txt b/src/lib/audio/ALSASafeAudioModule/CMakeLists.txt index bb82b98da..b37a41c98 100644 --- a/src/lib/audio/ALSASafeAudioModule/CMakeLists.txt +++ b/src/lib/audio/ALSASafeAudioModule/CMakeLists.txt @@ -24,7 +24,7 @@ ADD_LIBRARY( TARGET_INCLUDE_DIRECTORIES( ${_target} PUBLIC ${CMAKE_CURRENT_SOURCE_DIR} "$" "$" - "$" + "$" "$" ) TARGET_LINK_LIBRARIES( diff --git a/src/lib/base/TwkUtil/CMakeLists.txt b/src/lib/base/TwkUtil/CMakeLists.txt index b15b8a65a..4bed220b9 100644 --- a/src/lib/base/TwkUtil/CMakeLists.txt +++ b/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 diff --git a/src/lib/base/TwkUtil/PlaybackDiagnostics.cpp b/src/lib/base/TwkUtil/PlaybackDiagnostics.cpp new file mode 100644 index 000000000..81ff889e2 --- /dev/null +++ b/src/lib/base/TwkUtil/PlaybackDiagnostics.cpp @@ -0,0 +1,103 @@ +//****************************************************************************** +// Copyright (c) 2026 Autodesk Inc. All rights reserved. +// +// SPDX-License-Identifier: Apache-2.0 +// +//****************************************************************************** + +#include + +#include +#include +#include + +namespace TwkUtil +{ + using namespace std; + + bool PlaybackDiagnostics::enabled() + { + // + // Cached once: RV_PLAYBACK_DIAG is interpreted purely as an on/off + // boolean (non-empty and not "0"). It is never used to build a file + // path or otherwise passed to the filesystem, so there is no + // path-injection risk from this environment variable. + // + static const bool e = []() -> bool + { + const char* v = getenv("RV_PLAYBACK_DIAG"); + if (v == nullptr || v[0] == '\0') + return false; + if (v[0] == '0' && v[1] == '\0') + return false; + return true; + }(); + return e; + } + + PlaybackDiagnostics& PlaybackDiagnostics::instance() + { + static PlaybackDiagnostics s; + return s; + } + + PlaybackDiagnostics::PlaybackDiagnostics() + : m_ok(false) + { + // + // The output path is a hard-coded constant filename in the current + // working directory. No environment variable or other external input + // is used to construct it, so there is no file-path injection risk. + // + m_file.open("rv-playback-diag.log", ios::out | ios::trunc); + if (m_file.is_open()) + { + m_file << "t_ms,event,thread,frame,dur_ms,extra\n"; + m_file.flush(); + m_ok = true; + } + + m_timer.start(); + } + + PlaybackDiagnostics::~PlaybackDiagnostics() + { + if (m_file.is_open()) + m_file.close(); + } + + void PlaybackDiagnostics::record(const char* event, int threadId, int frame, double durMs, const std::string& extra) + { + if (!enabled()) + return; + + // + // Sanitize the free-form "extra" field so it can never corrupt the CSV + // structure: a comma would be read as a new field and a newline as a + // new row. Replace commas with semicolons and any newline/carriage + // return with a space. + // + string safeExtra; + safeExtra.reserve(extra.size()); + for (char c : extra) + { + if (c == ',') + safeExtra.push_back(';'); + else if (c == '\n' || c == '\r') + safeExtra.push_back(' '); + else + safeExtra.push_back(c); + } + + const double tMs = m_timer.elapsed() * 1000.0; + + lock_guard lock(m_mutex); + + if (!m_ok) + return; + + m_file << tMs << ',' << (event ? event : "") << ',' << threadId << ',' << frame << ',' << durMs << ',' << safeExtra << '\n'; + m_file.flush(); + } + +} // namespace TwkUtil diff --git a/src/lib/base/TwkUtil/TwkUtil/PlaybackDiagnostics.h b/src/lib/base/TwkUtil/TwkUtil/PlaybackDiagnostics.h new file mode 100644 index 000000000..9bacb205f --- /dev/null +++ b/src/lib/base/TwkUtil/TwkUtil/PlaybackDiagnostics.h @@ -0,0 +1,73 @@ +//****************************************************************************** +// Copyright (c) 2026 Autodesk Inc. All rights reserved. +// +// SPDX-License-Identifier: Apache-2.0 +// +//****************************************************************************** + +#ifndef _TwkUtilPlaybackDiagnostics_h_ +#define _TwkUtilPlaybackDiagnostics_h_ + +#include +#include +#include +#include +#include + +namespace TwkUtil +{ + + // + // Lightweight, thread-safe diagnostic logger used to attribute playback + // stuttering to frame (image) decoding versus audio decoding/starvation. + // + // Enabled by setting the RV_PLAYBACK_DIAG environment variable to a + // non-empty value other than "0". When enabled it writes CSV rows to a + // fixed file named "rv-playback-diag.log" in the process's current working + // directory. + // + // Security note: the output path is a hard-coded, constant filename. No + // environment or other external input is ever used to build the path, so + // there is no file-path injection risk (RV_PLAYBACK_DIAG is only ever + // interpreted as an on/off boolean, never as a path). + // + // Row schema (header written on open): + // t_ms,event,thread,frame,dur_ms,extra + // t_ms - milliseconds since diagnostics were initialized + // event - decode | cachemiss | audiolocked | buffering | resume | + // skip | underrun + // thread - caching/worker thread id (-1 when not applicable) + // frame - frame number (-1 when not applicable) + // dur_ms - duration in milliseconds (decode time), or a context value + // such as look-ahead seconds depending on the event + // extra - free-form key=value context + // + + class TWKUTIL_EXPORT PlaybackDiagnostics + { + public: + // Cached check of the RV_PLAYBACK_DIAG environment variable. Cheap + // enough to call on hot paths: callers should build the (more + // expensive) log arguments only when this returns true. + static bool enabled(); + + static PlaybackDiagnostics& instance(); + + void record(const char* event, int threadId, int frame, double durMs, const std::string& extra = std::string()); + + private: + PlaybackDiagnostics(); + ~PlaybackDiagnostics(); + + PlaybackDiagnostics(const PlaybackDiagnostics&) = delete; + PlaybackDiagnostics& operator=(const PlaybackDiagnostics&) = delete; + + std::mutex m_mutex; + std::ofstream m_file; + Timer m_timer; + bool m_ok; + }; + +} // namespace TwkUtil + +#endif diff --git a/src/lib/image/IOexr/FileStreamIStream.cpp b/src/lib/image/IOexr/FileStreamIStream.cpp index b940e9514..ddb49347c 100644 --- a/src/lib/image/IOexr/FileStreamIStream.cpp +++ b/src/lib/image/IOexr/FileStreamIStream.cpp @@ -7,6 +7,7 @@ // #include #include +#include #include namespace TwkFB @@ -65,4 +66,39 @@ namespace TwkFB // m_index = 0; } +#ifdef IOEXR_HAS_STATELESS_ISTREAM + + int64_t FileStreamIStream::size() { return int64_t(m_stream.size()); } + + // + // The entire file lives in one contiguous, read-only buffer, so + // concurrent reads from different offsets are safe. + // + bool FileStreamIStream::isStatelessRead() const { return true; } + + int64_t FileStreamIStream::read(void* buf, uint64_t sz, uint64_t offset) + { + const char* data = static_cast(m_stream.data()); + const int64_t fileSize = int64_t(m_stream.size()); + + if (data == nullptr || fileSize < 0) + return -1; + + // + // Per the OpenEXR contract a read at or past EOF is not an error: + // return 0, and clamp a read that would run past the end. + // + if (offset >= uint64_t(fileSize)) + return 0; + + const uint64_t available = uint64_t(fileSize) - offset; + const uint64_t toCopy = (sz < available) ? sz : available; + + memcpy(buf, data + offset, size_t(toCopy)); + + return int64_t(toCopy); + } + +#endif // IOEXR_HAS_STATELESS_ISTREAM + } // namespace TwkFB diff --git a/src/lib/image/IOexr/IOMultiPartEXR.cpp b/src/lib/image/IOexr/IOMultiPartEXR.cpp index 8aad861ec..a4fb7a990 100644 --- a/src/lib/image/IOexr/IOMultiPartEXR.cpp +++ b/src/lib/image/IOexr/IOMultiPartEXR.cpp @@ -1133,6 +1133,28 @@ namespace TwkFB { addToMultiPartChannelList(requestedMPChannelList, p, partName, ci.name(), ci.channel()); } + + // + // Performance: for straight playback the caller asks for + // no specific view/layer/channel and does not request all + // channels. In that case we only need the default part + // (the primary "beauty"/rgba image, part 0 by EXR + // convention). Multipart EXRs routinely carry additional + // full-resolution parts (mattes, AOVs, etc.) which are + // never displayed unless the user explicitly selects that + // layer. Collecting every part here forces the decoder to + // decompress 2x-Nx the pixel data per frame and then throw + // most of it away, which can dominate playback cost for + // large frames. Once we have captured the default part's + // channels, stop scanning the remaining parts. Explicit + // layer/channel selection and readAllChannels still read + // exactly what was requested via the branches above. + // + if (!requestedAllChannels && !requestedMPChannelList.empty()) + { + p = numOfParts; // default part captured; skip the rest + break; + } } else { diff --git a/src/lib/image/IOexr/IOexr/FileStreamIStream.h b/src/lib/image/IOexr/IOexr/FileStreamIStream.h index 287366468..88e9c3f85 100644 --- a/src/lib/image/IOexr/IOexr/FileStreamIStream.h +++ b/src/lib/image/IOexr/IOexr/FileStreamIStream.h @@ -9,8 +9,22 @@ #define __IOexr__FileStreamIStream__h__ #include #include +#include #include +// +// OpenEXR 3.3 rewired the C++ API onto the OpenEXRCore reader. Streams that +// do not report their size() or support stateless (offset-based, thread-safe) +// reads fall onto a much slower read path and cannot have their scanlines +// decompressed concurrently. Since the whole file is already resident in one +// buffer (see TwkUtil::FileStream), we can implement both cheaply. Guard the +// overrides so the class still builds against pre-3.3 OpenEXR (which lacks +// these virtuals). +// +#if OPENEXR_VERSION_MAJOR > 3 || (OPENEXR_VERSION_MAJOR == 3 && OPENEXR_VERSION_MINOR >= 3) +#define IOEXR_HAS_STATELESS_ISTREAM 1 +#endif + namespace TwkFB { @@ -45,6 +59,18 @@ namespace TwkFB virtual void seekg(uint64_t pos); virtual void clear(); +#ifdef IOEXR_HAS_STATELESS_ISTREAM + // + // The complete file is already in a single contiguous buffer, so we + // can report its size and service concurrent, offset-based reads + // directly from that buffer without touching any shared state. This + // restores the fast/parallel reader path in OpenEXR >= 3.3. + // + virtual int64_t size(); + virtual bool isStatelessRead() const; + virtual int64_t read(void* buf, uint64_t sz, uint64_t offset); +#endif + private: FileStream m_stream; size_t m_index; diff --git a/src/lib/image/TwkFB/FastMemcpy.cpp b/src/lib/image/TwkFB/FastMemcpy.cpp index 40f0a5d58..f5bbd8728 100644 --- a/src/lib/image/TwkFB/FastMemcpy.cpp +++ b/src/lib/image/TwkFB/FastMemcpy.cpp @@ -634,3 +634,117 @@ void swap_bytes_32bit_MP(size_t width, size_t height, const uint32_t* FASTMEMCPY curY += curHeight; } } + +//------------------------------------------------------------------------------ +// RGB -> RGBA expansion (inserts an opaque alpha component). +// +// GPUs have no fast DMA path for 3-component float texture uploads +// (GL_RGB16F/GL_RGB32F): the driver expands RGB->RGBA per pixel, which is +// slow. Expanding on the CPU here lets the upload use the native +// GL_RGBA16F/GL_RGBA32F transfer path. +// +void expand_rgb_to_rgba_16bit(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint16_t* FASTMEMCPYRESTRICT outBuf, uint16_t alpha) +{ + for (size_t row = 0; row < height; row++) + { + const uint16_t* FASTMEMCPYRESTRICT p0 = reinterpret_cast(inBuf + row * inRowBytes); + uint16_t* FASTMEMCPYRESTRICT p1 = outBuf + row * width * 4; + for (size_t x = 0; x < width; x++, p0 += 3, p1 += 4) + { + p1[0] = p0[0]; + p1[1] = p0[1]; + p1[2] = p0[2]; + p1[3] = alpha; + } + } +} + +void expand_rgb_to_rgba_32bit(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint32_t* FASTMEMCPYRESTRICT outBuf, uint32_t alpha) +{ + for (size_t row = 0; row < height; row++) + { + const uint32_t* FASTMEMCPYRESTRICT p0 = reinterpret_cast(inBuf + row * inRowBytes); + uint32_t* FASTMEMCPYRESTRICT p1 = outBuf + row * width * 4; + for (size_t x = 0; x < width; x++, p0 += 3, p1 += 4) + { + p1[0] = p0[0]; + p1[1] = p0[1]; + p1[2] = p0[2]; + p1[3] = alpha; + } + } +} + +//------------------------------------------------------------------------------ +// +template class ExpandRGBToRGBATask : public Task +{ +public: + ExpandRGBToRGBATask(TaskGroup* group, size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + T* FASTMEMCPYRESTRICT outBuf, T alpha) + : Task(group) + , _width(width) + , _height(height) + , _inBuf(inBuf) + , _inRowBytes(inRowBytes) + , _outBuf(outBuf) + , _alpha(alpha) + { + } + + virtual ~ExpandRGBToRGBATask() {} + + virtual void execute() + { + if (sizeof(T) == 2) + expand_rgb_to_rgba_16bit(_width, _height, _inBuf, _inRowBytes, reinterpret_cast(_outBuf), + static_cast(_alpha)); + else + expand_rgb_to_rgba_32bit(_width, _height, _inBuf, _inRowBytes, reinterpret_cast(_outBuf), + static_cast(_alpha)); + } + + const size_t _width; + const size_t _height; + const uint8_t* FASTMEMCPYRESTRICT _inBuf; + const size_t _inRowBytes; + T* FASTMEMCPYRESTRICT _outBuf; + const T _alpha; +}; + +template +static void expand_rgb_to_rgba_MP(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + T* FASTMEMCPYRESTRICT outBuf, T alpha) +{ + HOP_PROF_FUNC(); + + const size_t numThreads = std::max(1, TwkFB::ThreadPool::getNumThreads()); + const size_t taskHeight = std::max(1, height / numThreads); + const size_t outRowElems = width * 4; + + size_t curY = 0; + TaskGroup taskGroup; + + while (curY < height) + { + const uint8_t* FASTMEMCPYRESTRICT curInBuf = inBuf + curY * inRowBytes; + T* FASTMEMCPYRESTRICT curOutBuf = outBuf + curY * outRowElems; + const size_t curHeight = std::min(taskHeight, height - curY); + TwkFB::ThreadPool::addTask(new ExpandRGBToRGBATask(&taskGroup, width, curHeight, curInBuf, inRowBytes, curOutBuf, alpha)); + curY += curHeight; + } +} + +void expand_rgb_to_rgba_16bit_MP(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint16_t* FASTMEMCPYRESTRICT outBuf, uint16_t alpha) +{ + expand_rgb_to_rgba_MP(width, height, inBuf, inRowBytes, outBuf, alpha); +} + +void expand_rgb_to_rgba_32bit_MP(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint32_t* FASTMEMCPYRESTRICT outBuf, uint32_t alpha) +{ + expand_rgb_to_rgba_MP(width, height, inBuf, inRowBytes, outBuf, alpha); +} diff --git a/src/lib/image/TwkFB/TwkFB/FastMemcpy.h b/src/lib/image/TwkFB/TwkFB/FastMemcpy.h index fbb8534b2..7cfb1cde5 100644 --- a/src/lib/image/TwkFB/TwkFB/FastMemcpy.h +++ b/src/lib/image/TwkFB/TwkFB/FastMemcpy.h @@ -67,6 +67,33 @@ extern "C" TWKFB_EXPORT void swap_bytes_32bit_MP(size_t width, size_t height, const uint32_t* FASTMEMCPYRESTRICT inBuf, uint32_t* FASTMEMCPYRESTRICT outBuf); + /// @brief Expand packed 3-component RGB to packed 4-component RGBA by + /// inserting an opaque alpha, for 16-bit components (half float). + /// + /// GPUs have no fast DMA path for 3-component float uploads (GL_RGB16F); + /// the driver expands RGB->RGBA per pixel on upload. Doing the expansion on + /// the CPU here lets the texture use the native GL_RGBA16F transfer path. + /// + /// @param width Pixels per row. + /// @param height Number of rows. + /// @param inBuf Source RGB buffer. + /// @param inRowBytes Source scanline stride in bytes (>= width*3*2). + /// @param outBuf Destination RGBA buffer (tightly packed, width*4*2 bytes/row). + /// @param alpha Raw 16-bit alpha value to insert (0x3C00 == half 1.0). + TWKFB_EXPORT void expand_rgb_to_rgba_16bit(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint16_t* FASTMEMCPYRESTRICT outBuf, uint16_t alpha); + TWKFB_EXPORT void expand_rgb_to_rgba_16bit_MP(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint16_t* FASTMEMCPYRESTRICT outBuf, uint16_t alpha); + + /// @brief Expand packed 3-component RGB to packed 4-component RGBA for + /// 32-bit components (full float). @see expand_rgb_to_rgba_16bit. + /// + /// @param alpha Raw 32-bit alpha value to insert (0x3F800000 == 1.0f). + TWKFB_EXPORT void expand_rgb_to_rgba_32bit(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint32_t* FASTMEMCPYRESTRICT outBuf, uint32_t alpha); + TWKFB_EXPORT void expand_rgb_to_rgba_32bit_MP(size_t width, size_t height, const uint8_t* FASTMEMCPYRESTRICT inBuf, size_t inRowBytes, + uint32_t* FASTMEMCPYRESTRICT outBuf, uint32_t alpha); + #ifdef __cplusplus } #endif diff --git a/src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp b/src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp index 7833011c8..e036b31c8 100644 --- a/src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp +++ b/src/lib/ip/IPBaseNodes/FileSourceIPNode.cpp @@ -33,6 +33,7 @@ #include #include #include +#include #include #include #include @@ -618,16 +619,43 @@ namespace IPCore void FileSourceIPNode::testEvaluate(const Context& context, TestEvaluationResult& result) { + // + // Random-access performance only matters for the media that actually + // supplies the image at this frame. A single source can carry several + // media -- most commonly an EXR image sequence with a MOV attached + // purely for its audio track. That MOV has a video track + // (info.video == true) and may be a slow-random-access codec, but its + // images are never decoded during caching (evaluate() only decodes the + // media returned by getMediaFromContext(), i.e. the EXR here). The old + // behaviour flagged the whole source "slow" if *any* media had a video + // track, which needlessly forced fast EXR decode onto a single caching + // thread whenever an audio MOV was present. Test only the image- + // supplying media so fast image sequences keep decoding in parallel. + // bool slow = false; + bool fastVideo = false; - for (size_t i = 0, s = numMedia(); i < s; i++) { - const MovieInfo& info = mediaMovieInfo(i); - if (info.slowRandomAccess && info.video) - slow = true; + ImageComponent selection; + MediaPointer selectedMedia = getMediaFromContext(selection, context); + if (selectedMedia && selectedMedia->hasVideo()) + { + if (const Movie* mov = selectedMedia->primaryMovie()) + { + const MovieInfo& info = mov->info(); + if (info.video) + { + if (info.slowRandomAccess) + slow = true; + else + fastVideo = true; + } + } + } } result.poorRandomAccessPerformance = slow || result.poorRandomAccessPerformance; + result.hasFastVideoSource = fastVideo || result.hasFastVideoSource; } FileSourceIPNode::MediaPointer FileSourceIPNode::getMediaFromContext(ImageComponent& selection, const Context& context) const @@ -989,6 +1017,15 @@ namespace IPCore debuggingDelay(); + // TEMP DECODE-SOURCE DIAGNOSTIC: attribute each background decode to a + // concrete media file so we can tell whether the serialized (thread 1) + // decodes are the slow MOV itself or fast EXR frames dragged onto one + // thread. Only cache-eval threads and only when diagnostics are on. + const bool diagDecode = TwkUtil::PlaybackDiagnostics::enabled() && (context.thread & CacheEvalThread); + TwkUtil::Timer diagTimer; + if (diagDecode) + diagTimer.start(); + try { #if defined(HOP_ENABLED) @@ -999,6 +1036,87 @@ namespace IPCore mov->imagesAtFrame(request, fbs); + if (diagDecode) + { + const bool selSlow = mov->info().slowRandomAccess && mov->info().video; + std::string nm; + if (const MovieReader* r = dynamic_cast(mov)) + nm = TwkUtil::basename(r->filename()); + std::ostringstream extra; + extra << "file=" << nm << ";slow=" << (selSlow ? 1 : 0); + + // Report the decoded pixel format so we can see what bit depth + // the EXRs land in (half vs full float dominates upload cost), + // the EXR compression codec (PIZ/DWA decompress much slower + // than ZIP), and how many channels/planes we actually decoded + // vs how many are displayed (decoding unused AOV channels is + // wasted decode+upload time). + if (!fbs.empty() && fbs[0]) + { + const TwkFB::FrameBuffer* fb = fbs[0]; + const char* dt = "?"; + switch (fb->dataType()) + { + case TwkFB::FrameBuffer::BIT: + dt = "bit"; + break; + case TwkFB::FrameBuffer::UCHAR: + dt = "uint8"; + break; + case TwkFB::FrameBuffer::USHORT: + dt = "uint16"; + break; + case TwkFB::FrameBuffer::UINT: + dt = "uint32"; + break; + case TwkFB::FrameBuffer::HALF: + dt = "half"; + break; + case TwkFB::FrameBuffer::FLOAT: + dt = "float32"; + break; + case TwkFB::FrameBuffer::DOUBLE: + dt = "float64"; + break; + default: + dt = "packed"; + break; + } + + // Total channels actually decoded, summed across all + // planes (planar EXR keeps each channel in its own plane). + int decodedChannels = 0; + int planeCount = 0; + std::ostringstream chNames; + for (const TwkFB::FrameBuffer* p = fb; p; p = p->nextPlane()) + { + planeCount++; + for (int c = 0; c < p->numChannels(); c++) + { + if (decodedChannels < 12) + chNames << (decodedChannels ? "|" : "") << p->channelName(c); + decodedChannels++; + } + } + + // How many channels the display pipeline will actually use + // (RV shows at most RGBA). Anything decoded beyond this is + // wasted work for straight playback. + const int displayedChannels = std::min(decodedChannels, 4); + + std::string comp = "?"; + if (fb->hasAttribute("EXR/compression")) + comp = fb->attribute("EXR/compression"); + + extra << ";type=" << dt << ";comp=" << comp << ";w=" << fb->width() << ";h=" << fb->height() << ";planes=" << planeCount + << ";chDecoded=" << decodedChannels << ";chDisplayed=" << displayedChannels + << ";extraCh=" << (decodedChannels > displayedChannels ? 1 : 0) << ";chNames=" << chNames.str(); + } + + TwkUtil::PlaybackDiagnostics::instance().record("decsrc", int(context.threadNum), context.frame, + diagTimer.elapsed() * 1000.0, extra.str()); + } + if (fbs.empty()) { empty = true; @@ -2728,6 +2846,24 @@ namespace IPCore std::copy(m_inparams.begin(), m_inparams.end(), back_inserter(request.parameters)); MovieReader* reader = TwkMovie::GenericIO::openMovieReader(filename, info, request); + // Record whether this media reports "slow random access". Only such + // sources (e.g. long-GOP h264/dnxhd movies) force RV into single-thread + // block caching; EXR image sequences normally do not. This pins down + // which source in a session is responsible for serializing decode. + // + // NOTE: the `info` local passed to openMovieReader is const/input-only + // and is NOT updated by the reader, so it always reports the default + // (slowRandomAccess=false). The authoritative value lives in the opened + // reader's own info(), which is populated during initializeVideo(). + if (reader && TwkUtil::PlaybackDiagnostics::enabled()) + { + const MovieInfo& rinfo = reader->info(); + std::ostringstream extra; + extra << "file=" << TwkUtil::basename(filename) << ";slowRandomAccess=" << (rinfo.slowRandomAccess ? 1 : 0) + << ";video=" << (rinfo.video ? 1 : 0); + TwkUtil::PlaybackDiagnostics::instance().record("sourceinfo", -1, -1, rinfo.slowRandomAccess ? 1.0 : 0.0, extra.str()); + } + if (reader && reader->needsScan()) { reader->scan(); diff --git a/src/lib/ip/IPCore/Application.cpp b/src/lib/ip/IPCore/Application.cpp index dea295516..737e74783 100644 --- a/src/lib/ip/IPCore/Application.cpp +++ b/src/lib/ip/IPCore/Application.cpp @@ -164,10 +164,45 @@ namespace IPCore void Application::timerCB() { + // + // Optional redraw-request throttle. + // + // The heartbeat fires at 120Hz and, by default (minElapsedTime=0), + // every beat posts a repaint (Session::update -> redrawImmediately -> + // QWidget::update). On the Qt6 QOpenGLWidget path each posted repaint + // drives a full FBO composite + present through the top-level window's + // backing store, and posting at ~2x the display refresh can back up + // the compositor's present queue -- causing the main thread to block + // in swapBuffers for several vsync intervals (the ~68ms display + // stalls seen in the playback diagnostics). + // + // RV_REDRAW_MIN_INTERVAL_MS sets a minimum wall-clock spacing (in ms) + // between posted redraws so we post at most ~once per display refresh. + // A value slightly below the refresh period but above one heartbeat + // (e.g. 12 for a 60Hz display driven by a 120Hz heartbeat) yields one + // redraw per refresh. Default 0 preserves the original behavior. + // + static double s_minRedrawSecs = -1.0; + if (s_minRedrawSecs < 0.0) + { + s_minRedrawSecs = 0.0; + // Env var is developer-controlled tuning, not untrusted input; it is + // parsed only as a numeric interval and never used in file/command + // paths, so it does not fall under the user-input file-path rule. + if (const char* v = getenv("RV_REDRAW_MIN_INTERVAL_MS")) + { + s_minRedrawSecs = atof(v) / 1000.0; + if (s_minRedrawSecs < 0.0) + s_minRedrawSecs = 0.0; + cerr << "INFO: RV_REDRAW_MIN_INTERVAL_MS " << (s_minRedrawSecs * 1000.0) << " ms (min spacing between posted redraws)" + << endl; + } + } + for (int i = 0; i < documents().size(); i++) { Session* s = static_cast(documents()[i]); - s->update(); + s->update(s_minRedrawSecs); } } diff --git a/src/lib/ip/IPCore/FBCache.cpp b/src/lib/ip/IPCore/FBCache.cpp index b95901b32..e54f410c5 100644 --- a/src/lib/ip/IPCore/FBCache.cpp +++ b/src/lib/ip/IPCore/FBCache.cpp @@ -13,6 +13,8 @@ #include #include #include +#include +#include static ENVVAR_BOOL(evActiveTailCaching, "RV_ACTIVE_TAIL_CACHING", false); @@ -1626,15 +1628,40 @@ namespace IPCore if (overflowing()) { + // + // Diagnostics: the cache is full and we are about to give up on + // caching the best ahead target because the best freeable frame is + // considered at least as valuable. This is precisely the "cache + // full but the frame the player needs next is not cached" + // condition. Record which ahead frame we refused to cache and + // which cached frame we chose to protect instead, so playback + // stutter can be attributed to the cache retention policy. + // + auto emitCacheStall = [&]() + { + if (!TwkUtil::PlaybackDiagnostics::enabled()) + return; + std::ostringstream extra; + extra << "cacheFrame=" << cacheTarget.frame << ";cacheUtil=" << cacheTarget.utility << ";freeFrame=" << freeTarget.frame + << ";freeUtil=" << freeTarget.utility << ";displayFrame=" << m_displayFrame; + TwkUtil::PlaybackDiagnostics::instance().record("cachestall", -1, cacheTarget.frame, 0.0, extra.str()); + }; + if (isActiveTailCachingEnabled()) { if (freeTarget.utility >= cacheTarget.utility) + { + emitCacheStall(); return; + } } else { if (freeTarget.utility >= (utility(cacheTarget.frame, FOR_FREEING) - 0.001)) + { + emitCacheStall(); return; + } } } @@ -1974,6 +2001,21 @@ namespace IPCore //------------------------------------------------------------------------------ // + int FBCache::cachedRunwayAhead(int frame, int inc, int maxCount) const + { + if (inc == 0) + inc = 1; + + int n = 0; + int f = frame + inc; + while (n < maxCount && f >= m_minFrame && f < m_maxFrame && isFrameCached(f)) + { + ++n; + f += inc; + } + return n; + } + void FBCache::computeCachedRangesStat(FrameRangeVector& array) const { array.clear(); diff --git a/src/lib/ip/IPCore/IPCore/FBCache.h b/src/lib/ip/IPCore/IPCore/FBCache.h index 22d52beb7..66aa13676 100644 --- a/src/lib/ip/IPCore/IPCore/FBCache.h +++ b/src/lib/ip/IPCore/IPCore/FBCache.h @@ -118,6 +118,16 @@ namespace IPCore bool isFrameCached(int frame) const { return m_frames.find(frame) != m_frames.end(); } + // + // Number of contiguous cached frames immediately ahead of `frame` in + // the playback direction (`inc`), capped at `maxCount`. A value of 0 + // means the very next frame to be shown is NOT cached (the display + // thread will have to decode it on the fly). Used by playback + // diagnostics to prove "cache full but the needed frame is absent". + // The caller must already hold the cache lock. + // + int cachedRunwayAhead(int frame, int inc, int maxCount) const; + bool hasPartialFrameCache(int frame) const; TreeResults testInCache(const IDTree&); diff --git a/src/lib/ip/IPCore/IPCore/IPGraph.h b/src/lib/ip/IPCore/IPCore/IPGraph.h index 714c8d0c9..d6cd3e981 100644 --- a/src/lib/ip/IPCore/IPCore/IPGraph.h +++ b/src/lib/ip/IPCore/IPCore/IPGraph.h @@ -770,6 +770,15 @@ namespace IPCore int getMaxGroupSize(bool slowMedia) const; + // + // Whether the parallel caching thread group (ids 2..N) is allowed to + // run. We only restrict caching to the single thread when *all* media + // is slow-random-access. As soon as any fast media is present we let + // the parallel threads help; genuinely slow-source frames are still + // serialized onto thread 1 by the per-frame skip in evalThreadMain. + // + bool parallelCachingAllowed() const { return m_evalHasFastMedia || !m_evalSlowMedia; } + //-------------------------------------------------------------------------- // Audio related helper methods // @@ -867,6 +876,7 @@ namespace IPCore VoidSignal m_mediaLoadingSetEmptySignal; NodeSignal m_nodeWillRemoveSignal; std::atomic_bool m_evalSlowMedia; + std::atomic_bool m_evalHasFastMedia; void* m_jobDispatcher; // opaque pointer SGC::JobDispatcher std::atomic_bool m_clearAudioCacheRequested; diff --git a/src/lib/ip/IPCore/IPCore/IPNode.h b/src/lib/ip/IPCore/IPCore/IPNode.h index c1dc7e2c6..64eef8644 100644 --- a/src/lib/ip/IPCore/IPCore/IPNode.h +++ b/src/lib/ip/IPCore/IPCore/IPNode.h @@ -360,10 +360,22 @@ namespace IPCore { TestEvaluationResult() : poorRandomAccessPerformance(false) + , hasFastVideoSource(false) { } + // Set true if any source contributing to this frame has slow + // random-access video (e.g. a long-GOP MOV). Historically this + // alone forced single-threaded block caching for the whole frame. bool poorRandomAccessPerformance; + + // Set true if any source contributing to this frame supplies fast + // random-access video (e.g. an EXR image sequence). When a frame + // composites a slow movie (often present only for its audio/ + // reference track) together with a fast image sequence, the fast + // images can still be decoded in parallel across caching threads, + // so the slow flag should not serialize the whole frame. + bool hasFastVideoSource; }; // diff --git a/src/lib/ip/IPCore/IPCore/ImageRenderer.h b/src/lib/ip/IPCore/IPCore/ImageRenderer.h index 87812b35d..252b6906d 100644 --- a/src/lib/ip/IPCore/IPCore/ImageRenderer.h +++ b/src/lib/ip/IPCore/IPCore/ImageRenderer.h @@ -177,6 +177,7 @@ namespace IPCore TextureDescription() : uploaded(false) , age(-1) + , expandRGBToRGBA(false) { } @@ -202,6 +203,13 @@ namespace IPCore size_t pixelSize; // in byte bool swapBytes; + // When true the source FrameBuffer is 3-channel RGB but the GPU + // texture is allocated as 4-channel RGBA (native fast-DMA format); + // uploadPlane() expands RGB->RGBA (opaque alpha) during upload. + // channels/format/internalFormat/pixelSize below describe the + // RGBA destination; the source stride comes from the FrameBuffer. + bool expandRGBToRGBA; + int uncropWidth; // display window size for uncropped int uncropHeight; int uncropX; // position of the data window (can be negative) for diff --git a/src/lib/ip/IPCore/IPCore/Session.h b/src/lib/ip/IPCore/IPCore/Session.h index 41c17fc85..242a36551 100644 --- a/src/lib/ip/IPCore/IPCore/Session.h +++ b/src/lib/ip/IPCore/IPCore/Session.h @@ -1270,6 +1270,12 @@ namespace IPCore int m_avPlaybackVersion; bool m_enableFastTurnAround; double m_lastDrawingTime; + // Diagnostic: number of redraw requests posted from the heartbeat + // (Session::update -> redrawImmediately -> QWidget::update). Compared + // against the actual paint (render_v2) cadence this tells us whether a + // display stall is RV failing to request paints (event-loop/timer + // starvation) or Qt coalescing/deferring paints (compositor present). + long long m_diagRedrawRequests; std::vector m_disabledEventCategories; // List of blocked event categories class FpsCalculator; diff --git a/src/lib/ip/IPCore/IPGraph.cpp b/src/lib/ip/IPCore/IPGraph.cpp index 9998e2d94..a51f63644 100644 --- a/src/lib/ip/IPCore/IPGraph.cpp +++ b/src/lib/ip/IPCore/IPGraph.cpp @@ -42,6 +42,7 @@ #include #include #include +#include #include #include #include @@ -278,6 +279,7 @@ namespace IPCore , m_topologyChanged(false) , m_cacheTimingOutput(false) , m_evalSlowMedia(false) + , m_evalHasFastMedia(false) , m_jobDispatcher(nullptr) { pthread_mutex_init(&m_internalLock, NULL); @@ -1624,11 +1626,51 @@ IPGraph::findNodesByAbstractPath(int frame, bool isCached = m_fbcache.isFrameCached(frame); PROFILE_SAMPLE(frameCachedTestEnd); + // + // Cache hit/miss verification for playback stutter. Once per newly + // presented frame, capture whether the frame the display asked for was + // actually resident in the look-ahead cache and, if not, how "full" + // the cache was and how many contiguous frames ahead were cached (the + // runway). A miss here forces an on-the-fly decode on the display + // thread below (the visible stall). Captured while the cache lock is + // still held so the numbers are consistent. + // + const bool diagCache = forDisplay && m_newFrame && TwkUtil::PlaybackDiagnostics::enabled(); + bool diagHit = isCached; + size_t diagUsed = 0, diagCap = 0; + bool diagOverflow = false; + int diagRunway = 0, diagDisplayInc = 0; + if (diagCache) + { + diagUsed = m_fbcache.used(); + diagCap = m_fbcache.capacity(); + diagOverflow = m_fbcache.overflowing(); + diagDisplayInc = m_fbcache.displayInc(); + diagRunway = m_fbcache.cachedRunwayAhead(frame, diagDisplayInc, 300); + } + double diagOtfDecodeMs = 0.0; + TWK_CACHE_UNLOCK(m_fbcache, ""); // DB ("evaluateAtFrame f " << frame << " forDisplay " << forDisplay << // " isCached " << isCached); PROFILE_SAMPLE(cacheTestEnd); + // + // Emits the displaycache verification row. Called at every exit point + // of this function that returns a display image so a miss is never + // lost. diagOtfDecodeMs is filled in by the miss branch below. + // + auto emitDiagCache = [&]() + { + if (!diagCache) + return; + const double pct = diagCap ? (100.0 * double(diagUsed) / double(diagCap)) : 0.0; + ostringstream extra; + extra << "hit=" << (diagHit ? 1 : 0) << ";full=" << pct << ";overflow=" << (diagOverflow ? 1 : 0) << ";runway=" << diagRunway + << ";used=" << diagUsed << ";cap=" << diagCap << ";otfDecodeMs=" << diagOtfDecodeMs; + TwkUtil::PlaybackDiagnostics::instance().record("displaycache", 0, frame, pct, extra.str()); + }; + if (isCached) { // @@ -1698,6 +1740,7 @@ IPGraph::findNodesByAbstractPath(int frame, { } + emitDiagCache(); return make_pair(EvalBufferNeedsRefill, img); } catch (std::exception& exc) @@ -1749,7 +1792,19 @@ IPGraph::findNodesByAbstractPath(int frame, try { DBL(DB_CACHE, "overrun: evaling in display thread, frame " << frame); + + // This is the on-the-fly decode on the display thread caused by + // a look-ahead cache miss. Time it so we can attribute the + // on-screen stall directly to the missing frame. + TwkUtil::Timer diagOtfTimer; + if (diagCache) + diagOtfTimer.start(); + img = evaluate(frame, IPNode::DisplayCacheEvalThread); + + if (diagCache) + diagOtfDecodeMs = diagOtfTimer.elapsed() * 1000.0; + if (willPause) status = EvalBufferNeedsRefill; } @@ -1831,6 +1886,7 @@ IPGraph::findNodesByAbstractPath(int frame, } } + emitDiagCache(); return make_pair(status, img); } @@ -2057,7 +2113,7 @@ IPGraph::findNodesByAbstractPath(int frame, m_threadGroupSingle->dispatch(0, 0); - if (!m_evalSlowMedia) + if (parallelCachingAllowed()) { for (size_t i = 1; i < m_threadData.size(); i++) { @@ -2107,7 +2163,7 @@ IPGraph::findNodesByAbstractPath(int frame, if (m_threadGroupSingle) m_threadGroupSingle->awaken_all_workers(); - if (m_threadGroup && !m_evalSlowMedia) + if (m_threadGroup && parallelCachingAllowed()) m_threadGroup->awaken_all_workers(); } } @@ -2360,7 +2416,16 @@ IPGraph::findNodesByAbstractPath(int frame, try { TestEvalResult r = testEvaluate(frame, IPNode::CacheEvalThread, id); - poorPerf = r.poorRandomAccessPerformance; + // Only serialize this frame onto the single caching + // thread if it has slow-random-access video AND no fast + // image source that could be decoded in parallel. When + // a slow movie (commonly present just for its audio/ + // reference track) is composited with a fast EXR image + // sequence, keep the fast images decoding across all + // caching threads instead of dragging them onto thread + // 1. Each thread uses its own movie reader, so parallel + // access to the slow movie remains thread-safe. + poorPerf = r.poorRandomAccessPerformance && !r.hasFastVideoSource; } catch (std::exception& exc) { @@ -2374,8 +2439,33 @@ IPGraph::findNodesByAbstractPath(int frame, } DB("after testEvaluate, skipThisFrame " << skipThisFrame); + // As soon as we see any fast (non-poor-random-access) + // frame, allow the parallel caching thread group to run so + // fast sources (e.g. EXR) are not penalized by the presence + // of a single slow-random-access source (e.g. an h264 MOV) + // elsewhere in the session. Genuinely slow-source frames + // are still serialized onto thread 1 by the skip below. + if (!poorPerf && !m_evalHasFastMedia) + { + m_evalHasFastMedia = true; + if (TwkUtil::PlaybackDiagnostics::enabled()) + { + TwkUtil::PlaybackDiagnostics::instance().record("parallelcache", int(id), frame, 1.0, "state=on"); + } + } + if (id == 1) { + // Log slow-media transitions. When this turns on, RV + // restricts caching to this single thread (thread 1) + // and switches to block caching, which serializes image + // decode and is a common cause of playback stutter. + if (poorPerf != m_evalSlowMedia && TwkUtil::PlaybackDiagnostics::enabled()) + { + TwkUtil::PlaybackDiagnostics::instance().record("slowmedia", int(id), frame, poorPerf ? 1.0 : 0.0, + poorPerf ? "state=on" : "state=off"); + } + m_evalSlowMedia = poorPerf; if (maxGroupSize != getMaxGroupSize(poorPerf)) // @@ -2511,8 +2601,42 @@ IPGraph::findNodesByAbstractPath(int frame, try { DB("thread " << id << " evaluate frame " << frame << ", overflowing " << m_fbcache.overflowing()); + + // Time the per-frame background decode so playback stutter + // can be attributed to slow image (e.g. EXR) decoding. This + // is where the actual disk read + decode happens during + // look-ahead/region caching. + // + // We also record how many caching threads are decoding + // concurrently at the moment this decode starts. If the + // per-decode time grows with concurrency, the reader + // threads are oversubscribing a shared resource (most + // likely the OpenEXR global thread pool: N reader threads + // x M EXR threads each thrash the CPU), so adding reader + // threads does not scale throughput. If the time is flat + // across concurrency levels, the decode is genuinely + // CPU-bound per frame and needs real parallelism instead. + static std::atomic s_activeDecodes(0); + const bool diag = TwkUtil::PlaybackDiagnostics::enabled(); + TwkUtil::Timer decodeTimer; + int diagConcurrency = 0; + if (diag) + { + decodeTimer.start(); + diagConcurrency = ++s_activeDecodes; // includes this thread + } + IPImage* img = evaluate(frame, IPNode::CacheEvalThread, id); + if (diag) + { + --s_activeDecodes; + ostringstream extra; + extra << "concurrency=" << diagConcurrency; + TwkUtil::PlaybackDiagnostics::instance().record("decode", int(id), frame, decodeTimer.elapsed() * 1000.0, + extra.str()); + } + TWK_CACHE_LOCK(m_fbcache, ""); DB("thread " << id << " evaluate frame " << frame << " ok "); // m_fbcache.trimFBsOfFrame(frame, img); @@ -2986,6 +3110,16 @@ IPGraph::findNodesByAbstractPath(int frame, cerr << "DEBUG: audio cache miss, zeroing buffer!" << endl; } + // Record audio starvation independently of -debug audio so a + // stutter run can be captured with a single env var. A steady + // stream of these means the audio decode/cache can't keep up. + if (TwkUtil::PlaybackDiagnostics::enabled()) + { + ostringstream extra; + extra << "startSample=" << inbuffer.startSample(); + TwkUtil::PlaybackDiagnostics::instance().record("cachemiss", -1, -1, 0.0, extra.str()); + } + inbuffer.zero(); found = true; } @@ -3023,6 +3157,11 @@ IPGraph::findNodesByAbstractPath(int frame, cerr << "DEBUG: audio locked out -- skipping" << endl; } + if (TwkUtil::PlaybackDiagnostics::enabled()) + { + TwkUtil::PlaybackDiagnostics::instance().record("audiolocked", -1, -1, 0.0); + } + inbuffer.zero(); } @@ -3429,6 +3568,11 @@ IPGraph::findNodesByAbstractPath(int frame, { if (n == root()) { + // Media set changed: recompute whether any fast media is present. + // The caching threads will set this back to true within a frame if + // a fast (non-poor-random-access) source exists. + m_evalHasFastMedia = false; + TwkApp::GenericStringEvent event("media-change", this, ""); sendEvent(event); m_nodeMediaChangedSignal(n); diff --git a/src/lib/ip/IPCore/ImageRenderer.cpp b/src/lib/ip/IPCore/ImageRenderer.cpp index 83b45db0b..8428e0c10 100644 --- a/src/lib/ip/IPCore/ImageRenderer.cpp +++ b/src/lib/ip/IPCore/ImageRenderer.cpp @@ -42,6 +42,8 @@ #include #include #include +#include +#include #include #include #include @@ -59,6 +61,8 @@ #include #include #include +#include +#include #ifdef PLATFORM_DARWIN #include @@ -111,6 +115,10 @@ namespace IPCore static ENVVAR_BOOL(evUsePBOs, "RV_RENDERING_USE_PBOS", true); static ENVVAR_INT(evMaxConcurrentPBOs, "RV_RENDERING_MAX_CONCURRENT_PBOS", 10); + // Upload 3-channel half/float images as native RGBA16F/RGBA32F (fast GPU + // DMA) instead of GL_RGB16F/GL_RGB32F (per-pixel driver expansion on + // upload). Set RV_EXPAND_RGB_TO_RGBA=0 to restore the legacy RGB path. + static ENVVAR_BOOL(evExpandRGBToRGBA, "RV_EXPAND_RGB_TO_RGBA", true); #define NOT_A_FRAME (std::numeric_limits::min()) #define NOT_A_COORDINATE (GLuint(-1)) @@ -3180,7 +3188,14 @@ namespace IPCore s.uncropX = image->uncropX; s.uncropY = image->uncropY; s.planar = image->planes.size() > 1; - s.numChannels = s.planar ? image->planes.size() : (image->planes.size() ? image->planes.front().tile->channels : 4); + // Report the logical source channel count. For RGB half/float images + // uploaded via the RGBA-expansion fast path the texture has 4 channels + // but the image is still logically 3-channel (opaque alpha), so undo + // the expansion here to keep externally-visible semantics unchanged. + s.numChannels = + s.planar + ? image->planes.size() + : (image->planes.size() ? (image->planes.front().tile->expandRGBToRGBA ? 3 : image->planes.front().tile->channels) : 4); s.pixelAspect = image->pixelAspect; s.initPixelAspect = image->initPixelAspect; s.device = (VideoDevice*)context.device; @@ -3860,22 +3875,44 @@ namespace IPCore bool ImageRenderer::compatible(const FrameBuffer* fb, const TextureDescription* tex) const { + // + // Build the description this fb would produce and compare against the + // existing texture. We must compare against the *derived* description + // (not the raw fb) because the destination geometry can differ from + // the source -- e.g. 3-channel RGB half/float is expanded to a + // 4-channel RGBA texture (see initializeTextureFormat), so the + // texture's channels/pixelSize/format intentionally differ from the fb. + // + TextureDescription b; + initializeTextureFormat(fb, &b); + // // Check for basic geometry // - if (fb->height() != tex->height || fb->width() != tex->width || fb->depth() != tex->depth || fb->numChannels() != tex->channels - || fb->pixelSize() != tex->pixelSize || fb->uncropWidth() != tex->uncropWidth || fb->uncropHeight() != tex->uncropHeight - || fb->uncropX() != tex->uncropX || fb->uncropY() != tex->uncropY) + if (b.height != tex->height || b.width != tex->width || b.depth != tex->depth || b.channels != tex->channels + || b.pixelSize != tex->pixelSize || b.uncropWidth != tex->uncropWidth || b.uncropHeight != tex->uncropHeight + || b.uncropX != tex->uncropX || b.uncropY != tex->uncropY) { return false; } // - // Check further + // An expanded (3ch RGB -> 4ch RGBA) texture and a genuine 4-channel + // RGBA texture produce identical destination geometry/format, but the + // *upload path* differs (one expands the source, one does not). The + // Compatible-reuse path in getTexture() does not re-run + // initializeTextureFormat, so it would leave tex->expandRGBToRGBA + // stale and make uploadPlane read the source with the wrong channel + // stride -> corruption. Never cross-reuse between the two. // - TextureDescription b; - initializeTextureFormat(fb, &b); + if (b.expandRGBToRGBA != tex->expandRGBToRGBA) + { + return false; + } + // + // Check further + // if (tex->channelType != b.channelType || tex->internalFormat != b.internalFormat || tex->format != b.format || tex->alignment != b.alignment) { @@ -4013,6 +4050,7 @@ namespace IPCore d->channels = fb->numChannels(); d->pixelSize = fb->pixelSize(); d->swapBytes = false; + d->expandRGBToRGBA = false; d->uncropWidth = fb->uncropWidth(); d->uncropHeight = fb->uncropHeight(); d->uncropX = fb->uncropX(); @@ -4184,6 +4222,34 @@ namespace IPCore break; } + // + // 3-component float texture uploads (GL_RGB16F/GL_RGB32F) have no + // native DMA path on real GPUs: the driver expands RGB->RGBA per + // pixel on upload, which is far slower than a native RGBA transfer + // (and worse when it also forces the slow non-PBO path). Allocate + // the texture as RGBA and expand RGB->RGBA on the CPU in + // uploadPlane() so we ride the native GL_RGBA16F/RGBA32F fast path. + // The extra opaque alpha is harmless (shaders sample .rgb). Only + // applies to hardware float paths; software renderer already uses + // an RGBA internal format above. + // Only the GL_TEXTURE_RECTANGLE path in uploadPlane() implements + // the RGB->RGBA expansion. Normalized-coordinate textures + // (GL_TEXTURE_1D/2D/3D, e.g. 3D color LUTs) go through + // upload{1,2,3}DTexture() which upload the source as-is, so they + // must keep the real RGB format or they would be corrupted. + if (evExpandRGBToRGBA.getValue() && !m_softwareGLRenderer && d->target == GL_TEXTURE_RECTANGLE + && (d->channelType == GL_HALF_FLOAT_ARB || d->channelType == GL_FLOAT)) + { + d->expandRGBToRGBA = true; + d->format = GL_RGBA; + d->channels = 4; + d->pixelSize = (d->channelType == GL_HALF_FLOAT_ARB) ? 8 : 16; + d->internalFormat = (d->channelType == GL_HALF_FLOAT_ARB) ? GL_RGBA16F_ARB : GL_RGBA32F_ARB; + // Destination rows are tightly packed RGBA (8 or 16 bytes/px), + // both multiples of 8, so an 8-byte unpack alignment is valid. + d->alignment = 8; + } + break; case 4: @@ -4244,22 +4310,14 @@ namespace IPCore const size_t totalBytes = d->width * d->height * d->depth * d->pixelSize; d->id = m_glState->createGLTexture(totalBytes); - // Note: The minimum size restriction is to prevent an NVIDIA driver - // issue The problem is that once a PBO has been used for a transfer < - // 128KB it becomes slow when used for larger transfers. - // -- - // Note: The upper limit restriction set on the number of concurrent - // PBOs is to prevent an explosion of PBOs allocated when the user - // switches to a large layout say with over 20 clips. These extra PBOs - // can really stress a system and also make the default layout slow to - // appear due to the time it takes to allocate all those extra PBOs. - const bool usePBO = m_pixelBuffers && (d->channels != 3 || d->channelType != GL_UNSIGNED_SHORT) && !useAppleClientStorage() - && fb->scanlinePixelPadding() == 0 && totalBytes > 128 * 1024 - && m_uploadedTextures.size() < evMaxConcurrentPBOs.getValue(); - if (usePBO) - { - d->pPBOToGPU = std::make_shared(TwkGLF::GLPixelBufferObject::TO_GPU, totalBytes); - } + // NOTE: The staging PBO used to be allocated here and stored on the + // TextureDescription, which pinned one pool buffer for the whole cache + // lifetime of the texture (~10+ frames). With a large look-ahead cache + // that starved the small fixed pool, forcing most large streaming + // frames onto the slow synchronous client-memory upload path. The PBO + // is now acquired transiently in uploadPlane() and released back to the + // pool immediately after the upload is issued, so a handful of buffers + // can serve an unbounded streaming cache. See uploadPlane(). } void ImageRenderer::assignAuxImages(const IPImage* img) @@ -4576,6 +4634,14 @@ namespace IPCore ProfilerGuard guard(m_profilingState); + // Per-upload diagnostic (Option A): measures the CPU-side submission + // time of a single plane upload and records whether the PBO fast path + // was taken plus the frame geometry/bytes. Combined with the + // RV_DIAG_GLFINISH per-paint GPU total (GLView), this distinguishes a + // slow-but-correct DMA from a fallback/non-PBO upload path. + const bool diagUpload = TwkUtil::PlaybackDiagnostics::enabled(); + const double diagUploadStart = diagUpload ? TwkUtil::SystemClock().now() : 0.0; + if (fb->coordinateType() == FrameBuffer::NormalizedCoordinates) { GLuint pixelInterpolation = GL_LINEAR; @@ -4640,8 +4706,26 @@ namespace IPCore // We should support non-contiguous pixel data in the PBO path. const bool contiguousData = (fb->scanlineSize() / fb->pixelSize()) == fb->width(); - const bool usePBO = m_pixelBuffers && (d->channels != 3 || d->channelType != GL_UNSIGNED_SHORT) && !useAppleClientStorage() - && fb->scanlinePixelPadding() == 0 && d->pPBOToGPU && d->pPBOToGPU->getSize() >= totalBytes && contiguousData; + // Transient staging PBO: acquire it from the pool for this single + // upload (the 128KB minimum avoids an NVIDIA driver slowdown where a + // PBO first used for a tiny transfer stays slow for large ones). It is + // released immediately after the upload is issued (see below), so a + // small pool of buffers can serve an unbounded streaming cache instead + // of one buffer being pinned per resident texture for its cache life. + const bool pboEligible = m_pixelBuffers && (d->channels != 3 || d->channelType != GL_UNSIGNED_SHORT) && !useAppleClientStorage() + && fb->scanlinePixelPadding() == 0 && contiguousData && totalBytes > 128 * 1024; + + if (pboEligible && !d->pPBOToGPU) + { + auto pbo = std::make_shared(TwkGLF::GLPixelBufferObject::TO_GPU, totalBytes); + // pop() hands back a zero-sized wrapper when the pool is exhausted + // or the request exceeds the max PBO size; fall back to the + // client-memory path in that case. + if (pbo->getSize() >= totalBytes) + d->pPBOToGPU = pbo; + } + + const bool usePBO = pboEligible && d->pPBOToGPU && d->pPBOToGPU->getSize() >= totalBytes; bool updateOnly = d->uploaded ? true : false; @@ -4665,7 +4749,21 @@ namespace IPCore TWK_THROW_STREAM(RenderFailedExc, "glMapBuffer FAILED" << estring); } - FastMemcpy_MP(b, p, totalBytes); + if (d->expandRGBToRGBA) + { + // Expand RGB->RGBA directly into the mapped PBO (no extra + // staging copy) so the GPU gets a native RGBA transfer. + if (d->channelType == GL_HALF_FLOAT_ARB) + expand_rgb_to_rgba_16bit_MP(iw, ih, p, fb->scanlineSize(), reinterpret_cast(b), + static_cast(0x3C00)); + else + expand_rgb_to_rgba_32bit_MP(iw, ih, p, fb->scanlineSize(), reinterpret_cast(b), + static_cast(0x3F800000)); + } + else + { + FastMemcpy_MP(b, p, totalBytes); + } d->pPBOToGPU->unmap(); d->pPBOToGPU->bind(); @@ -4675,7 +4773,9 @@ namespace IPCore glBindTexture(d->target, d->id); TWK_GLDEBUG; - glPixelStorei(GL_UNPACK_ROW_LENGTH, d->width + fb->scanlinePixelPadding()); + // Expanded data in the PBO is tightly packed RGBA (no source + // scanline padding), so the row length is just the width. + glPixelStorei(GL_UNPACK_ROW_LENGTH, d->expandRGBToRGBA ? d->width : (d->width + fb->scanlinePixelPadding())); TWK_GLDEBUG; glPixelStorei(GL_UNPACK_IMAGE_HEIGHT, d->height); TWK_GLDEBUG; @@ -4727,14 +4827,37 @@ namespace IPCore d->pPBOToGPU->unbind(); d->uploaded = true; + + // Return the staging PBO to the pool right away so the next frame's + // upload can recycle it instead of it being pinned to this cached + // texture. The pool fences the buffer, so it will not be handed out + // again until this upload's DMA has completed -- releasing now is + // safe and is what lets a small pool serve the whole stream. + d->pPBOToGPU.reset(); } else { HOP_PROF("ImageRenderer::uploadPlane() - !usePBO"); + if (d->expandRGBToRGBA) + { + // No PBO available: expand RGB->RGBA into a reusable per-thread + // scratch buffer and upload that (still a native RGBA + // transfer, just synchronous from client memory). + static thread_local std::vector expandScratch; + expandScratch.resize(totalBytes); + if (d->channelType == GL_HALF_FLOAT_ARB) + expand_rgb_to_rgba_16bit_MP(iw, ih, p, fb->scanlineSize(), reinterpret_cast(expandScratch.data()), + static_cast(0x3C00)); + else + expand_rgb_to_rgba_32bit_MP(iw, ih, p, fb->scanlineSize(), reinterpret_cast(expandScratch.data()), + static_cast(0x3F800000)); + p = expandScratch.data(); + } + glBindTexture(d->target, d->id); TWK_GLDEBUG; - glPixelStorei(GL_UNPACK_ROW_LENGTH, fb->scanlineSize() / fb->pixelSize()); + glPixelStorei(GL_UNPACK_ROW_LENGTH, d->expandRGBToRGBA ? d->width : (fb->scanlineSize() / fb->pixelSize())); TWK_GLDEBUG; glPixelStorei(GL_UNPACK_IMAGE_HEIGHT, d->height); TWK_GLDEBUG; @@ -4798,6 +4921,20 @@ namespace IPCore d->uploaded = true; } HOP_CALL(glFinish();) + + if (diagUpload) + { + const double cpuMs = (TwkUtil::SystemClock().now() - diagUploadStart) * 1000.0; + const double mbytes = totalBytes / (1024.0 * 1024.0); + // cpuThroughput is the effective GB/s of just the CPU submission + // (map+memcpy for PBO, or glTexImage2D client-copy for non-PBO). + // A slow value with usePBO=0 means we fell into the fallback path. + const double gbPerSec = (cpuMs > 0.0) ? (mbytes / 1024.0) / (cpuMs / 1000.0) : 0.0; + std::ostringstream extra; + extra << "w=" << iw << ";h=" << ih << ";ch=" << d->channels << ";type=" << d->channelType << ";pxsz=" << d->pixelSize + << ";mb=" << mbytes << ";pbo=" << (usePBO ? 1 : 0) << ";update=" << (updateOnly ? 1 : 0) << ";cpuGBps=" << gbPerSec; + TwkUtil::PlaybackDiagnostics::instance().record("upload", -1, -1, cpuMs, extra.str()); + } } //---------------------------------------------------------------------- diff --git a/src/lib/ip/IPCore/Session.cpp b/src/lib/ip/IPCore/Session.cpp index 6419e3845..132676b3d 100644 --- a/src/lib/ip/IPCore/Session.cpp +++ b/src/lib/ip/IPCore/Session.cpp @@ -35,6 +35,7 @@ #include #include #include +#include #include #include #include @@ -394,6 +395,7 @@ namespace IPCore , m_waitingOnSync(false) , m_avPlaybackVersion(DEFAULT_AVPLAYBACK_VERSION) , m_lastDrawingTime(0) + , m_diagRedrawRequests(0) { if (!m_graph) m_graph = new IPGraph(App()->nodeManager()); @@ -1870,6 +1872,13 @@ namespace IPCore m_framePatternFailCount = 0; } + // Resuming from a buffering pause: pairs with the "buffering" stop + // above so the diagnostic log shows how long each pause lasted. + if (eventData == "buffering" && isBuffering() && TwkUtil::PlaybackDiagnostics::enabled()) + { + TwkUtil::PlaybackDiagnostics::instance().record("resume", -1, m_frame, m_cacheStats.lookAheadSeconds * 1000.0); + } + if (m_avPlaybackVersion == 2) { return play_v2(eventData); @@ -2074,6 +2083,15 @@ namespace IPCore if (!isPlaying() && !isBuffering()) return; + // A stop triggered with the "buffering" reason means the look-ahead + // cache under-ran and playback is pausing to let it refill. Frequent + // buffering events indicate image (e.g. EXR) decode throughput can't + // keep up. Captured under RV_PLAYBACK_DIAG regardless of -debug flags. + if (eventData == "buffering" && TwkUtil::PlaybackDiagnostics::enabled()) + { + TwkUtil::PlaybackDiagnostics::instance().record("buffering", -1, m_frame, m_cacheStats.lookAheadSeconds * 1000.0); + } + m_timer.stop(); m_stopTimer.start(); m_preEval = false; @@ -3236,6 +3254,13 @@ namespace IPCore double now = TwkUtil::SystemClock().now(); if (now >= (m_lastDrawingTime + minElapsedTime)) { + // Count each posted redraw request so render_v2 can report + // how many requests were coalesced into a single actual + // paint (see m_diagRedrawRequests). update() posts an async + // QWidget::update(); the paint itself lands whenever Qt's + // event loop / compositor gets to it. + if (isPlaying()) + ++m_diagRedrawRequests; d->redrawImmediately(); m_lastDrawingTime = now; } @@ -3366,6 +3391,11 @@ namespace IPCore m_skipped = (newFrame - nextFrame) / inc(); if (inc() * m_skipped < 0) m_skipped = 0; + + // Realtime playback dropped one or more frames to stay in + // sync: another symptom of image decode not keeping up. + if (m_skipped != 0 && TwkUtil::PlaybackDiagnostics::enabled()) + TwkUtil::PlaybackDiagnostics::instance().record("skip", -1, m_frame, double(m_skipped)); } else if (outDeviceClock) { @@ -3895,6 +3925,52 @@ namespace IPCore int currentFrame = m_frame; m_skipped = 0; + // + // Playback pacing diagnostics. + // + // The display work (evaluate + GPU render) is measured separately in + // the "display" event below. What that cannot show is the *cadence*: + // how much wall-clock time actually elapses between successive + // displayed frames. If decode keeps up and there is no buffering yet + // the achieved fps is still below target, the time is being spent in + // the display loop itself (heartbeat throttle / vsync swap / Qt event + // loop) rather than in decode. Capture the entry-to-entry interval on + // the main thread here so the "display" record can report the true + // frame cadence and whether the frame number is actually advancing + // 1:1 (vs repeating or being skipped). + // + static double s_diagPrevRenderTime = 0.0; + static int s_diagPrevFrame = 0; + // Snapshot of m_diagRedrawRequests at the previous paint, so we can + // report how many heartbeat redraw requests were coalesced into this + // one actual paint. During a stall: many requests -> Qt deferred the + // paint (compositor); ~1 request -> the heartbeat/event loop starved. + static long long s_diagPrevRedrawReqs = 0; + // Counts how many redraws (vsync intervals) the currently-displayed + // frame has been held for. At 60Hz redraw / 24fps content a healthy + // cadence alternates 2,3,2,3... (avg 2.5). A bias toward 3 drags the + // perceived fps below target even when frames are cached and ready -- + // this is the play-all-frames vsync-quantization signature. + static int s_diagRefreshCount = 0; + // Wall-clock at the end of the previous render_v2, so we can isolate + // time spent OUTSIDE render_v2 (paintGL rest + Qt composite + + // swapBuffers/vsync + event loop) from time INSIDE it (eval + render + + // frameChangeEvent). This localizes a main-thread stall to either the + // present path or in-graph work (e.g. the synchronous frame-changed + // UI/Mu/Python handlers, which run only on new frames). + static double s_diagRenderV2EndTime = 0.0; + double diagPaceInterval = 0.0; + double diagOutsideGap = 0.0; + if (playing && TwkUtil::PlaybackDiagnostics::enabled()) + { + const double nowSecs = TwkUtil::SystemClock().now(); + if (s_diagPrevRenderTime > 0.0) + diagPaceInterval = (nowSecs - s_diagPrevRenderTime) * 1000.0; + if (s_diagRenderV2EndTime > 0.0) + diagOutsideGap = (nowSecs - s_diagRenderV2EndTime) * 1000.0; + s_diagPrevRenderTime = nowSecs; + } + bool outDeviceClock = m_realtimeOverride && multipleVideoDevices() && outputVideoDevice()->hasClock(); // if (m_outputVideoDevice) cerr << "ovd timing " << @@ -3954,6 +4030,11 @@ namespace IPCore m_skipped = (newFrame - nextFrame) / inc(); if (inc() * m_skipped < 0) m_skipped = 0; + + // Realtime playback dropped one or more frames to stay in + // sync: another symptom of image decode not keeping up. + if (m_skipped != 0 && TwkUtil::PlaybackDiagnostics::enabled()) + TwkUtil::PlaybackDiagnostics::instance().record("skip", -1, m_frame, double(m_skipped)); } else if (outDeviceClock) { @@ -4150,6 +4231,15 @@ namespace IPCore graph().beginProfilingSample(); } + // Time how long it takes to pull the frame for display from the + // cache. In Play-All-Frames this should be tiny for cached frames; + // if it isn't, the display is stalling on evaluation rather than + // on the GPU render below. + const bool diagDisplay = TwkUtil::PlaybackDiagnostics::enabled(); + TwkUtil::Timer diagEvalTimer; + if (diagDisplay) + diagEvalTimer.start(); + try { HOP_CALL(glFinish();) @@ -4203,6 +4293,8 @@ namespace IPCore graph().endProfilingSample(); } + const double diagEvalMs = diagDisplay ? diagEvalTimer.elapsed() * 1000.0 : 0.0; + const float clockMult = fps() / currentTargetFPS(); if (hasAudio() && (!realtime() || clockMult != 1.0) && !outDeviceClock) @@ -4270,6 +4362,15 @@ namespace IPCore AuxUserRender auxRender(this); AuxAudioRenderer auxAudio(this); + // Time the GPU-side work (texture upload + shaders + present) + // for this displayed frame. In Play-All-Frames the achieved + // fps is 1 / (evaluate + this render), so if this dominates the + // frame budget the stall is on the render path (e.g. large + // synchronous texture uploads), not on decode/cache. + TwkUtil::Timer diagRenderTimer; + if (diagDisplay) + diagRenderTimer.start(); + waitForUploadToFinish(); m_waitForUploadThreadPrefetch = m_preEval && useThreadedUpload(); @@ -4290,6 +4391,42 @@ namespace IPCore m_renderer->render(m_frame, m_displayImage, &auxRender, &auxAudio); } + if (diagDisplay) + { + const double diagRenderMs = diagRenderTimer.elapsed() * 1000.0; + + // Frame delta since the previous displayed frame: +1 is a + // clean advance, 0 means the same frame was displayed again + // (the elapsed clock said "stay"), >1 means frames were + // skipped. Combined with the interval this shows whether we + // are dropping to a lower cadence or repeating frames. + const int diagDFrame = m_frame - s_diagPrevFrame; + s_diagPrevFrame = m_frame; + + // Every display pass is one redraw/vsync interval. When a + // new frame finally appears (dframe != 0), refreshes holds + // how many redraws the *previous* frame was shown for -- the + // 2-vs-3 hold count we want to prove the pacing bias. + s_diagRefreshCount++; + int diagRefreshes = 0; + if (diagDFrame != 0) + { + diagRefreshes = s_diagRefreshCount; + s_diagRefreshCount = 0; + } + + // Heartbeat redraw requests coalesced into this paint. + const long long diagReqs = m_diagRedrawRequests - s_diagPrevRedrawReqs; + s_diagPrevRedrawReqs = m_diagRedrawRequests; + + std::ostringstream extra; + extra << "eval=" << diagEvalMs << ";render=" << diagRenderMs << ";threadedUpload=" << (useThreadedUpload() ? 1 : 0) + << ";interval=" << diagPaceInterval << ";dframe=" << diagDFrame << ";skipped=" << m_skipped + << ";refreshes=" << diagRefreshes << ";shift=" << m_shift << ";elapsed=" << elapsed << ";reqs=" << diagReqs + << ";outsideGap=" << diagOutsideGap; + TwkUtil::PlaybackDiagnostics::instance().record("display", 0, m_frame, diagEvalMs + diagRenderMs, extra.str()); + } + if (debugProfile) { ProfilingRecord& trecord = currentProfilingSample(); @@ -4421,6 +4558,11 @@ namespace IPCore m_lastFrame = m_frame; m_rendering = false; + + // Mark when render_v2 returns so the next entry can measure the time + // spent outside render_v2 (present/composite/swap + event loop). + if (playing && TwkUtil::PlaybackDiagnostics::enabled()) + s_diagRenderV2EndTime = TwkUtil::SystemClock().now(); } void Session::waitForUploadToFinish() diff --git a/tools/analyze_playback_diag.py b/tools/analyze_playback_diag.py new file mode 100644 index 000000000..b64a60a84 --- /dev/null +++ b/tools/analyze_playback_diag.py @@ -0,0 +1,1494 @@ +#!/usr/bin/env python3 +# Copyright (c) 2026 Autodesk Inc. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 +"""Analyze an OpenRV playback diagnostics log to attribute stuttering to frame +(image/EXR) decoding vs audio decoding/starvation vs both. + +It ingests the CSV file produced when OpenRV is run with the RV_PLAYBACK_DIAG +environment variable set (default name: rv-playback-diag.log), and optionally an +.rvprof file written by `-debug profile`. + +Standard library only -- no third party dependencies. + +Usage: + python3 analyze_playback_diag.py [rv-playback-diag.log] --fps 24 [--rvprof FILE] + +Diagnostic log row schema: + t_ms,event,thread,frame,dur_ms,extra +Events: + decode - one background image decode completed (dur_ms = decode time) + cachemiss - audio look-ahead cache had no data ready (silence emitted) + audiolocked - audio fill was locked out and skipped (silence emitted) + underrun - ALSA hardware underrun / xrun + buffering - playback paused because the frame cache under-ran + resume - playback resumed after a buffering pause + skip - realtime playback dropped one or more frames + display - one on-screen frame was shown (dur_ms = evaluate + render); + extra: eval=;render=;threadedUpload=<0|1>; + interval=;dframe=; + skipped=;refreshes=; + shift=;elapsed=; + reqs=; + outsideGap= + paint - one GLView::paintGL pass; extra: paint=; + gap=; + gpuFinish= + perrender - per-render-event-processing handler duration (GUI-thread + Mu/Python work run between paints); dur_ms = handler time + decsrc - one media decode (extra reports file/type/bit-depth/size) + displaycache- per presented frame: was it resident in cache? extra: + hit=<0|1>;full=;overflow=<0|1>;runway=;used;cap; + otfDecodeMs= (on-the-fly decode time on a miss) + cachestall - caching gave up while cache overflowing; extra: + cacheFrame;cacheUtil;freeFrame;freeUtil;displayFrame + upload - one ImageRenderer::uploadPlane() call; dur_ms = CPU submit + time; extra: w;h;ch;type;pxsz;mb;pbo=<0|1>;update=<0|1>; + cpuGBps (effective CPU-submit throughput) +""" + +import argparse +import csv +import os +import sys +from collections import defaultdict + + +def percentile(sorted_values, pct): + """Linear-interpolated percentile of an already-sorted list.""" + if not sorted_values: + return 0.0 + if len(sorted_values) == 1: + return sorted_values[0] + rank = (pct / 100.0) * (len(sorted_values) - 1) + low = int(rank) + high = min(low + 1, len(sorted_values) - 1) + frac = rank - low + return sorted_values[low] * (1.0 - frac) + sorted_values[high] * frac + + +def mean(values): + return sum(values) / len(values) if values else 0.0 + + +def median(sorted_values): + return percentile(sorted_values, 50.0) + + +def merged_interval_length(intervals): + """Total length of the union of [start, end] intervals (same unit in/out).""" + if not intervals: + return 0.0 + ordered = sorted(intervals) + total = 0.0 + cur_start, cur_end = ordered[0] + for start, end in ordered[1:]: + if start > cur_end: + total += cur_end - cur_start + cur_start, cur_end = start, end + else: + cur_end = max(cur_end, end) + total += cur_end - cur_start + return total + + +def read_diag_log(path): + """Return (rows, header_ok). Each row is a dict with typed fields.""" + rows = [] + with open(path, newline="") as fh: + reader = csv.reader(fh) + try: + header = next(reader) + except StopIteration: + return rows + # Tolerate a missing header (older logs) by detecting a numeric first col. + if header and header[0].strip() != "t_ms": + fh.seek(0) + reader = csv.reader(fh) + for raw in reader: + if len(raw) < 5: + continue + try: + row = { + "t_ms": float(raw[0]), + "event": raw[1].strip(), + "thread": int(raw[2]), + "frame": int(raw[3]), + "dur_ms": float(raw[4]), + "extra": raw[5].strip() if len(raw) > 5 else "", + } + except ValueError: + continue + rows.append(row) + return rows + + +def analyze_decode(decode_rows, fps, span_s): + """Per-thread and aggregate image-decode statistics.""" + per_thread = defaultdict(list) + for r in decode_rows: + per_thread[r["thread"]].append(r["dur_ms"]) + + frame_budget_ms = 1000.0 / fps if fps > 0 else 0.0 + + print("=" * 72) + print("IMAGE (EXR) DECODE -- measured on background caching threads") + print("=" * 72) + if not decode_rows: + print(" No decode events recorded.") + print(" (Either the sequence was already fully cached, or caching never ran.)") + return { + "count": 0, + "active_fps": 0.0, + "measured_fps": 0.0, + "concurrency": 0.0, + "mean_ms": 0.0, + "n_threads": 0, + "top_thread_share": 0.0, + "over_budget_frac": 0.0, + } + + all_durs = sorted(r["dur_ms"] for r in decode_rows) + n_threads = len(per_thread) + mean_ms = mean(all_durs) + over_budget = [d for d in all_durs if frame_budget_ms and d > frame_budget_ms] + over_budget_frac = len(over_budget) / len(all_durs) + + print(" target fps : %.3f (frame budget %.2f ms)" % (fps, frame_budget_ms)) + print(" decode events : %d across %d caching thread(s)" % (len(decode_rows), n_threads)) + print( + " per-decode time (ms) : mean %.2f median %.2f p95 %.2f max %.2f" + % (mean_ms, median(all_durs), percentile(all_durs, 95.0), all_durs[-1]) + ) + print(" decodes over budget : %d / %d (%.1f%%)" % (len(over_budget), len(all_durs), 100.0 * over_budget_frac)) + + top_thread_share = 0.0 + print(" per-thread share :") + for tid in sorted(per_thread): + durs = sorted(per_thread[tid]) + share = len(durs) / len(decode_rows) + top_thread_share = max(top_thread_share, share) + print( + " thread %-3d : n=%-5d (%.1f%%) mean %.2f median %.2f p95 %.2f max %.2f" + % (tid, len(durs), 100.0 * share, mean(durs), median(durs), percentile(durs, 95.0), durs[-1]) + ) + + # Realized parallelism, measured from the actual busy intervals rather than + # assuming all caching threads run in parallel (they do NOT in slow-media + # mode, where RV serializes decode onto thread 1). + # busy_union = wall time during which >=1 decode was in progress + # concurrency = sum(decode time) / busy_union (avg threads working at once) + # active_fps = decodes / busy_union (real sustained decode rate) + intervals = [((r["t_ms"] - r["dur_ms"]), r["t_ms"]) for r in decode_rows] + busy_union_ms = merged_interval_length(intervals) + busy_sum_ms = sum(r["dur_ms"] for r in decode_rows) + concurrency = (busy_sum_ms / busy_union_ms) if busy_union_ms > 0 else 0.0 + active_fps = (len(decode_rows) / (busy_union_ms / 1000.0)) if busy_union_ms > 0 else 0.0 + measured_fps = len(decode_rows) / span_s if span_s > 0 else 0.0 + + print( + " realized concurrency : %.2f decode thread(s) working at once (of %d configured)" % (concurrency, n_threads) + ) + print( + " active decode rate : %.2f frames/s while decoding (busy %.1f s of %.1f s)" + % (active_fps, busy_union_ms / 1000.0, span_s) + ) + print(" overall throughput : %.2f frames/s decoded across the whole run" % measured_fps) + if top_thread_share >= 0.6: + print(" NOTE: %.0f%% of decodes ran on a single thread -> decode is effectively" % (100.0 * top_thread_share)) + print(" serialized (slow-media mode). The extra threads are NOT helping.") + if fps > 0: + judgement = "CANNOT keep up" if active_fps < fps * 0.98 else "can keep up" + print(" -> at %.2f fps the decode pipeline %s (based on realized parallelism)" % (fps, judgement)) + + # Oversubscription test: group decode time by how many decodes were running + # concurrently when each started. If median decode time climbs steeply with + # concurrency, adding reader threads is counter-productive (they fight over + # the shared OpenEXR global thread pool / CPU) and throughput will not scale. + by_conc = defaultdict(list) + for r in decode_rows: + e = parse_extra(r.get("extra", "")) + if "concurrency" in e: + try: + by_conc[int(e["concurrency"])].append(r["dur_ms"]) + except ValueError: + pass + oversubscribed = False + if by_conc: + print(" decode time vs concurrency (does adding threads scale?):") + base_med = None + for c in sorted(by_conc): + durs = sorted(by_conc[c]) + med = median(durs) + if c == 1: + base_med = med + ratio = (" (%.1fx slower than solo)" % (med / base_med)) if base_med and base_med > 0 and c > 1 else "" + # Effective aggregate throughput at this level: c frames in flight, + # each taking 'med' ms, so ~ c / med * 1000 frames/s of capacity. + eff = (c / med * 1000.0) if med > 0 else 0.0 + print(" concurrency %-2d : n=%-5d median %7.2f ms eff %5.1f fps%s" % (c, len(durs), med, eff, ratio)) + # Flag oversubscription if decodes at high concurrency are much slower + # than solo decodes (the aggregate barely improves or regresses). + if base_med and base_med > 0: + hi = [c for c in by_conc if c >= 3] + if hi: + hi_med = median(sorted([d for c in hi for d in by_conc[c]])) + if hi_med > base_med * 2.0: + oversubscribed = True + print( + " NOTE: decodes are ~%.1fx slower when %d+ run at once than when solo." + % (hi_med / base_med, min(hi)) + ) + print(" This is EXR-pool / CPU oversubscription: the reader threads are") + print(" stealing cores from each other, so more threads != more throughput.") + + return { + "count": len(decode_rows), + "active_fps": active_fps, + "measured_fps": measured_fps, + "concurrency": concurrency, + "oversubscribed": oversubscribed, + "mean_ms": mean_ms, + "n_threads": n_threads, + "top_thread_share": top_thread_share, + "over_budget_frac": over_budget_frac, + } + + +def parse_extra(extra): + """Parse a 'k=v;k=v' extra field into a dict of strings.""" + out = {} + for tok in extra.split(";"): + if "=" in tok: + k, _, v = tok.partition("=") + out[k.strip()] = v.strip() + return out + + +def analyze_display(rows, fps, span_s): + """On-screen display pacing: evaluate (cache pull) vs GPU render/upload. + + In Play-All-Frames mode the achieved fps is bounded by 1/(eval+render) per + displayed frame. If render dominates while frames are already cached, the + stall is on the GPU/upload path rather than on decode. + """ + disp = [r for r in rows if r["event"] == "display"] + + print("=" * 72) + print("DISPLAY PACING -- on-screen frame time (evaluate vs GPU render)") + print("=" * 72) + if not disp: + print(" No display events recorded.") + print(" (Rebuild with the display diagnostic, or the run predates it.)") + return {"count": 0, "render_bound": False, "achieved_fps": 0.0} + + frame_budget_ms = 1000.0 / fps if fps > 0 else 0.0 + evals, renders, totals = [], [], [] + advances = 0 # dframe == +/-1 : clean 1:1 advance + repeats = 0 # dframe == 0 : same frame shown again (redraw > content) + multi_skips = 0 # |dframe| > 1 : frames skipped + skipped_frames = 0 # sum of realtime m_skipped reported by the player + # (t_ms, dframe) per displayed frame, in capture order. We derive the true + # cadence from these absolute timestamps rather than the C++ "interval" + # field so that idle/loading stretches and pause/resume gaps (which show up + # as a handful of large outliers) do not distort the medians. + disp_samples = [] + # Hold-count (number of redraws/vsync intervals) for each *new* frame. At + # 60Hz redraw / 24fps this should alternate 2,3,2,3 (avg 2.5). A bias toward + # 3 is the play-all-frames vsync-quantization signature that drags the + # perceived fps below target even when frames are cached. + refresh_counts = [] + threaded_upload = None + bit_types = set() + for r in disp: + e = parse_extra(r["extra"]) + try: + ev = float(e.get("eval", "nan")) + rd = float(e.get("render", "nan")) + except ValueError: + continue + if ev == ev: # not NaN + evals.append(ev) + if rd == rd: + renders.append(rd) + totals.append(r["dur_ms"]) + if "threadedUpload" in e: + threaded_upload = e["threadedUpload"] == "1" + # dframe tells us whether the displayed frame number actually advanced. + df = None + if "dframe" in e: + try: + df = int(e["dframe"]) + if df == 0: + repeats += 1 + elif abs(df) == 1: + advances += 1 + else: + multi_skips += 1 + except ValueError: + df = None + disp_samples.append((r["t_ms"], df)) + if e.get("refreshes"): + try: + rc = int(e["refreshes"]) + if rc > 0: + refresh_counts.append(rc) + except ValueError: + pass + try: + skipped_frames += abs(int(e.get("skipped", "0"))) + except ValueError: + pass + + comps = defaultdict(int) + comp_times = defaultdict(list) + extra_channel_frames = 0 + decsrc_count = 0 + ch_examples = {} + for r in rows: + if r["event"] == "decsrc": + e = parse_extra(r["extra"]) + t = e.get("type") + if t: + bit_types.add(t) + c = e.get("comp") + if c: + comps[c] += 1 + comp_times[c].append(r["dur_ms"]) + if e.get("extraCh") == "1": + extra_channel_frames += 1 + if e.get("chNames") and e.get("chDecoded") not in (None, "3", "4"): + ch_examples.setdefault(e.get("chDecoded"), e.get("chNames")) + decsrc_count += 1 + + evals.sort() + renders.sort() + totals.sort() + n = len(totals) + over = [t for t in totals if frame_budget_ms and t > frame_budget_ms] + achieved_fps = (1000.0 / mean(totals)) if totals and mean(totals) > 0 else 0.0 + + print(" target fps : %.3f (frame budget %.2f ms)" % (fps, frame_budget_ms)) + print(" displayed frames : %d" % n) + if threaded_upload is not None: + print(" threaded upload : %s" % ("ON" if threaded_upload else "OFF")) + if bit_types: + print(" decoded pixel types : %s" % ", ".join(sorted(bit_types))) + if comps: + summary = ", ".join("%s x%d" % (k, v) for k, v in sorted(comps.items(), key=lambda kv: -kv[1])) + print(" EXR compression : %s" % summary) + slow_codecs = {"PIZ_COMPRESSION", "DWAA_COMPRESSION", "DWAB_COMPRESSION", "B44_COMPRESSION", "B44A_COMPRESSION"} + seen_slow = [k for k in comps if k in slow_codecs] + if seen_slow: + print(" NOTE: %s decode significantly slower than ZIP/ZIPS on CPU." % ", ".join(seen_slow)) + + # Per-compression decode time, sorted slowest-median first. Uses the + # decsrc decode duration (mov->imagesAtFrame) grouped by codec so we + # can see which compression dominates the decode cost. + print(" decode time by codec (ms):") + + def _label(codec): + return {"?": "(movie/non-EXR)"}.get(codec, codec) + + rows_by_slow = sorted(comp_times.items(), key=lambda kv: -median(sorted(kv[1]))) + for codec, times in rows_by_slow: + st = sorted(times) + print( + " %-22s n=%-5d mean %7.2f median %7.2f p95 %7.2f max %8.2f" + % (_label(codec), len(st), mean(st), median(st), percentile(st, 95.0), st[-1]) + ) + if decsrc_count: + print( + " frames decoding extra channels (> displayed RGBA): %d / %d (%.1f%%)" + % (extra_channel_frames, decsrc_count, 100.0 * extra_channel_frames / decsrc_count) + ) + for chd, names in list(ch_examples.items())[:3]: + print(" e.g. %s channels decoded: %s" % (chd, names)) + if evals: + print( + " evaluate/pull (ms) : mean %.2f median %.2f p95 %.2f max %.2f" + % (mean(evals), median(evals), percentile(evals, 95.0), evals[-1]) + ) + if renders: + print( + " GPU render+upload (ms): mean %.2f median %.2f p95 %.2f max %.2f" + % (mean(renders), median(renders), percentile(renders, 95.0), renders[-1]) + ) + print( + " total frame time (ms) : mean %.2f median %.2f p95 %.2f max %.2f" + % (mean(totals), median(totals), percentile(totals, 95.0), totals[-1]) + ) + print(" frames over budget : %d / %d (%.1f%%)" % (len(over), n, 100.0 * len(over) / n if n else 0.0)) + print(" implied display rate : %.2f fps (1 / mean frame time)" % achieved_fps) + + # + # CADENCE: the real answer to "why not 24 fps even though decode keeps up". + # + # "implied display rate" above is 1/(eval+render): the fps we *could* hit if + # the display loop had zero overhead. What matters to the eye is how often a + # *new* frame actually appears. We derive that from the absolute timestamps + # of the display events: + # * redraw gap = time between successive on-screen redraws (any frame) + # * advance gap = time between successive *new* frames (dframe advanced) + # Using medians of these gaps ignores idle/loading time and pause/resume + # outliers, so the numbers reflect steady-state playback rather than the + # whole-file average. + # + redraw_gaps = [] + for i in range(1, len(disp_samples)): + g = disp_samples[i][0] - disp_samples[i - 1][0] + if g > 0: + redraw_gaps.append(g) + + advance_ts = [t for (t, df) in disp_samples if df is not None and df != 0] + advance_gaps = [] + for i in range(1, len(advance_ts)): + g = advance_ts[i] - advance_ts[i - 1] + if g > 0: + advance_gaps.append(g) + + # A "stall" is an advance gap noticeably longer than the frame budget: the + # frame froze on screen longer than it should have (the visible stutter). + stall_gaps = [g for g in advance_gaps if frame_budget_ms and g > frame_budget_ms * 1.5] + + redraw_hz = 0.0 + playback_fps = 0.0 + med_advance_gap = 0.0 + if redraw_gaps or advance_gaps: + print(" --") + print(" frame cadence (from timestamps) :") + + if redraw_gaps: + srg = sorted(redraw_gaps) + redraw_hz = 1000.0 / median(srg) if median(srg) > 0 else 0.0 + print( + " redraw gap (ms) : median %.2f p95 %.2f max %.2f -> %.1f Hz redraw" + % (median(srg), percentile(srg, 95.0), srg[-1], redraw_hz) + ) + + print( + " frame advances : %d new, %d repeats (dframe=0), %d multi-skips (>1)" + % (advances, repeats, multi_skips) + ) + + if advance_gaps: + sag = sorted(advance_gaps) + med_advance_gap = median(sag) + playback_fps = 1000.0 / med_advance_gap if med_advance_gap > 0 else 0.0 + print( + " new-frame gap (ms) : median %.2f p95 %.2f max %.2f" + % (med_advance_gap, percentile(sag, 95.0), sag[-1]) + ) + print(" playback rate : %.2f fps (1 / median new-frame gap = perceived fps)" % playback_fps) + if stall_gaps: + worst = sorted(stall_gaps)[-1] + print( + " stalls (>1.5x budget): %d / %d new-frame gaps froze the image; worst %.1f ms (%.1f frames)" + % (len(stall_gaps), len(advance_gaps), worst, worst / frame_budget_ms if frame_budget_ms else 0.0) + ) + + # Refresh-count distribution: the direct proof of vsync quantization. For + # 60Hz redraw / 24fps content the ideal is a 2:3 mix averaging 2.5 redraws + # per new frame; a distribution skewed to 3 (avg > 2.5) explains a sub-24fps + # perceived rate that is NOT decode- or render-bound. + if refresh_counts: + hist = defaultdict(int) + for rc in refresh_counts: + hist[rc] += 1 + avg_rc = sum(refresh_counts) / len(refresh_counts) + redraw_ms = 1000.0 / redraw_hz if redraw_hz > 0 else 0.0 + print(" refreshes/new frame : mean %.2f (redraws each new frame is held)" % avg_rc) + for k in sorted(hist): + share = 100.0 * hist[k] / len(refresh_counts) + print(" held %d redraw(s) : %5d (%4.1f%%)" % (k, hist[k], share)) + if redraw_ms > 0 and fps > 0: + ideal_rc = (1000.0 / fps) / redraw_ms + print(" ideal hold : %.2f redraws/frame -> vsync bias %+.2f" % (ideal_rc, avg_rc - ideal_rc)) + if avg_rc > ideal_rc + 0.1: + print(" NOTE: cadence is rounding UP to an extra vsync interval (play-all-frames") + print(" m_shift re-anchor): perceived fps drops below target even though") + print(" frames are cached and display work is cheap.") + + if repeats and (advances + repeats + multi_skips): + total_dr = advances + repeats + multi_skips + print( + " NOTE: %.0f%% of redraws re-show the same frame. If the playback rate above is" + % (100.0 * repeats / total_dr) + ) + print(" ~= target fps that is HEALTHY (redraw loop simply runs faster than the") + print(" content); if it is well below target, new frames are arriving late.") + if skipped_frames: + print(" realtime m_skipped : %d frame(s) reported skipped by the player" % skipped_frames) + + mean_render = mean(renders) if renders else 0.0 + mean_eval = mean(evals) if evals else 0.0 + render_bound = fps > 0 and achieved_fps < fps * 0.98 and mean_render >= mean_eval + if render_bound: + print(" -> render/upload dominates the frame budget: the display loop, not") + print(" decode, is capping the fps (frames are cached but slow to show).") + + # Cadence-based classification (robust to idle time): + # healthy : new frames arrive at ~target and redraw work is cheap + # stutter : new-frame gaps are erratic / well below target while the + # measured display work per frame is small -> frames arriving + # late (decode/scheduling), not render-bound. + cadence_ok = fps > 0 and playback_fps >= fps * 0.95 + cadence_stutter = fps > 0 and playback_fps > 0 and playback_fps < fps * 0.9 and mean(totals) < frame_budget_ms * 0.5 + if cadence_stutter: + print(" -> playback rate %.1f fps < target %.1f fps although per-frame display work is" % (playback_fps, fps)) + print(" only %.2f ms: new frames are arriving late (not display/render bound)." % mean(totals)) + if stall_gaps: + print(" %d visible stall(s) where the on-screen frame froze > 1.5x the budget." % len(stall_gaps)) + + return { + "count": n, + "render_bound": render_bound, + "cadence_ok": cadence_ok, + "cadence_stutter": cadence_stutter, + "achieved_fps": achieved_fps, + "redraw_hz": redraw_hz, + "playback_fps": playback_fps, + "med_advance_gap_ms": med_advance_gap, + "stalls": len(stall_gaps), + "repeats": repeats, + "advances": advances, + "mean_render_ms": mean_render, + "mean_eval_ms": mean_eval, + "bit_types": sorted(bit_types), + } + + +def analyze_audio(rows, span_s): + """Audio starvation statistics.""" + misses = [r for r in rows if r["event"] == "cachemiss"] + locked = [r for r in rows if r["event"] == "audiolocked"] + underruns = [r for r in rows if r["event"] == "underrun"] + + print("=" * 72) + print("AUDIO -- cache misses, lock-outs and hardware underruns") + print("=" * 72) + total = len(misses) + len(locked) + len(underruns) + print(" audio cache misses : %d" % len(misses)) + print(" audio lock-outs : %d" % len(locked)) + print(" ALSA underruns/xruns : %d" % len(underruns)) + if span_s > 0: + print(" starvation rate : %.3f events/s over %.1f s" % (total / span_s, span_s)) + + # First event is often a harmless startup miss; count steady-state ones. + steady = [r for r in (misses + locked + underruns) if r["t_ms"] > 2000.0] + print(" steady-state events : %d (excluding first 2 s of playback)" % len(steady)) + return { + "misses": len(misses), + "locked": len(locked), + "underruns": len(underruns), + "total": total, + "steady": len(steady), + } + + +def analyze_buffering(rows, span_s): + """Buffering pauses (frame cache under-runs) and realtime skips.""" + events = [r for r in rows if r["event"] in ("buffering", "resume")] + buffering = [r for r in rows if r["event"] == "buffering"] + skips = [r for r in rows if r["event"] == "skip"] + + print("=" * 72) + print("PLAYBACK CONTROL -- buffering pauses and realtime frame skips") + print("=" * 72) + print(" buffering pauses : %d" % len(buffering)) + print( + " realtime frame skips : %d event(s), %d frame(s) dropped" + % (len(skips), sum(abs(int(r["dur_ms"])) for r in skips)) + ) + + # Pair buffering -> resume in time order to estimate pause durations. + pause_durations = [] + open_pause_t = None + for r in sorted(events, key=lambda x: x["t_ms"]): + if r["event"] == "buffering" and open_pause_t is None: + open_pause_t = r["t_ms"] + elif r["event"] == "resume" and open_pause_t is not None: + pause_durations.append(r["t_ms"] - open_pause_t) + open_pause_t = None + if pause_durations: + sp = sorted(pause_durations) + print( + " pause duration (ms) : n=%d mean %.1f median %.1f max %.1f total %.1f" + % (len(sp), mean(sp), median(sp), sp[-1], sum(sp)) + ) + if span_s > 0: + print(" time spent buffering : %.1f%% of the run" % (100.0 * sum(sp) / (span_s * 1000.0))) + return { + "buffering": len(buffering), + "skips": len(skips), + "skipped_frames": sum(abs(int(r["dur_ms"])) for r in skips), + "pause_total_ms": sum(pause_durations), + } + + +def analyze_slow_media(rows, span_s): + """Report per-source slowRandomAccess flags and slow-media mode transitions.""" + sources = [r for r in rows if r["event"] == "sourceinfo"] + transitions = sorted((r for r in rows if r["event"] == "slowmedia"), key=lambda x: x["t_ms"]) + + if not sources and not transitions: + return {"slow_sources": 0, "slow_fraction": 0.0, "any": False} + + print("=" * 72) + print("SLOW-MEDIA MODE -- why decode may be restricted to one thread") + print("=" * 72) + + slow_sources = 0 + if sources: + print(" sources opened:") + for r in sources: + flag = "SLOW random access" if r["dur_ms"] >= 0.5 else "fast" + if r["dur_ms"] >= 0.5: + slow_sources += 1 + print(" [%s] %s" % (flag, r["extra"])) + else: + print(" (no per-source info recorded)") + + # Estimate the fraction of the run spent in slow-media mode by integrating + # the on/off transitions over time. Assume mode starts "off". + slow_ms = 0.0 + state_on = False + last_t = transitions[0]["t_ms"] if transitions else 0.0 + end_t = max((r["t_ms"] for r in rows), default=0.0) + for tr in transitions: + if state_on: + slow_ms += tr["t_ms"] - last_t + state_on = tr["dur_ms"] >= 0.5 # 1.0=on, 0.0=off + last_t = tr["t_ms"] + if state_on: + slow_ms += end_t - last_t + slow_fraction = (slow_ms / (span_s * 1000.0)) if span_s > 0 else 0.0 + + print(" slow-media transitions: %d" % len(transitions)) + if transitions: + onc = sum(1 for t in transitions if t["dur_ms"] >= 0.5) + print(" turned ON %d time(s), OFF %d time(s)" % (onc, len(transitions) - onc)) + print( + " first ON at frame %d (t=%.1f s)" + % ( + next((t["frame"] for t in transitions if t["dur_ms"] >= 0.5), -1), + next((t["t_ms"] / 1000.0 for t in transitions if t["dur_ms"] >= 0.5), 0.0), + ) + ) + print(" time in slow-media : ~%.0f%% of the run" % (100.0 * slow_fraction)) + + return {"slow_sources": slow_sources, "slow_fraction": slow_fraction, "any": True} + + +def parse_rvprof(path): + """Light parse of an .rvprof file; report display-thread frame budget overruns.""" + records = [] + try: + with open(path) as fh: + for line in fh: + line = line.strip() + if not line or line.startswith("#"): + continue + fields = {} + for tok in line.split(","): + if "=" in tok: + k, _, v = tok.partition("=") + try: + fields[k] = float(v) + except ValueError: + pass + if "R0" in fields and "R1" in fields: + records.append(fields) + except OSError as exc: + print(" could not read rvprof: %s" % exc) + return + + print("=" * 72) + print("RVPROF (display thread) -- %s" % os.path.basename(path)) + print("=" * 72) + if not records: + print(" No usable per-frame records found.") + return + + render_ms = sorted(1000.0 * (r["R1"] - r["R0"]) for r in records if r["R1"] >= r["R0"]) + io_ms = sorted( + 1000.0 * (r["IO1"] - r["IO0"]) for r in records if "IO1" in r and "IO0" in r and r["IO1"] >= r["IO0"] + ) + print(" frames profiled : %d" % len(records)) + if render_ms: + print( + " display render (ms) : mean %.2f median %.2f p95 %.2f max %.2f" + % (mean(render_ms), median(render_ms), percentile(render_ms, 95.0), render_ms[-1]) + ) + if io_ms: + nonzero = [v for v in io_ms if v > 0.01] + print( + " display-thread IO (ms): %d/%d frames did synchronous IO; mean(nonzero) %.2f max %.2f" + % (len(nonzero), len(io_ms), mean(nonzero) if nonzero else 0.0, io_ms[-1]) + ) + print(" (display-thread IO > 0 means a cache miss forced a decode on the display") + print(" thread -- a direct on-screen stutter caused by slow image decode.)") + + +def analyze_cache(rows, fps, span_s): + """Cache-content verification: was the frame the display asked for actually + resident in the look-ahead cache, and if not, how full was the cache? + + Emitted by IPGraph::evaluateAtFrame (displaycache) and + FBCache::initiateCachingOfBestFrameGroup (cachestall). + """ + dc = [r for r in rows if r["event"] == "displaycache"] + stalls = [r for r in rows if r["event"] == "cachestall"] + + print("=" * 72) + print("CACHE CONTENT -- was the needed frame actually in cache?") + print("=" * 72) + if not dc: + print(" No displaycache events recorded.") + print(" (Rebuild with the cache-content diagnostic, or the run predates it.)") + return {"count": 0, "miss_rate": 0.0, "misses": 0, "cachestalls": len(stalls)} + + n = len(dc) + hits, misses = 0, 0 + miss_full = [] # cache percent-full at each miss + miss_runway = [] # contiguous cached frames ahead at each miss + miss_overflow = 0 # misses where the cache was overflowing (full) + otf_ms = [] # on-the-fly decode time (display thread) at misses + runway_all = [] # runway on every presented frame (hit or miss) + zero_runway = 0 # presented frames whose NEXT frame was not cached + full_all = [] + for r in dc: + e = parse_extra(r["extra"]) + is_hit = e.get("hit") == "1" + try: + rw = int(e.get("runway", "0")) + runway_all.append(rw) + if rw == 0: + zero_runway += 1 + except ValueError: + rw = None + try: + full_all.append(float(e.get("full", "0"))) + except ValueError: + pass + if is_hit: + hits += 1 + else: + misses += 1 + try: + miss_full.append(float(e.get("full", "0"))) + except ValueError: + pass + if rw is not None: + miss_runway.append(rw) + if e.get("overflow") == "1": + miss_overflow += 1 + try: + otf = float(e.get("otfDecodeMs", "0")) + if otf > 0: + otf_ms.append(otf) + except ValueError: + pass + + miss_rate = misses / n if n else 0.0 + print(" presented frames : %d" % n) + print(" cache HITS / MISSES : %d / %d (%.1f%% miss)" % (hits, misses, 100.0 * miss_rate)) + if full_all: + sfa = sorted(full_all) + print(" cache fullness (all) : median %.1f%% min %.1f%% max %.1f%%" % (median(sfa), sfa[0], sfa[-1])) + if runway_all: + sra = sorted(runway_all) + print( + " ahead runway (all) : median %d p05 %d frame(s) cached ahead of playhead" + % (median(sra), percentile(sra, 5.0)) + ) + print(" next frame NOT cached : %d / %d presented frames (%.1f%%)" % (zero_runway, n, 100.0 * zero_runway / n)) + + med_full_miss = 0.0 + med_runway_miss = 0.0 + if misses: + if miss_full: + smf = sorted(miss_full) + med_full_miss = median(smf) + print(" -- at cache MISSES --") + print( + " cache was full : median %.1f%% (%d/%d misses while overflowing)" + % (med_full_miss, miss_overflow, misses) + ) + if miss_runway: + smr = sorted(miss_runway) + med_runway_miss = median(smr) + print(" ahead runway : median %d max %d frame(s) cached ahead" % (med_runway_miss, smr[-1])) + if otf_ms: + som = sorted(otf_ms) + print( + " on-the-fly decode : n=%d median %.1f ms p95 %.1f ms max %.1f ms (blocks display)" + % (len(som), median(som), percentile(som, 95.0), som[-1]) + ) + + # The signature the user suspects: misses happening while the cache is + # essentially full and there is little/no runway ahead of the playhead. + if med_full_miss >= 90.0 and med_runway_miss <= 2: + print(" => CONFIRMED pattern: frames are MISSING from a nearly-full cache with an") + print(" empty ahead-runway -> the cache is full of frames that are not the ones") + print(" the player needs next. See cachestall below for why.") + + print(" cache stalls (caching gave up while overflowing): %d" % len(stalls)) + if stalls: + # Show how far the refused cache target sat from the protected frame. + sample = stalls[: min(3, len(stalls))] + for r in sample: + e = parse_extra(r["extra"]) + print( + " want frame %s (util %s) but protected cached frame %s (util %s); displayFrame %s" + % ( + e.get("cacheFrame", "?"), + e.get("cacheUtil", "?"), + e.get("freeFrame", "?"), + e.get("freeUtil", "?"), + e.get("displayFrame", "?"), + ) + ) + + return { + "count": n, + "misses": misses, + "miss_rate": miss_rate, + "miss_overflow": miss_overflow, + "med_full_at_miss": med_full_miss, + "med_runway_at_miss": med_runway_miss, + "zero_runway_frac": (zero_runway / n) if n else 0.0, + "cachestalls": len(stalls), + "otf_count": len(otf_ms), + } + + +def analyze_stall_causes(rows, fps): + """Decompose slow redraws into eval / GPU-render / 'outside' time and test + whether they coincide with concurrent EXR decode activity. + + The refresh-count histogram tells us WHETHER new frames arrive late; this + tells us WHERE the time goes on a slow redraw. For each display event we + have interval (wall time since the previous redraw), eval and render. The + residual (interval - eval - render) is 'outside' time: heartbeat/event-loop + scheduling, vsync swap wait, or the main thread being blocked/starved. If + the slow redraws overlap windows where >=3 decodes were running, the main + thread is losing the CPU (or a lock) to the reader pool even though the + frame is already cached -- i.e. oversubscription is stalling *display*, not + just decode. + """ + budget = 1000.0 / fps if fps > 0 else 0.0 + + disp = [] + for r in rows: + if r["event"] != "display": + continue + e = parse_extra(r["extra"]) + try: + interval = float(e.get("interval", "0")) + ev = float(e.get("eval", "0")) + rd = float(e.get("render", "0")) + except ValueError: + continue + try: + reqs = int(e.get("reqs", "-1")) + except ValueError: + reqs = -1 + try: + outside_gap = float(e.get("outsideGap", "-1")) + except ValueError: + outside_gap = -1.0 + try: + df = int(e.get("dframe", "0")) + except ValueError: + df = 0 + disp.append((r["t_ms"], interval, ev, rd, reqs, outside_gap, df)) + + print("=" * 72) + print("STALL ANATOMY -- where does a slow redraw spend its time?") + print("=" * 72) + if not disp or budget <= 0: + print(" No display events with interval timing recorded.") + return {"stalls": 0, "decode_overlap_frac": 0.0} + + # Decode windows [start,end] with the concurrency reported at decode start. + decodes = [] + for r in rows: + if r["event"] != "decode": + continue + e = parse_extra(r.get("extra", "")) + try: + conc = int(e.get("concurrency", "1")) + except ValueError: + conc = 1 + decodes.append((r["t_ms"] - r["dur_ms"], r["t_ms"], conc)) + decodes.sort() + dec_starts = [d[0] for d in decodes] + + # Per-render event-processing handler samples (GUI-thread Mu/Python work + # that runs between paints). Used to split the "outside render_v2" bucket + # into event-loop-handler time vs composite/swapBuffers present time. + perrender = sorted((r["t_ms"], r["dur_ms"]) for r in rows if r["event"] == "perrender") + pr_ts = [p[0] for p in perrender] + + # Optional GPU-completion probe (RV_DIAG_GLFINISH): paint events carry + # gpuFinish = glFinish() time right after render(), i.e. how long the GPU + # took to actually execute the frame's upload+shaders. If this is large on + # slow paints, the stall is GPU upload/render bound; if it is small while the + # present (gap) still stalls, the block is the compositor/present path. + gpu_all = [] + gpu_gap = [] # (gap, gpuFinish) pairs for paints where glFinish was active + for r in rows: + if r["event"] != "paint": + continue + e = parse_extra(r["extra"]) + try: + g = float(e.get("gpuFinish", "-1")) + gp = float(e.get("gap", "-1")) + except ValueError: + continue + if g >= 0: + gpu_all.append(g) + if gp >= 0: + gpu_gap.append((gp, g)) + + def perrender_in(a, b): + """Sum of per-render handler time whose events fall within [a,b].""" + import bisect + + lo = bisect.bisect_left(pr_ts, a) + hi = bisect.bisect_right(pr_ts, b) + return sum(perrender[i][1] for i in range(lo, hi)) + + def max_conc_in(a, b): + """Max decode concurrency for any decode window overlapping [a,b].""" + import bisect + + # any decode with start <= b and end >= a + hi = bisect.bisect_right(dec_starts, b) + best = 0 + # scan backwards from hi while decode start could still overlap; decode + # durations are bounded (<~0.3s) but we simply scan the candidates whose + # start < b and check end >= a. + for i in range(hi - 1, -1, -1): + s, e2, c = decodes[i] + if e2 >= a: + if c > best: + best = c + # stop once starts are far enough before 'a' that no window reaches + if s < a - 400.0: + break + return best + + slow = [d for d in disp if d[1] > budget * 1.5] + outside_all = [max(0.0, d[1] - d[2] - d[3]) for d in disp if d[1] > 0] + + # New-frame vs repeat present time. In Play-All-Frames a repeat re-shows the + # already-resident GPU texture (cheap present), while a NEW frame must upload + # a fresh texture before the swap can present it. If the present cost is paid + # almost entirely on NEW frames, the stall is the synchronous GPU texture + # upload (threaded upload OFF), not a uniform compositor/vsync problem -- + # which points the fix at async/threaded upload or prefetch. + new_gap = sorted(d[5] for d in disp if d[6] != 0 and d[5] >= 0) + rep_gap = sorted(d[5] for d in disp if d[6] == 0 and d[5] >= 0) + if new_gap and rep_gap: + stall_line = budget * 1.5 + new_stalls = sum(1 for g in new_gap if g > stall_line) + rep_stalls = sum(1 for g in rep_gap if g > stall_line) + print(" present (outsideGap) by frame kind:") + print( + " NEW frames (dframe!=0) : median %.2f ms p95 %.2f (n=%d) stalls>%.0fms: %d (%.0f%%)" + % ( + median(new_gap), + percentile(new_gap, 95.0), + len(new_gap), + stall_line, + new_stalls, + 100.0 * new_stalls / len(new_gap), + ) + ) + print( + " repeats (dframe==0) : median %.2f ms p95 %.2f (n=%d) stalls>%.0fms: %d (%.0f%%)" + % ( + median(rep_gap), + percentile(rep_gap, 95.0), + len(rep_gap), + stall_line, + rep_stalls, + 100.0 * rep_stalls / len(rep_gap), + ) + ) + total_stalls = new_stalls + rep_stalls + # The stalls live in the tail, not the median: compare where the >1.5x + # budget presents actually occur. If they are overwhelmingly NEW frames, + # the cost is specific to presenting new content (GPU texture upload of + # the new frame and/or the compositor presenting changed content), not a + # uniform per-present vsync cost (which would hit repeats too). + if total_stalls > 0 and new_stalls >= total_stalls * 0.8: + print(" -> stalls occur almost only on NEW frames (repeats present fine).") + print(" The cost is specific to presenting a NEW frame: either the") + print(" synchronous GPU texture upload (threaded upload OFF) or the") + print(" compositor presenting changed content. Test both cheaply:") + print(" * TWK_ALLOW_THREADED_UPLOAD=1 (overlaps upload with present)") + print(" * disable desktop compositor / fullscreen-unredirect") + else: + print(" -> stalls hit repeats too: uniform compositor/vsync present cost,") + print(" not new-frame texture upload.") + + if outside_all: + so = sorted(outside_all) + print(" 'outside' time per redraw (interval - eval - render):") + print(" median %.2f ms p95 %.2f ms max %.2f ms" % (median(so), percentile(so, 95.0), so[-1])) + print(" (at 60Hz vsync ~16 ms of this is the normal swap wait)") + + if not slow: + print(" No slow redraws (> 1.5x budget) -- pacing is clean.") + return {"stalls": 0, "decode_overlap_frac": 0.0} + + # Heartbeat = 120Hz (RvApplication timer), so an on-time redraw loop posts + # ~ interval/8.33ms redraw requests per actual paint. If during a stall the + # number of coalesced requests (reqs) tracks the gap, RV DID ask for the + # paint and Qt deferred it (compositor present). If reqs stays ~1, the + # heartbeat/event loop itself was starved (RV never asked). + HEARTBEAT_MS = 1000.0 / 120.0 + slow_reqs = [d[4] for d in slow if d[4] >= 0] + if slow_reqs: + exp = [max(1.0, d[1] / HEARTBEAT_MS) for d in slow if d[4] >= 0] + got = sorted(slow_reqs) + print(" heartbeat requests coalesced per stalled paint:") + print(" observed reqs/paint : median %.1f p95 %.1f" % (median(got), percentile(got, 95.0))) + print(" expected (if 120Hz) : median %.1f (gap / 8.33 ms)" % median(sorted(exp))) + if median(got) >= median(sorted(exp)) * 0.6: + print(" -> RV posted redraws on time but Qt did NOT paint them: the") + print(" stall is in the Qt6 compositor/present path (async QWidget::") + print(" update decoupled from vsync), NOT RV's heartbeat or decode.") + else: + print(" -> few requests during stalls: the 120Hz heartbeat/event loop") + print(" itself is being starved (main thread blocked) -- investigate") + print(" what blocks Session::update between paints.") + + # Three-way split of a stalled interval (needs the outsideGap field): + # eval+render : the measured display work (tiny) + # rest of render_v2 : interval - outsideGap - eval - render + # (frameChangeEvent + graph work + locks) + # outside render_v2 : outsideGap + # (paintGL rest + Qt composite + swapBuffers/vsync + # + event loop) + slow_gap = [d for d in slow if d[5] >= 0] + if slow_gap: + og = sorted(d[5] for d in slow_gap) + inside = sorted(max(0.0, d[1] - d[5]) for d in slow_gap) + rest_rv2 = sorted(max(0.0, d[1] - d[5] - d[2] - d[3]) for d in slow_gap) + print(" stalled interval split (where the ~%.0f ms goes):" % median(sorted(d[1] for d in slow_gap))) + print(" outside render_v2 : median %.2f ms (present/composite/swap + event loop)" % median(og)) + print(" inside render_v2 : median %.2f ms (eval + render + frameChangeEvent)" % median(inside)) + print( + " rest of render_v2 : median %.2f ms (frameChangeEvent/graph, excl eval+render)" % median(rest_rv2) + ) + + # Split the "outside render_v2" bucket into the per-render event-loop + # handler vs the composite/swapBuffers present path, using perrender + # events that land within each stalled between-paint window. + if perrender: + handler = [] + swap = [] + for d in slow_gap: + t, gap = d[0], d[5] + h = perrender_in(t - gap, t) + handler.append(h) + swap.append(max(0.0, gap - h)) + mh = median(sorted(handler)) + ms = median(sorted(swap)) + print(" -- outside split (via perrender events) --") + print(" event-loop handler : median %.2f ms (per-render Mu/Python on GUI thread)" % mh) + print(" composite + swap : median %.2f ms (Qt present / swapBuffers / vsync)" % ms) + if mh >= ms: + print(" -> the stall is the PER-RENDER EVENT HANDLER blocking the GUI thread") + print(" (userGenericEvent 'per-render-event-processing' -> Mu/Python).") + print(" Fix target: make that handler cheap/async, not the present path.") + else: + print(" -> the stall is the Qt COMPOSITE/SWAPBUFFERS present path blocking the") + print(" GUI thread (QOpenGLWidget composite + vsync swap). Fix target:") + print(" restore a direct synchronous present for the playback view.") + + # GPU-completion probe (only present when run with RV_DIAG_GLFINISH=1). + if gpu_all: + ga = sorted(gpu_all) + print(" -- GPU probe (RV_DIAG_GLFINISH: glFinish after render) --") + print( + " gpuFinish (GPU exec) : median %.2f ms p95 %.2f max %.2f (n=%d)" + % (median(ga), percentile(ga, 95.0), ga[-1], len(ga)) + ) + slow_gpu = sorted(g for (gp, g) in gpu_gap if (gp + g) > budget * 1.5) + if slow_gpu: + print( + " on stalled paints : gpuFinish median %.2f ms p95 %.2f" + % (median(slow_gpu), percentile(slow_gpu, 95.0)) + ) + # The decision must use the GPU time ON the stalled paints, not the + # overall distribution (most paints are fast, which hides the tail). + stall_gpu_med = median(slow_gpu) if slow_gpu else 0.0 + if stall_gpu_med > budget * 1.5: + print(" -> GPU execution ITSELF stalls (median %.1f ms on stalled paints):" % stall_gpu_med) + print(" the synchronous texture upload/render of new frames is the") + print(" bottleneck. Fix: async/threaded upload, PBO streaming, prefetch") + print(" the next frame, or reduce upload cost -- NOT the compositor.") + elif percentile(ga, 95.0) > budget * 1.5: + print(" -> GPU execution stalls on the tail: upload/render bound.") + else: + print(" -> GPU finishes fast even on stalls: the block is AFTER the GPU is") + print(" done -> the compositor/swapBuffers present path, not upload.") + elif median(og) >= median(inside): + print(" -> the stall is OUTSIDE render_v2 (present + event loop). Rebuild with the") + print(" paint/perrender instrumentation to split swap vs event-handler.") + + s_iv = sorted(d[1] for d in slow) + s_ev = sorted(d[2] for d in slow) + s_rd = sorted(d[3] for d in slow) + s_out = sorted(max(0.0, d[1] - d[2] - d[3]) for d in slow) + print(" slow redraws (> %.1f ms) : %d" % (budget * 1.5, len(slow))) + print(" interval : median %.2f p95 %.2f max %.2f ms" % (median(s_iv), percentile(s_iv, 95.0), s_iv[-1])) + print(" eval : median %.2f p95 %.2f ms" % (median(s_ev), percentile(s_ev, 95.0))) + print(" render : median %.2f p95 %.2f ms" % (median(s_rd), percentile(s_rd, 95.0))) + print( + " outside : median %.2f p95 %.2f ms <- unexplained by display work" + % (median(s_out), percentile(s_out, 95.0)) + ) + + overlap_any = 0 + overlap_hi = 0 + iv_overlap_hi = [] + iv_no_decode = [] + for d in slow: + t, iv = d[0], d[1] + mc = max_conc_in(t - iv, t) + if mc >= 1: + overlap_any += 1 + if mc >= 3: + overlap_hi += 1 + iv_overlap_hi.append(iv) + else: + iv_no_decode.append(iv) + n = len(slow) + frac_hi = overlap_hi / n if n else 0.0 + print(" decode overlap of slow redraws:") + print(" overlapped ANY decode : %d / %d (%.0f%%)" % (overlap_any, n, 100.0 * overlap_any / n)) + print(" overlapped 3+ concurrent : %d / %d (%.0f%%)" % (overlap_hi, n, 100.0 * frac_hi)) + if iv_overlap_hi and iv_no_decode: + print(" median slow-redraw interval when 3+ decodes active : %.2f ms" % median(sorted(iv_overlap_hi))) + print(" median slow-redraw interval otherwise : %.2f ms" % median(sorted(iv_no_decode))) + if frac_hi >= 0.4: + print(" -> most stalls coincide with 3+ concurrent decodes: the main display") + print(" thread is losing CPU/locks to the reader pool even though the frame") + print(" is cached. This is decode oversubscription stalling DISPLAY, not a") + print(" pacing-math (m_shift) problem.") + elif median(s_out) > budget: + print(" -> stalls are 'outside' time not tied to decode: investigate the") + print(" heartbeat/update timer and vsync swap on the main thread.") + + return { + "stalls": n, + "decode_overlap_frac": frac_hi, + "median_outside_ms": median(s_out), + } + + +def analyze_upload(rows, fps): + """Per-plane GPU texture-upload analysis (Option A). + + Each 'upload' row is one ImageRenderer::uploadPlane() call. Fields: + w,h,ch,type,pxsz,mb,pbo(0/1),update(0/1),cpuGBps + dur_ms is the CPU-side submission time (map+memcpy for PBO, or the + glTexImage2D client copy for the non-PBO fallback). The per-paint GPU + total is measured separately by RV_DIAG_GLFINISH in the 'paint' event. + + This isolates the cause of slow new-frame uploads: + * pbo usage low -> we are on the slow fallback path (a bug/gate) + * pbo=1 but cpuGBps low -> map+memcpy (CPU/mem bandwidth) is the cost + * pbo=1 and cpuGBps high -> CPU submit is fine; the cost is GPU-side DMA + (see gpuFinish); suspect format conversion + """ + ups = [r for r in rows if r["event"] == "upload"] + print("=" * 72) + print("GPU TEXTURE UPLOAD -- ImageRenderer::uploadPlane() (Option A)") + print("=" * 72) + if not ups: + print(" No upload events recorded.") + print(" (Run with RV_PLAYBACK_DIAG=1 on a build that has the uploadPlane probe.)") + return {"count": 0} + + cpu_ms = [] + gbps = [] + pbo_yes = 0 + update_yes = 0 + by_res = defaultdict(lambda: {"n": 0, "cpu": [], "gbps": [], "pbo": 0, "pbo_gbps": [], "nopbo_gbps": []}) + for r in ups: + e = parse_extra(r["extra"]) + cpu_ms.append(r["dur_ms"]) + try: + g = float(e.get("cpuGBps", "0")) + except ValueError: + g = 0.0 + gbps.append(g) + is_pbo = e.get("pbo", "0") == "1" + if is_pbo: + pbo_yes += 1 + if e.get("update", "0") == "1": + update_yes += 1 + key = "%sx%s ch%s ty%s" % (e.get("w", "?"), e.get("h", "?"), e.get("ch", "?"), e.get("type", "?")) + b = by_res[key] + b["n"] += 1 + b["cpu"].append(r["dur_ms"]) + b["gbps"].append(g) + if is_pbo: + b["pbo"] += 1 + b["pbo_gbps"].append(g) + else: + b["nopbo_gbps"].append(g) + + n = len(ups) + cpu_s = sorted(cpu_ms) + gbps_s = sorted(gbps) + pbo_frac = pbo_yes / n + + print(" upload events : %d plane upload(s)" % n) + print( + " PBO fast path used : %d / %d (%.1f%%) sub-image updates: %d" + % (pbo_yes, n, 100.0 * pbo_frac, update_yes) + ) + print( + " CPU submit time (ms) : mean %.2f median %.2f p95 %.2f max %.2f" + % (mean(cpu_ms), median(cpu_s), percentile(cpu_s, 95.0), cpu_s[-1]) + ) + print(" CPU submit throughput : median %.2f GB/s min %.2f GB/s" % (median(gbps_s), gbps_s[0])) + print("") + print(" by resolution/format (frame size drives upload cost):") + for key, b in sorted(by_res.items(), key=lambda kv: -kv[1]["n"]): + cs = sorted(b["cpu"]) + gs = sorted(b["gbps"]) + print( + " %-24s n=%-5d cpu med %.2f ms / p95 %.2f ms cpuGBps med %.2f pbo %d%%" + % (key, b["n"], median(cs), percentile(cs, 95.0), median(gs), int(round(100.0 * b["pbo"] / b["n"]))) + ) + # Split throughput PBO vs non-PBO: a plain memcpy into the PBO does + # not depend on RGB-vs-RGBA, so if PBO throughput is uniform across + # formats the CPU-submit cost is purely the non-PBO fallback; the + # RGB16F penalty then lives on the GPU side (gpuFinish). + pg = sorted(b["pbo_gbps"]) + ng = sorted(b["nopbo_gbps"]) + if pg and ng: + print( + " PBO med %.2f GB/s (n=%d) non-PBO med %.2f GB/s (n=%d)" + % (median(pg), len(pg), median(ng), len(ng)) + ) + + print("") + if pbo_frac < 0.9: + print(" -> VERDICT: %.0f%% of uploads fall back to the NON-PBO path" % (100.0 * (1.0 - pbo_frac))) + print(" (glTexImage2D from client memory). This is the slow, synchronous") + print(" upload path. Check the usePBO gate in uploadPlane():") + print(" - fb->scanlinePixelPadding()==0 and contiguous scanlines") + print( + " - d->pPBOToGPU created (m_uploadedTextures.size() < RV_RENDERING_MAX_CONCURRENT_PBOS, default 10)" + ) + print(" - PBO size >= totalBytes") + print(" Fixing the gate should restore DMA-speed uploads (Option B).") + elif median(gbps_s) < 3.0: + print(" -> VERDICT: PBO path IS used but CPU submit throughput is low") + print(" (%.2f GB/s median). The map+FastMemcpy_MP into the PBO is the" % median(gbps_s)) + print(" cost -> CPU/memory-bandwidth bound, not GPU. Look at memcpy") + print(" thread count / NUMA, or upload directly from the decoded FB.") + else: + print(" -> VERDICT: CPU submit is fast (%.2f GB/s median) and PBO is used." % median(gbps_s)) + print(" The remaining cost is GPU-side (see gpuFinish in the 'paint'") + print(" stall anatomy). Suspect a driver pixel-format conversion on") + print(" glTexSubImage2D: verify internalFormat vs (format,type) is a") + print(" natively supported combo for GL_TEXTURE_RECTANGLE half-float.") + + return {"count": n, "pbo_frac": pbo_frac, "cpu_gbps_med": median(gbps_s)} + + +def verdict(dec, aud, buf, slow, disp, cache, fps): + print("=" * 72) + print("VERDICT") + print("=" * 72) + + frame_reasons = [] + if buf["buffering"] > 0: + frame_reasons.append("%d buffering pause(s) (%.0f ms total)" % (buf["buffering"], buf["pause_total_ms"])) + if buf["skips"] > 0: + frame_reasons.append("%d realtime skip event(s), %d frame(s) dropped" % (buf["skips"], buf["skipped_frames"])) + if fps > 0 and dec["count"] > 0 and dec["active_fps"] < fps * 0.98: + frame_reasons.append( + "realized decode rate %.1f fps < target %.1f fps (%.1f thread(s) working at once)" + % (dec["active_fps"], fps, dec["concurrency"]) + ) + if dec["count"] > 0 and dec["over_budget_frac"] > 0.5: + frame_reasons.append("%.0f%% of decodes exceed the frame budget" % (100.0 * dec["over_budget_frac"])) + if dec["count"] > 0 and dec["top_thread_share"] >= 0.6: + frame_reasons.append( + "decode serialized onto one thread (%.0f%% of decodes) -- slow-media mode" + % (100.0 * dec["top_thread_share"]) + ) + if slow["any"] and slow["slow_fraction"] >= 0.5: + frame_reasons.append( + "session in slow-media mode ~%.0f%% of the run (%d slow source(s))" + % (100.0 * slow["slow_fraction"], slow["slow_sources"]) + ) + + display_reasons = [] + if disp["count"] > 0 and disp["render_bound"]: + display_reasons.append( + "display loop capped at %.1f fps < target %.1f fps; GPU render+upload " + "mean %.1f ms vs evaluate %.1f ms (frames cached but slow to show)" + % (disp["achieved_fps"], fps, disp["mean_render_ms"], disp["mean_eval_ms"]) + ) + if disp["count"] > 0 and disp.get("cadence_stutter"): + msg = ( + "playback rate %.1f fps < target %.1f fps while per-frame display work is only " + "%.2f ms -- new frames are arriving late (decode/scheduling), not display/render bound" + % (disp.get("playback_fps", 0.0), fps, disp.get("mean_render_ms", 0.0) + disp.get("mean_eval_ms", 0.0)) + ) + if disp.get("stalls"): + msg += " (%d visible stall(s) froze the frame > 1.5x budget)" % disp["stalls"] + display_reasons.append(msg) + + audio_reasons = [] + if aud["steady"] > 0: + audio_reasons.append("%d steady-state audio starvation event(s)" % aud["steady"]) + if aud["underruns"] > 0: + audio_reasons.append("%d ALSA underrun(s)" % aud["underruns"]) + + # Cache-content evidence: distinguishes "frame not in cache" (the on-the-fly + # decode / cache-retention problem) from a pure pacing problem. + cache_reasons = [] + if cache.get("count", 0) > 0: + if cache["miss_rate"] > 0.01: + msg = "%.1f%% of presented frames were cache MISSES (needed frame not resident)" % ( + 100.0 * cache["miss_rate"] + ) + if cache.get("med_full_at_miss", 0.0) >= 80.0: + msg += "; at those misses the cache was ~%.0f%% full with median runway %d frame(s)" % ( + cache["med_full_at_miss"], + cache.get("med_runway_at_miss", 0), + ) + msg += " -> cache is full of the wrong frames (retention/eviction), not a pacing issue" + if cache.get("otf_count", 0) > 0: + msg += "; %d on-the-fly decode(s) blocked the display thread" % cache["otf_count"] + cache_reasons.append(msg) + if cache.get("cachestalls", 0) > 0: + cache_reasons.append( + "%d cachestall event(s): caching refused to evict a protected frame to " + "cache the frame the player needed next" % cache["cachestalls"] + ) + else: + cache_reasons.append( + "cache MISS rate ~0% (needed frames were resident) -> drops are NOT a cache-" + "content problem; investigate pacing (render_v2 targetFrame/shift)" + ) + + frame_bound = bool(frame_reasons) + audio_bound = bool(audio_reasons) + display_bound = bool(display_reasons) + + # A confirmed cache-content problem: real misses while the cache is full. + cache_miss_confirmed = ( + cache.get("count", 0) > 0 and cache["miss_rate"] > 0.01 and cache.get("med_full_at_miss", 0.0) >= 80.0 + ) + + if cache_miss_confirmed: + print(" Cause: CACHE CONTENT -- the frame the player needs is often NOT in the cache") + print(" even though the cache is nearly full (on-the-fly decode stalls the") + print(" display). This is a cache retention/look-ahead problem, not raw decode.") + elif display_bound and not frame_bound and not audio_bound: + print(" Cause: DISPLAY/RENDER path is the bottleneck -- frames are cached but the") + print(" on-screen loop (GPU upload/render) can't hit the target fps.") + elif frame_bound and audio_bound: + print(" Cause: BOTH frame decode AND audio are contributing to the stutter.") + elif frame_bound: + print(" Cause: FRAME (image/EXR) DECODING is too slow -- this is the bottleneck.") + elif audio_bound: + print(" Cause: AUDIO decoding/starvation is the bottleneck.") + elif display_bound: + print(" Cause: DISPLAY/RENDER path is a bottleneck (in addition to the above).") + else: + print(" Cause: no clear stutter signature in this capture.") + print(" (Try a longer capture during the stutter, confirm RV_PLAYBACK_DIAG=1,") + print(" and pass the real playback --fps.)") + + if frame_reasons: + print(" Frame-side evidence:") + for r in frame_reasons: + print(" - " + r) + if display_reasons: + print(" Display-side evidence:") + for r in display_reasons: + print(" - " + r) + if audio_reasons: + print(" Audio-side evidence:") + for r in audio_reasons: + print(" - " + r) + if cache_reasons: + print(" Cache-side evidence:") + for r in cache_reasons: + print(" - " + r) + + +def main(argv): + ap = argparse.ArgumentParser(description="Attribute OpenRV playback stutter to frame vs audio decode.") + ap.add_argument( + "log", + nargs="?", + default="rv-playback-diag.log", + help="path to the RV_PLAYBACK_DIAG log (default: rv-playback-diag.log)", + ) + ap.add_argument("--fps", type=float, default=24.0, help="target playback fps of the session (default: 24)") + ap.add_argument("--rvprof", default=None, help="optional .rvprof file from -debug profile") + args = ap.parse_args(argv) + + if not os.path.isfile(args.log): + # Do not interpolate untrusted paths into shells or file APIs beyond this + # read; argparse value is used only as a direct path to open() for reading. + sys.stderr.write("ERROR: log file not found: %s\n" % args.log) + return 2 + + rows = read_diag_log(args.log) + if not rows: + sys.stderr.write("ERROR: no diagnostic rows parsed from %s\n" % args.log) + return 2 + + t_min = min(r["t_ms"] for r in rows) + t_max = max(r["t_ms"] for r in rows) + span_s = max(0.0, (t_max - t_min) / 1000.0) + + print("OpenRV playback diagnostics: %s" % args.log) + print(" rows=%d span=%.1f s target_fps=%.3f" % (len(rows), span_s, args.fps)) + print("") + + decode_rows = [r for r in rows if r["event"] == "decode"] + dec = analyze_decode(decode_rows, args.fps, span_s) + print("") + aud = analyze_audio(rows, span_s) + print("") + buf = analyze_buffering(rows, span_s) + print("") + disp = analyze_display(rows, args.fps, span_s) + print("") + cache = analyze_cache(rows, args.fps, span_s) + print("") + analyze_stall_causes(rows, args.fps) + print("") + analyze_upload(rows, args.fps) + print("") + slow = analyze_slow_media(rows, span_s) + if slow["any"]: + print("") + if args.rvprof: + parse_rvprof(args.rvprof) + print("") + verdict(dec, aud, buf, slow, disp, cache, args.fps) + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv[1:])) From e3e824f1539d1557e94623504988fedfba4e3558 Mon Sep 17 00:00:00 2001 From: Bernard Laberge Date: Thu, 16 Jul 2026 11:30:57 -0400 Subject: [PATCH 2/2] fix: cap Automatic OpenEXR decode threads on high-core systems When the OpenEXR "Automatic Threads" preference is on (exrcpus == 0), RV set the shared OpenEXR global thread pool to numCPUs-1 (e.g. 63 on a 64-core box). Because every EXR decode draws from that single global pool, on high-core machines the decode threads starve RV's playback/UI, audio and caching threads and cause dropped frames -- worst with DWA/DWAB-compressed EXRs. Add Rv::automaticExrThreadCount() and use it wherever the Automatic value is applied: - threads = (logicalCores > 16) ? logicalCores/2 : (logicalCores > 1 ? logicalCores-1 : 1) - On hyper-threaded systems logicalCores/2 is roughly the physical core count, leaving headroom for the main/UI, audio and caching threads. - Overridable at runtime via the RV_EXR_AUTO_MAX_THREADS environment variable. - Behavior on <=16-core machines is unchanged. Call sites updated: src/bin/apps/rv/main.cpp, src/bin/nsapps/RV/main.cpp, and RvPreferences::exrNumThreadsFinished()/exrAutoThreads(). Manual thread counts (exrcpus > 0) and rvio (batch, no interactive UI to starve) are unchanged. Docs: document the Automatic heuristic and RV_EXR_AUTO_MAX_THREADS in the RV user manual (EXR decoding threads section) and refresh the -exrcpus entries in the RV and RVIO command-line reference tables. Co-authored-by: Cursor --- .../rv-user-manual-chapter-fourteen.md | 9 ++++++- .../rv-user-manual-chapter-sixteen.md | 2 +- .../rv-user-manual-chapter-three.md | 2 +- src/bin/apps/rv/main.cpp | 2 +- src/bin/nsapps/RV/main.cpp | 2 +- src/lib/app/RvApp/Options.cpp | 27 +++++++++++++++++++ src/lib/app/RvApp/RvApp/Options.h | 11 ++++++++ src/lib/app/RvCommon/RvPreferences.cpp | 5 ++-- 8 files changed, 53 insertions(+), 7 deletions(-) diff --git a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-fourteen.md b/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-fourteen.md index d5e74c759..7f6991c04 100644 --- a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-fourteen.md +++ b/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 diff --git a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-sixteen.md b/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-sixteen.md index 51cfdc12e..1ae67a836 100644 --- a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-sixteen.md +++ b/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) | diff --git a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-three.md b/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-three.md index fd63508b9..595c2098b 100644 --- a/docs/rv-manuals/rv-user-manual/rv-user-manual-chapter-three.md +++ b/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) | diff --git a/src/bin/apps/rv/main.cpp b/src/bin/apps/rv/main.cpp index 32b10b467..6526959ae 100644 --- a/src/bin/apps/rv/main.cpp +++ b/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()); } // diff --git a/src/bin/nsapps/RV/main.cpp b/src/bin/nsapps/RV/main.cpp index 9ac24f5b9..d2a0f0b9c 100644 --- a/src/bin/nsapps/RV/main.cpp +++ b/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()); } // diff --git a/src/lib/app/RvApp/Options.cpp b/src/lib/app/RvApp/Options.cpp index 631f7bfff..a50898235 100644 --- a/src/lib/app/RvApp/Options.cpp +++ b/src/lib/app/RvApp/Options.cpp @@ -39,6 +39,7 @@ #include #include #include +#include #include #include #include @@ -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(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; diff --git a/src/lib/app/RvApp/RvApp/Options.h b/src/lib/app/RvApp/RvApp/Options.h index 22b48fce7..51231c5b2 100644 --- a/src/lib/app/RvApp/RvApp/Options.h +++ b/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 // diff --git a/src/lib/app/RvCommon/RvPreferences.cpp b/src/lib/app/RvCommon/RvPreferences.cpp index a07c9f873..e28c058b1 100644 --- a/src/lib/app/RvCommon/RvPreferences.cpp +++ b/src/lib/app/RvCommon/RvPreferences.cpp @@ -38,6 +38,7 @@ #include #include #include +#include #include #include #include @@ -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 {