RPI ola_recorder, playback is not consistent to time!

[magdesign]

Having a Rpi 3B+ with the full OLA install.
I can record and playback DMX /ArtNet sequences.

But we figured out that the timing is not constant, the playback speed varies a lot.
We tried to optimize some settings on the RPI, enable Turbo mode, disable other services to free up resources, with no luck.
Tried with USB-DMX dongle and just Art-Net over the integrated RJ45.

Anyone else having the same problems ? Any tricks to get consistent playback speeds ?
Any help very very appreciated , will even donate for fixes!

[MagnusHerrlin]

Hi

We had a discussion about this in Google groups in 2017
https://groups.google.com/g/open-lighting/c/H53-bSavPJc/m/8wPmKKKNBAAJ
I came up with a small program to get it "working" by adding/removing milliseconds to the recorded file
and to trim the start time of the recording,
It made it better but didnt really solve the problem.
I still don't understand why this is happening and
if someone can explain it to me then I would be very happy.

[magdesign]

@MagnusHerrlin: thanks for your response! The manual add/remove milliseconds solution is a bit confusing, imagine I have recorded 4 universes and want to fit the timing with this shifting solution... this would take hours :(

@DragoonBoots: did your latest commits address the timing issues as well ?

• Is there any other solution to this or even another opensource art-net recorder/player to use on RPI?

• Would it make sense to split the recording to 20 second files and play them after each other?

• Could we somehow build a master clock (time send protocol) to control the playback speed?

• Any other workarounds?

[magdesign]

@MagnusHerrlin: We now test what happens if we playback recorded files shorter than 20 seconds, if this somehow is more precise, we would need to split every record track into pieces. Currently waiting for feedback from Greg, who is doing the tests on the field :-)

[danielskeenan]

Hmmm. The actual playback timing is controlled from inside the OLA daemon; the only thing I can imagine the PR affecting is each piece of the show file taking a few more CPU cycles (because of the added logic around custom timing). Let me dig up my RPi and see if I can reproduce.

[MagnusHerrlin]

Hi

From what I can recall the lights got out of sync after about 3 minutes.
I only recorded one universe, maybe the syncproblem gets even worse when you record/playback more universes
But I dont understand why you think it would take hours, normally I only have to run this one or two times to get it in sync.
But I agree my solution is not great it is more of last a desperate hack to get it to "work",
at least for the length of recordings we did back in 2017.
And I totally agree that it would be much nicer to have the recording/playback sync with some master clock
perhaps MIDI clock or SMPTE.
How does ola_timecode work?
can that be included somehow into ola_recorder?

Thanks
/Magnus

[danielskeenan]

I just did some tests comparing performance on my Raspberry Pi 3B and my desktop PC. The setup for these tests was to run a 5 minute show file that changes address 1/1 between 255 and 0 every 1000ms. The output from olad was captured and logged in sACNView as this provides a timestamp for each frame received. I then did some math with the timestamps to find the average time between value changes. Here's the results (also comparing ola_recorder revisions):

Platform	Average diff (seconds)
Linux x64 (new)	1.000444
Linux x64 (old)	1.000653
RPi 3b (new)	1.000737
RPi 3b (old)	1.000693

On both platforms, the time between value changes (i.e. when 255 becomes 0) is veeeeeery slightly off from 1 second, so I could see how the extra time could compound enough to be noticeable over several hours, but not over several minutes.

With these error rates (gaining 0.5 milliseconds over 5 minutes) I'm inclined to think this may not be fixable if this is a similar scale to the error's your seeing. The program doesn't (and, to my knowledge, can't) run in real time. The gained time is likely from processing each line in the file (i.e. time between frames = delay time + processing time), but that can't reliably be compensated for.

Having said that, if your errors are at a much greater scale, it may be a platform issue. I ran the tests with Raspbian lite downloaded this morning, so didn't have any GUI or extras running. I also have my RPi in a fan case - I can't imagine ola would place such a heavy load on the CPU that it would start thermal throttling, but it's a possibility.

Re ola_timecode (more experienced contributors - please correct me if this is wrong!), it doesn't appear to interact directly with ola and only exists to forward timecode data to an ArtNet output.

[MagnusHerrlin]

With these error rates (gaining 0.5 milliseconds over 5 minutes) I'm inclined to think this may not be fixable if this is a similar scale to the error's your seeing. The program doesn't (and, to my knowledge, can't) run in real time. The gained time is likely from processing each line in the file (i.e. time between frames = delay time + processing time), but that can't reliably be compensated for.

