release_on_idle cache flush starves the CAF scheduler and stalls every embedded-Python plugin

[jhery-rdo]

release_on_idle cache flush starves the CAF scheduler and stalls every embedded-Python plugin

Summary

Enabling the Video Cache Idle Clear preference
(/core/image_cache/release_on_idle) makes every embedded-Python plugin
progressively unresponsive over a session, while the native UI stays perfectly
fluid. Setting the preference back to 0 fixes it completely, as does
restarting the app.

The mechanism is that a full cache flush triggers a reload storm of scheduled
CAF reader actors, which saturates the shared scheduler pool — and
EventToPythonThreadLockerActor, the single actor that delivers every
attribute_changed into Python, is a plain scheduled actor drawing from that
same pool. When the pool is saturated its mailbox is simply not serviced.

Symptom

With a suite of Python plugins loaded, clicking a control in a plugin's QML
panel runs the JS handler immediately, but the corresponding Python
attribute_changed callback arrives seconds to minutes later. The delay grows
through the session. Playback, scrubbing and all native UI remain responsive
throughout. No TimeoutError is raised anywhere — Python is never the
bottleneck, it is simply not being scheduled.

Measurements

Our plugins stamp Date.now() into the action string at the moment of the
click, which gives an exact click-to-Python latency when compared against the
log timestamp of the handler. From one session (identifiers removed):

#	click → Python attribute_changed
1	0.00 s
2	4.3 s
3	18.0 s
4	19.8 s
5	49.5 s
6	53.5 s
7	56.3 s
8	67.1 s
9	83.9 s

Every backend (HTTP) call logged in the same window completed in 0.2–1.5 s, so
the latency is entirely in the C++ → Python delivery path. Delivery gaps ran
consistently at ~2× the click gaps, i.e. lag accumulating at roughly 1 s per
second of wall clock.

Root cause

All references against main as of this writing.

1. The idle check re-arms every minute regardless of the configured
   threshold, and the flush is a full clear, not an LRU trim —
   src/media_cache/src/media_cache_actor.cpp:

   // ctor: threshold in minutes
   reset_idle_ = std::chrono::minutes(
       preference_value<size_t>(j, "/core/image_cache/release_on_idle"));
   
   // unconditional 1-minute self-ping
   anon_mail(clear_atom_v, true).delay(std::chrono::minutes(1)).send(this, weak_ref);
   
   [=](clear_atom, const bool idle_check) {
       if (reset_idle_.count() and not cache_.empty() and
           utility::clock::now() - last_activity_ > reset_idle_) {
           anon_mail(clear_atom_v).send(this);
       }
       anon_mail(clear_atom_v, true).delay(std::chrono::minutes(1)).send(this, weak_ref);
   },
   [=](clear_atom) -> bool {
       cache_.clear();   // full flush
       anon_mail(unpreserve_atom_v, static_cast<size_t>(0)).send(trim);
       return true;
   },

   The flush is immediately followed by malloc_trim(64) on a TrimActor,
   also scheduled.

2. Refilling that cache makes a large number of scheduled reader actors
   runnable at once. CachingMediaReaderActor spawns
   read_threads_per_source (default 8) precache workers plus an urgent
   worker plus an audio worker per open source, and GlobalMediaReaderActor
   keeps up to max_source_count (default 16) sources open — on the order
   of 100+ reader actors. EXR takes this path specifically, since
   OpenEXRMediaReader::prefer_sequential_access() returns false.

3. The decode is synchronous inside the reader actor's message handler —
   include/xstudio/media_reader/media_reader.hpp:

   [=](get_image_atom, const media::AVFrameID &mptr) -> result<ImageBufPtr> {
       ...
       mb = media_reader_.image(mptr);   // blocking read + decompress, inline
       ...
   }

   MediaReaderActor<T> is a caf::event_based_actor, so this occupies a
   shared scheduler worker for the whole read. On a network filesystem that can
   be seconds per frame.

4. Everything above shares one pool with the Python bridge.
   src/global/src/xstudio_actor_system.cpp configures
   --caf.scheduler.max-threads=128 with --caf.scheduler.policy=sharing.
   There is no caf::detached anywhere in src/media_reader,
   src/media_cache, src/plugin_manager or src/python_module.

