Attempting to find small latency spikes at segment boundaries

[jackjansen]

I've managed to repeat the issue that we have small spikes at segment boundaries using the Python testlatency.py script.

Currently on the 95-test-tiling-multiquality branch.

We experience a 100ms latency spike at every segment boundary. The spike is always almost exactly 100ms, it is not dependent on the fragment size (see below). It is not dependent on quality switching, it is not dependent on whether we use multiple tiles or qualities.

[jackjansen]

On the #95 branch I'm doing untiled 2-quality, with no quality switching:

python tests/testlatency/testlatency.py --npoints 100000 --fps 10 --seg_dur 4000 --duration 20 --octree_bits 6 --octree_bits 8 --synchronizer --print-latencies

I get this graph when pasting the latencies into `tests/testlatency/plot_numbers.py:

The x-axis is fragment index, and you can see the spikes are about 40 apart, which is the segment size for fps=10 and seg_dur=4000.

[jackjansen]

First thing to try: does this depend on sending multiple qualities. Answer is: no.

Single quality command:

python tests/testlatency/testlatency.py --npoints 100000 --fps 10 --seg_dur 4000 --duration 20 --octree_bits 6 --synchronizer --print-latencies

The plot is very similar:

(but different enough that I'm pretty sure I haven't uploaded the same image:-)

[jackjansen]

Next test: the 100ms peaks are about one frame time. Let's see if this changes if we change the FPS.

5 FPS command:

python tests/testlatency/testlatency.py --npoints 100000 --fps 5 --seg_dur 4000 --duration 20 --octree_bits 6 --synchronizer --print-latencies

Spikes are still 100ms.

Let's try 20 FPS:

python tests/testlatency/testlatency.py --npoints 100000 --fps 20 --seg_dur 4000 --duration 20 --octree_bits 6 --synchronizer --print-latencies

Spikes are still 100ms. So the magic number 100ms comes from somewhere else.

[jackjansen]

Next test to see whether there is indeed a relationship with the segment boundaries.

Try with seg_dur=2000:

python tests/testlatency/testlatency.py --npoints 100000 --fps 20 --seg_dur 2000 --duration 20 --octree_bits 6 --synchronizer --print-latencies

And with seg_dur=8000:

python tests/testlatency/testlatency.py --npoints 100000 --fps 20 --seg_dur 8000 --duration 20 --octree_bits 6 --synchronizer --print-latencies

It seems pretty clear that the spike interval is the segment duration.

[rbouqueau]

I see the spikes on the graph but I didn't see it while using the C API. Did we identify where the spikes occur more precisely? What's different in our setup? Mine is pretty optimal (executing locally so no network throttling etc).

[jackjansen]

Wild idea (triggered by the 100ms): we should check how lldash_relay implements the "wait for segment that doesn't exist yet".

[jackjansen]

Another wild idea: we should see if we can make the C API and the Python API produce the same set of packets.

Then see if the problem goes away when using the Python API.

Converting the C test to Python should be relatively straightforward: cwipc.net.sink_lldpkg and cwipc.net.source_lldplay can be used without bothering with point clouds, just using the Python->Native wrappers. You can do something like

dll = cwipc.net.sink_lldpkg._lldpkg_dll()
handle = dll.lldpkg_create(mpdname, ...)

I have a preference if you @rbouqueau write the test, because I'm a bit worried that if I do it I somehow structure it the same way I did the current Python code and the C# code, so we get into the same loop hole again.

Our maybe we should both do it and see whether it makes a difference?

Where's your C test code?

[rbouqueau]

https://github.com/MotionSpell/lldash-playout/blob/4cbcf36d623e744d25baa1d29ddab737334db464/src/loader.cpp and https://github.com/MotionSpell/lldash-playout/blob/4cbcf36d623e744d25baa1d29ddab737334db464/src/example.cpp

[rbouqueau]

When I tried to simplify testlatency.py, I tried to execute it and got the following error: OSError: dlopen(/opt/homebrew/lib/libcwipc_util.dylib, 0x0006): Symbol not found: ___kmpc_dispatch_deinit. Any idea?

((.venv) ) rbouqueau@didouce testlatency % python3 testlatency.py 
lldash-relay: t=2025-11-20T14:12:28.201 event=server_start port=9000 version=0.99.7 long_poll=true long_poll_timeout_ms=2000
lldash-relay: t=2025-11-20T14:12:28.201 Server listening on: 9000
Exception in thread testlatency.SenderThread:
Traceback (most recent call last):
  File "/opt/homebrew/Cellar/python@3.12/3.12.12/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/Users/rbouqueau/works/CWI/lldash/tests/testlatency/testlatency_sender.py", line 81, in run
    self.init()
  File "/Users/rbouqueau/works/CWI/lldash/tests/testlatency/testlatency_sender.py", line 40, in init
    self.source = cwipc.cwipc_synthetic(self.args.fps, npoints)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/rbouqueau/works/CWI/lldash/.venv/lib/python3.12/site-packages/cwipc/util.py", line 1079, in cwipc_synthetic
    rv = cwipc_util_dll_load().cwipc_synthetic(fps, npoints, ctypes.byref(errorString), CWIPC_API_VERSION)
         ^^^^^^^^^^^^^^^^^^^^^
  File "/Users/rbouqueau/works/CWI/lldash/.venv/lib/python3.12/site-packages/cwipc/util.py", line 341, in cwipc_util_dll_load
    _cwipc_util_dll_reference = ctypes.CDLL(libname)
                                ^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/python@3.12/3.12.12/Frameworks/Python.framework/Versions/3.12/lib/python3.12/ctypes/__init__.py", line 379, in __init__
    self._handle = _dlopen(self._name, mode)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^
OSError: dlopen(/opt/homebrew/lib/libcwipc_util.dylib, 0x0006): Symbol not found: ___kmpc_dispatch_deinit
  Referenced from: <0B4EDF3A-F835-3489-8F9A-4C156D8A5C6C> /opt/homebrew/Cellar/pcl/1.15.1_2/lib/libpcl_features.1.15.1.dylib
  Expected in:     <F059AD51-57EA-34D3-AF72-303BEEA39915> /Users/rbouqueau/works/CWI/lldash/.venv/lib/python3.12/site-packages/open3d/libomp.dylib
lldash-relay: t=2025-11-20T14:12:30.268 event=request_received method=GET url=/lldash_testlatency.mpd version=HTTP/1.1
lldash-relay: t=2025-11-20T14:12:32.335 event=error_reply method=GET url=/lldash_testlatency.mpd status=404 reason=not_found
lldash-relay: t=2025-11-20T14:12:32.335 event=connection_closed reason=client_closed
lldash_play: asynchronous error: [lldplay::cwipc_lldplay] [lldplay_play] exception caught: can't get mpd


Exception in thread testlatency.ReceiverThread:
netdecoder: source.get returned no data
Traceback (most recent call last):
  File "/opt/homebrew/Cellar/python@3.12/3.12.12/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/Users/rbouqueau/works/CWI/lldash/tests/testlatency/testlatency_receiver.py", line 67, in run
    self.init()
  File "/Users/rbouqueau/works/CWI/lldash/tests/testlatency/testlatency_receiver.py", line 35, in init
    self.decoder.start()
  File "/Users/rbouqueau/works/CWI/lldash/.venv/lib/python3.12/site-packages/cwipc/net/source_decoder.py", line 48, in start
    self.source.start()
  File "/Users/rbouqueau/works/CWI/lldash/.venv/lib/python3.12/site-packages/cwipc/net/source_lldplay.py", line 213, in start
    raise LLDashPlayoutError("lldash_play: lldplay_play returned false")
cwipc.net.source_lldplay.LLDashPlayoutError: lldash_play: lldplay_play returned false
testlatency: Sender thread exited with exit status code -1
testlatency: Receiver thread exited with exit status code -1
testlatency: One or more threads exited with an error.
testlatency: results are probably bogus.
testlatency: count_total=0, count_lost_initial=0, count_lost_running=0, latency_ignored_count=0, latency_min=0.000, latency_max=0.000, latency_avg=0.000, latency_stddev=0.000
testlatency: Latency test failed.
((.venv) ) rbouqueau@didouce testlatency %