In 2017 I was getting more error drift than that (but that was on Jessie perhaps it has changed on Buster)
I made a showfile turning a channel on for 500ms and off for 500ms (blue trace) every second
and played a beep (red trace) every second

And it took about 1,5 seconds to get 500ms off.

So how does ola_recorder really work?

Is it like I think?

1 open the file check that first line is OLA Show
2 read universe number and all recorded channels comma separated like 0 0,0,0,0....etc well how long does this take?
3 read time in milliseconds to wait
4 what happens here? I guess the file is still open?

Does it give control to the system that sets the ola_recorder process in some sort of wait state?
and when the wait time has passed sets it back to active state that makes it jump to step 2.

If it takes too long to read a line of dmxdata and convert it from decimal to a array of unsigned 8bit bytes
why not read the whole file or a big chunk of it into a bigger buffer and playback it from there?

Then I guess it would be better to have the data in ram so you can manipulate it faster
It would be nice if the program could take input while playing to start/stop/rec/pause/rev/ff like a audio/video player.

But can the file read speed really be the case?
I mean how does a audio or video player program work? most certainly they must be reading data at a much higher rate?

The ola_recorder sure have some problems but also a lot of potential.

But what if i would like to change the speed while playing back the file?
or add some kind of master to some or all the channels?
or play it backwards?
or playback several files at once?
or only change some of the channels but leave the rest to whatever value they have?

This last question i think have a answer to.
Currently when ola_recorder reads a line that looks like this
0 255,,255 sets universe 0 channel 1 and 3 to 255 but treats the missing number as between the commas as 0
setting channel 2 to zero, Well I think it should not it should not change channel two at all.
so if you have a line like this
0 ,,255,255 in a future version of ola_recorder would set universe 0 channel 2 and 3 to full but leave channel
to whatever value it has.
This would make it possible to mute certain channels from the recording.

Say you have a string of rgb leds, dimmers, moving heads or whatever on one universe
and you only want to record/change some channels or groups of channels, for example change every third led to red
or change 4 moving heads to blue
well you can't do that with ola_recorder as it is now.

/Magnus

[peternewman]

There's a tiny chance #1673 may help improve things if your machine's clock kept getting updated (e.g. via NTP).

But I dont understand why you think it would take hours, normally I only have to run this one or two times to get it in sync.

Do you mean two iterations of a three minute showfile, or something else?

Re ola_timecode (more experienced contributors - please correct me if this is wrong!), it doesn't appear to interact directly with ola and only exists to forward timecode data to an ArtNet output.

Yeah as @DragoonBoots says, ola_timecode simply sends a value out to any plugins which support timecode (which is currently just Art-Net), it doesn't do any processing of that data.

Even if ola_recorder supported Art-Net timecode, unless it only sends out data based on those timecode values (and doesn't free-run; which would have it's own issues with loss of timecode data) then we'd still have this issue between timecode frames.

I just did some tests comparing performance on my Raspberry Pi 3B and my desktop PC. The setup for these tests was to run a 5 minute show file that changes address 1/1 between 255 and 0 every 1000ms. The output from olad was captured and logged in sACNView as this provides a timestamp for each frame received. I then did some math with the timestamps to find the average time between value changes.

Out of interest @DragoonBoots , what were your min and max differences? Care to plot a graph like I did in the linked issue to see if the differences are constant or cumulative

In 2017 I was getting more error drift than that (but that was on Jessie perhaps it has changed on Buster)
I made a showfile turning a channel on for 500ms and off for 500ms (blue trace) every second
and played a beep (red trace) every second

Personally I'm tempted to trust @DragoonBoots figures more, there's not extra load on the Pi due to audio playback, but more importantly it's not another variable. sACNView will be simply logging each packet as it receives it, there's no risk compared to the audio of it's playback varying (unless you also measured that independently e.g. with your scope to confirm the playback frequency was accurate).

With these error rates (gaining 0.5 milliseconds over 5 minutes) I'm inclined to think this may not be fixable if this is a similar scale to the error's your seeing. The program doesn't (and, to my knowledge, can't) run in real time. The gained time is likely from processing each line in the file (i.e. time between frames = delay time + processing time), but that can't reliably be compensated for.

So how does ola_recorder really work?