5. EventToPythonThreadLockerActor is a scheduled singleton on that same
   pool — src/python_module/src/py_context.cpp:

   if (!message_callback_handler_actor_) {
       message_callback_handler_actor_ =
           self_->spawn<EventToPythonThreadLockerActor>(this);
   }

   It is confirmed to be the attribute_changed delivery path: the Python side
   registers through ModuleBase.setup_message_handler() →
   connection.link.add_message_callback(...) (api/module.py), which is the
   binding for py_add_message_callback, the function that spawns and uses this
   actor. So every plugin's attribute callbacks funnel through this one
   actor's mailbox.

The native UI is unaffected because it does not route through this bridge
actor — which is exactly why this presents as "Python plugins are broken"
rather than "the app is slow".

Caveat on the growth curve

The chain above is read directly from source. The specific monotonic growth
of the latency is an inference: the idle check re-arms every minute regardless
of threshold, so with a small non-zero value a flush + reload storm can repeat
roughly every minute, and if one storm has not drained before the next fires,
contention compounds. We have not instrumented that directly. Confirming it
would want scripts/debug/hung_actors.py on a live session.

Workaround

Set Video Cache Idle Clear to 0. Note the default is 0, so this only
affects users who have deliberately enabled it.

Suggested fixes

In rough order of value:

1. Spawn EventToPythonThreadLockerActor with caf::detached. It exists
   solely to acquire the GIL and call into Python; blocking a shared scheduler
   worker while it waits on the GIL is exactly what a detached actor is for.
   This alone would decouple Python event delivery from scheduler pressure of
   any origin, not just this one.
2. Do not re-arm the idle check when reset_idle_ is zero. Currently the
   1-minute self-ping runs forever even when the feature is disabled. Minor,
   but it is pure overhead for the default configuration.
3. Consider making the flush incremental (or yielding between buffer
   destructions) rather than one synchronous cache_.clear() of up to
   max_count (default 1,000,000) entries / max_size (default 4096 MB).
4. Consider a global cap on in-flight precache reads. Backpressure today is
   per-playhead (max_num_inflight_requests_), so open panels/playheads add
   allowances additively.

Related, and arguably the same class of problem: the pybind11 bindings in
src/python_module/src/py_link.cpp have no
py::call_guard<py::gil_scoped_release>(), so a blocking mailbox call holds
the GIL for its whole duration; and py_request uses caf::infinite
(py_context.cpp), so a Python-side timeout never cancels the request. Those
compound anything that makes the mailbox slow. Happy to split those out if
preferred.

Secondary (trivial, same file)

share/preference/core_cache.json — the audio cache's release_on_idle
entry has the image cache's path:

"path": "/core/image_cache/release_on_idle"

It should be /core/audio_cache/release_on_idle. It also has no category or
display_name, so it is presumably not surfaced in the preferences UI at all,
meaning the "Video Cache Idle Clear" control only ever affects the image cache.
The C++ reads the correct /core/audio_cache/... path, so this is a
metadata/UI inconsistency rather than a functional bug. Happy to file
separately if you would rather keep this issue focused.

Environment

• xStudio 1.3.0
• Linux (Rocky 8)
• ~16 embedded-Python plugins loaded via XSTUDIO_PYTHON_PLUGIN_PATH
• Media: EXR sequences and QuickTime on a network filesystem

Related

• Embedded Python interpreter connects over TCP and is permanently disconnected by system sleep #325 — embedded Python interpreter connects over TCP and is disconnected by sleep
• Connection.response() raises TimeoutError when the response has already arrived #331 / (fix): Return a response that arrived instead of reporting a timeout #330 — Connection.response() raises TimeoutError when the response has already arrived

[tedwaine]

Hi @jhery-rdo

I've been unable to reproduce this problem - I forced the cache clear to be 10 seconds and viewed EXR sources. Then played back so as to refill the cache many times over and I still don't experience a slow-down in python plugins. There must be something else going on.

Are any/many of your plugins using the 'subscribe_to_playhead_events' method?

Am I right in saying that the above analysis was done by a coding agent? The mechanism it describes for the hobbling of the Python callback actor seems completely incorrect, unfortunately!