1 open the file check that first line is OLA Show
2 read universe number and all recorded channels comma separated like 0 0,0,0,0....etc well how long does this take?
3 read time in milliseconds to wait
4 what happens here? I guess the file is still open?

Actually I think it could potentially be @DragoonBoots (as mentioned in the Google Group discussion).

As you roughly surmised, we currently do this:

1. open the file check that first line is OLA Show
2. read universe number and all recorded channels comma separated like 0 0,0,0,0....etc well how long does this take?
3. read time in milliseconds to wait
4. wait for that time
5. goto 2

This does mean that the small delays in running and processing 2, 3 and 4 do build up. If we instead did this:

1. open the file check that first line is OLA Show
   1a. record current timestamp
2. read universe number and all recorded channels comma separated like 0 0,0,0,0....etc well how long does this take?
3. read time in milliseconds to wait
4. wait until recorded timestamp + that time or wait for (time to wait - (now - recorded timestamp))
5. goto 1a

Then we'd take into account the processing delay and wouldn't introduce as much of a cumulative error. Obviously there would still be a small amount we can't handle because we do various other processing.

We could easily test if we'd fixed this by adding a deliberate delay in as 3a as a test, in the current model, each frame would be that delay late. Improved code shouldn't vary at all (as long as the intended wait time is more than the deliberate delay).

If it takes too long to read a line of dmxdata and convert it from decimal to a array of unsigned 8bit bytes
why not read the whole file or a big chunk of it into a bigger buffer and playback it from there?

Because then you get into all sorts of memory allocation issues. When reviewing @DragoonBoots recent changes we settled on handling a showfile of a month long (just in case); the limit is actually a lot more than that, but if we dropped down to a uint32 it would be less than a month and I figured potentially someone may run monthly shows so they could have special Christmas ones. Realistically I suspect daily files is the most that most people would do, but even with one universe that's 512 bytes * 40 frames * 60 seconds * 60 minutes * 24 hours = just over 1.75GB of data for one universe for one day. It also makes all the code a lot, lot more complicated; currently it reads a line (or a few lines at most), processes them and then moves onto the next line.

It would be nice if the program could take input while playing to start/stop/rec/pause/rev/ff like a audio/video player.

That's certainly technically possible; patches welcome. Start by considering how to do the remote control (OSC/HTTP/OLA API/DMX/something else) then design a protocol then implement the code to do it, then deal with all the edge cases. As @DragoonBoots is all too aware we came up with plenty just adding the ability to start playing from any point within a file and stopping at any other point, without changing direction or speed.

I mean how does a audio or video player program work? most certainly they must be reading data at a much higher rate?

Yes, a lot of them use a buffer so there is a delay between what's read off the disk and what appears onscreen. If you take something like and MP2/MP4 you need to read quite a bit of surrounding data to be able to assemble the first frame you want to watch because of the compression in use.

But what if i would like to change the speed while playing back the file?
or play it backwards?

These are a repetition of your question above.

or playback several files at once?

You can start multiple ola_recorders pointing at the same or different universes already.

or add some kind of master to some or all the channels?
or only change some of the channels but leave the rest to whatever value they have?

These are better handled in patcher v2 #280 (or as a client for now), as they aren't specific to recording, they are processing of DMX data which could be useful as a filter in many scenarios.

This last question i think have a answer to.
Currently when ola_recorder reads a line that looks like this
0 255,,255 sets universe 0 channel 1 and 3 to 255 but treats the missing number as between the commas as 0
setting channel 2 to zero, Well I think it should not it should not change channel two at all.
so if you have a line like this
0 ,,255,255 in a future version of ola_recorder would set universe 0 channel 2 and 3 to full but leave channel
to whatever value it has.
This would make it possible to mute certain channels from the recording.

ola_recorder doesn't know about the current value though, it's just sending DMX data out which is being merged by the universe and output via any plugins patched to that universe. Again this would need to be done in patcher v2.

More broadly our DMXBuffer doesn't have the concept of a channel with no value (as it's just an array of bytes essentially) so you'd need to extend that or send the mask separately. Think of a transparent PNG, there is R, G, B and a separate alpha channel. DMX doesn't have that idea as such.

Say you have a string of rgb leds, dimmers, moving heads or whatever on one universe
and you only want to record/change some channels or groups of channels, for example change every third led to red
or change 4 moving heads to blue
well you can't do that with ola_recorder as it is now.

You can only do HTP and LTP merges via all of OLA currently, that's not specific to ola_recorder.

[magdesign]

If I get you right,
would it make sense to convert the human readable playback file to dmx binary for faster processing ?

Would it help to send the data from a timeline addon, like ofxTimeLine, or is the bottleneck in the plugins processing the data ?

How did you make this nice test-drift graphs ? Still not sure if they help to find a regularity pattern...

[magdesign]

@vanvught said in the issue on his dmx project that this is an issue caused by Linux kernel (?)
vanvught/h3dmx512-zip#10 (comment)

If this is true, would a realtime-kernel help on RPI?
I am currently compiling a realtime kernel to test, also saw in this thread reserving some cores only for the ola_record might help.

Since I do not have art-net and dmx hardware here, I need to wait for people to send me files....
For this I would appreciate to get one of the dmx files and the audio from @MagnusHerrlin and maybe a tip on how to make a graph as you posted.

I just can not agree that we shall life with this timing behavior :-)

[shenghaoyang]

open the file check that first line is OLA Show
1a. record current timestamp
read universe number and all recorded channels comma separated like 0 0,0,0,0....etc well how long does this take?
read time in milliseconds to wait
wait until recorded timestamp + that time or wait for (time to wait - (now - recorded timestamp))
goto 1a

I think this is quite feasible - used to do this and extend it to something like a simple feedback loop that additionally tries to predict the delay so it gets more accurate.

With this scheme at most you'd get some delay between when the frame should start versus when it actually starts, and there shouldn't be growing shifts of the actual start time and when it should start.

Trying to reduce the (should be rather small relative to the frame duration) processing time could be a next step if that doesn't seem to help (gonna have to profile OLA recorder).

(Of course this is all in the recorder application, whatever happens in the server core is .....?)

[peternewman]

If I get you right,
would it make sense to convert the human readable playback file to dmx binary for faster processing ?

No, well not in terms of usability and utility. It might make it marginally faster, but lots of people are creating or modifying (or debugging) the plain text file data.

We've got ola_latency you could try:

./examples/ola_latency --send-dmx -c 100000
--------------
Sent 100000 RPCs
Max was 49867 microseconds
Mean 56 microseconds

Or this test (which includes a 1s sleep, a 20ms sleep and a lot of runs of reading and writing DMXBuffers:

time ./common/utils/UtilsTester 
.common/utils/ActionQueue.cpp:59: Action queue already finished!
.common/utils/ActionQueue.cpp:59: Action queue already finished!
.........................common/utils/DmxBuffer.cpp:241: Attempting to set channel 30 when length is 20
common/utils/DmxBuffer.cpp:241: Attempting to set channel 200 when length is 20
............................................

OK (71)

real	0m1.048s
user	0m0.029s
sys	0m0.003s

Would it help to send the data from a timeline addon, like ofxTimeLine, or is the bottleneck in the plugins processing the data ?

There will be a lot more overhead running a GUI to use that ofxTimeLine.

Different plugins have different amounts of effort to get the data out, the plugin being used may be part of the problem, which might explain why it doesn't show up with sACN. You could try recreating @DragoonBoots test with sACN which would help to rule things out.

How did you make this nice test-drift graphs ? Still not sure if they help to find a regularity pattern...

It's on the Google thread, it adds a timestamp to each line, then I dump those in a graph and do the difference between them. I generated a file with 500ms on/500ms off pulses (which I guess is quite slow and friendly for it).

I guess we could do with repeating these tests or the ones @DragoonBoots did with different frame period timings (e.g. 250ms, 100ms, 50ms say) and see what difference it makes.

If you consider another classic cumulative error scenario we've probably all coded, fading from A to B. If you do B-A/steps and get say 0.5 then for example round it up/store it in an int, every step if you add the pre-calculate value, you'd actually increase it by 1 when it should be 0.5 so your line would be twice as steep. If you accidentally had an offset instead (e.g. 1 + increment), you'd have a line at the same angle but lifted up/down relative to the expected path. Similarly with the timing they help to give an idea, is it a constant delay, variable or increasing.

If this is true, would a realtime-kernel help on RPI?

Possibly, but we do lots of more complicated bits on the Pi, and more so for others, it seems somewhat unlikely but I've never really tried working a Pi hard.

Since I do not have art-net and dmx hardware here, I need to wait for people to send me files....

I didn't use any hardware. I generated the source file by a basic script, but you could hand-craft or copy/paste (try doing that with a binary one).

Dan's test is just using the sACNView software, mine isn't even that clever just logging the time each line is output on the PC.

For this I would appreciate to get one of the dmx files and the audio from @MagnusHerrlin

As mentioned I think audio risks confusing things further as it's another variable to consider. We really just want to find out how consistent the output is. You could also record OLA driving an LED fixture via the plugin and then count frames on a video editor/player.

and maybe a tip on how to make a graph as you posted.

See my comment above.

I just can not agree that we shall life with this timing behavior :-)

Hopefully not.

I think this is quite feasible - used to do this and extend it to something like a simple feedback loop that additionally tries to predict the delay so it gets more accurate.

I'm not sure you need to do that. My suggestion is already taking into account the processing time, so it's not intended delay + processing time. I'd imagine the delay is likely to vary anyway due to load on the machine/background processes, so I'm not sure a feedback loop would be very accurate.

Trying to reduce the (should be rather small relative to the frame duration) processing time could be a next step if that doesn't seem to help (gonna have to profile OLA recorder).

That would be cool, although make sure you look at @DragoonBoots version in master.

(Of course this is all in the recorder application, whatever happens in the server core is .....?)

Yeah quite, the core is far more involved and complicated. Someone could replace ola_recorder as a test with something that uses the client API to send a frame, waits n seconds then sends another one. That would help to pinpoint which bit of software is causing it even if not why.

[danielskeenan]

Chart for science!

I'm guessing the two spikes are from me having some other things going on in the background on my local machine - everything else is pretty on point (no pun intended).

Part of me is also wondering about I/O latency on the Pi - using a good SD card or USB drive could be key here.

[shenghaoyang]

Anyone with some time to test this RFC patch before a real PR?

It keeps track of the current "playhead/desired" time relative to the last seek and the actual elapsed time since the last seek and just tries to sleep to match those.

May have edge cases >:), applies onto master.

diff --git a/examples/ShowPlayer.cpp b/examples/ShowPlayer.cpp
index 5a57f497a..8c1def457 100644
--- a/examples/ShowPlayer.cpp
+++ b/examples/ShowPlayer.cpp
@@ -217,6 +217,8 @@ ShowLoader::State ShowPlayer::SeekTo(uint64_t seek_time) {
     }
   }
   m_playback_pos = playhead_time;
+  m_clock.CurrentTime(&m_start_ts);
+  m_start_playback_pos = m_playback_pos;
 
   // Send data in the state it would be in at the given time
   map<unsigned int, ShowEntry>::iterator entry_it;
@@ -270,8 +272,17 @@ void ShowPlayer::SendEntry(const ShowEntry &entry) {
   SendFrame(entry);
   m_playback_pos += entry.next_wait;
 
+  unsigned int timeout = entry.next_wait;
+  if (!m_simulate) {
+    uint64_t target_delta = m_playback_pos - m_start_playback_pos;
+    ola::TimeStamp now;
+    m_clock.CurrentTime(&now);
+    uint64_t delay = (target_delta - (now - m_start_ts).InMilliSeconds());
+    // Handle overflow
+    timeout = (delay >= (~((unsigned int)0))) ? 0 : delay;
+  }
   // Set when next to send data
-  RegisterNextTimeout(entry.next_wait);
+  RegisterNextTimeout(timeout);
 }
 
 
diff --git a/examples/ShowPlayer.h b/examples/ShowPlayer.h
index 0ae885dbf..dfa168bbe 100644
--- a/examples/ShowPlayer.h
+++ b/examples/ShowPlayer.h
@@ -18,6 +18,7 @@
  * Copyright (C) 2011 Simon Newton
  */
 
+#include <ola/Clock.h>
 #include <ola/DmxBuffer.h>
 #include <ola/client/ClientWrapper.h>
 
@@ -89,6 +90,9 @@ class ShowPlayer {
   uint64_t m_run_time;
   std::map<unsigned int, uint64_t> m_frame_count;
   bool m_simulate;
+  ola::Clock m_clock;
+  ola::TimeStamp m_start_ts;
+  uint64_t m_start_playback_pos;
 
   /** Used for tracking simulation progress */
   typedef enum {

Quick smoke tests with a ~30Hz input, 2 channel, for 330 seconds total
X axis is elapsed real time (ms), Y axis is time when frame was supposed to be sent - time frame actually sent: Positive values means frame was early, negative value means frame was late.

Master @ ea3a18a:

After patch: