[Bug] Serious Problem with HighResolutionTimer since JUCE 7.0.3

General JUCE discussion
22

as I mentioned toward the top of the thread, this is a difference between absolute and relative timing. You can confirm this by literally changing a single line of code in JUCE:

juce_HighResolutionTimer.cpp (JUCE 7.0.5) line #83

                nextTickTime = steady_clock::now() + milliseconds (periodMillis);

                nextTickTime += milliseconds (periodMillis);

Note this means that occupying more than the period number of milliseconds in your callback (whether from code execution or the OS scheduler just being busy) will cause a pile-up of due events. So a proper implementation would detect some amount of skew and “drop” frames (ideally notifying of these via the timer callback).

                  --internal 1 ms-  --hiResTime ms-   ----elapsed----   ---accum diff--
                  sec  ms   micro   sec  ms   micro   sec  ms   micro   sec  ms   micro
1000 callbacks:    00.000    000     00.000    000     00.000    000     00.000    000
1000 callbacks:    01.000    000     00.999    862     00.999    862     00.000    -137
1000 callbacks:    02.000    000     01.999    290     00.999    427     00.000    -709
1000 callbacks:    03.000    000     02.999    459     01.000    168     00.000    -540
1000 callbacks:    04.000    000     04.000    392     01.000    933     00.000    392
1000 callbacks:    05.000    000     04.999    866     00.999    473     00.000    -133
1000 callbacks:    06.000    000     06.000    072     01.000    206     00.000    072
1000 callbacks:    07.000    000     07.000    793     01.000    720     00.000    793
1000 callbacks:    08.000    000     07.998    973     00.998    180     00.-01    -26
1000 callbacks:    09.000    000     08.999    026     01.000    052     00.000    -973
1000 callbacks:    10.000    000     10.000    061     01.001    035     00.000    061
1000 callbacks:    11.000    000     10.999    761     00.999    699     00.000    -238
1000 callbacks:    12.000    000     11.999    434     00.999    673     00.000    -565
1000 callbacks:    13.000    000     12.998    837     00.999    402     00.-01    -162
1000 callbacks:    14.000    000     13.999    766     01.000    929     00.000    -233
1000 callbacks:    15.000    000     14.998    994     00.999    228     00.-01    -05
1000 callbacks:    16.000    000     16.000    413     01.001    418     00.000    413
1000 callbacks:    17.000    000     16.999    167     00.998    753     00.000    -832
1000 callbacks:    18.000    000     17.999    880     01.000    712     00.000    -119
1000 callbacks:    19.000    000     19.000    033     01.000    153     00.000    033
1000 callbacks:    20.000    000     19.998    902     00.998    868     00.-01    -97
1000 callbacks:    21.000    000     21.000    611     01.001    709     00.000    611
1000 callbacks:    22.000    000     22.000    092     00.999    480     00.000    092
1000 callbacks:    23.000    000     22.999    849     00.999    757     00.000    -150
1000 callbacks:    24.000    000     23.999    300     00.999    451     00.000    -699
1000 callbacks:    25.000    000     25.000    462     01.001    161     00.000    462
1000 callbacks:    26.000    000     25.999    723     00.999    261     00.000    -276
1000 callbacks:    27.000    000     26.998    988     00.999    264     00.-01    -11
1000 callbacks:    28.000    000     28.000    560     01.001    572     00.000    560
1000 callbacks:    29.000    000     28.999    335     00.998    774     00.000    -664
1000 callbacks:    30.000    000     29.999    077     00.999    742     00.000    -922
1000 callbacks:    31.000    000     30.999    234     01.000    156     00.000    -765
1000 callbacks:    32.000    000     32.000    531     01.001    297     00.000    531
1000 callbacks:    33.000    000     33.000    386     00.999    855     00.000    386
1000 callbacks:    34.000    000     33.999    166     00.998    780     00.000    -833
1000 callbacks:    35.000    000     35.000    598     01.001    431     00.000    598
1000 callbacks:    36.000    000     36.000    296     00.999    697     00.000    296
1000 callbacks:    37.000    000     36.999    568     00.999    272     00.000    -431
1000 callbacks:    38.000    000     37.999    537     00.999    968     00.000    -462
1000 callbacks:    39.000    000     38.998    950     00.999    413     00.-01    -49
1000 callbacks:    40.000    000     39.999    447     01.000    497     00.000    -552
1000 callbacks:    41.000    000     40.999    280     00.999    832     00.000    -719
1000 callbacks:    42.000    000     42.000    447     01.001    167     00.000    447
1000 callbacks:    43.000    000     43.000    231     00.999    783     00.000    231
1000 callbacks:    44.000    000     44.000    250     01.000    018     00.000    250
1000 callbacks:    45.000    000     45.000    046     00.999    795     00.000    046
1000 callbacks:    46.000    000     45.999    748     00.999    702     00.000    -251
1000 callbacks:    47.000    000     46.999    251     00.999    502     00.000    -748
1000 callbacks:    48.000    000     47.999    579     01.000    328     00.000    -420
1000 callbacks:    49.000    000     48.999    105     00.999    526     00.000    -894
1000 callbacks:    50.000    000     49.999    745     01.000    640     00.000    -254
1000 callbacks:    51.000    000     50.998    875     00.999    129     00.-01    -124
1000 callbacks:    52.000    000     51.999    118     01.000    242     00.000    -881
1000 callbacks:    53.000    000     53.000    507     01.001    389     00.000    507
1000 callbacks:    54.000    000     53.999    507     00.998    999     00.000    -492
1000 callbacks:    55.000    000     54.999    646     01.000    139     00.000    -353
1000 callbacks:    56.000    000     56.000    662     01.001    016     00.000    662
1000 callbacks:    57.000    000     57.000    222     00.999    559     00.000    222
1000 callbacks:    58.000    000     57.999    315     00.999    093     00.000    -684
1000 callbacks:    59.000    000     58.999    101     00.999    785     00.000    -898
1000 callbacks:    00.000    000     00.000    459     01.001    357     00.000    459
1000 callbacks:    01.000    000     00.999    594     00.999    135     00.000    -405
1000 callbacks:    02.000    000     02.000    396     01.000    801     00.000    396
1000 callbacks:    03.000    000     02.999    043     00.998    646     00.000    -956
1000 callbacks:    04.000    000     03.999    377     01.000    334     00.000    -622
1000 callbacks:    05.000    000     04.999    533     01.000    155     00.000    -466
1000 callbacks:    06.000    000     05.998    873     00.999    340     00.-01    -126
1000 callbacks:    07.000    000     06.999    399     01.000    526     00.000    -600
1000 callbacks:    08.000    000     07.998    928     00.999    528     00.-01    -71
1000 callbacks:    09.000    000     09.000    279     01.001    351     00.000    279
1000 callbacks:    10.000    000     09.999    192     00.998    913     00.000    -807
1000 callbacks:    11.000    000     11.000    702     01.001    510     00.000    702
1000 callbacks:    12.000    000     12.000    423     00.999    720     00.000    423
1000 callbacks:    13.000    000     13.000    242     00.999    819     00.000    242
1000 callbacks:    14.000    000     13.998    873     00.998    631     00.-01    -126
1000 callbacks:    15.000    000     15.000    256     01.001    382     00.000    256
4 Likes
23

I was just saying that if you have a DAW block size of say 4096 samples (i.e. one every ~43ms in a 96k project), you’re going to get far fewer calls coming in on dependable timing cycle to use as a source of accurate time stamping than if the block size is 64 samples (sub 1ms). So clearly if you are hoping to use it for timing data based on getting regular calls the block size could be so large it’s not good enough for the intended use. It could be better or worse than you’re getting from an OS timer.

24

It depends on your perspective. If you want absolute timing, like you do, then it looks like it was correct before and broken now. If you want relative timing, like some other people might, then it looks like it was broken before and was fixed. The reason why there’s confusion at all is because the documentation never specified to this degree of detail, it was never a contract promise. It probably makes sense to have a parameter to specify the behavior you prefer.

2 Likes
25

Brilliant! Thank you for that! It seems to go back to working the previous way! It’s nice to know I can change this one line and have it the old way.

I’m sorry if I don’t get it, but what is the purpose of this “relative timing”? Where 1 ms cannot be counted on to be 1 ms, but may be 1.1 or 1.8 ms? In a purportedly “high resolution timer”?

What situation is this SUPER-breaking change (that wasn’t mentioned) supposed to fix?

And if it is left this way, then there is no such thing as an accurate absolute timer in JUCE anymore?

I’d agree with that.

1 Like
26

Nice detective work!

1 Like
27

I don’t understand the rationale for the change. If they don’t change it back, then the only reasonable solution is to add a parameter as suggested by @caustik. Otherwise, you would have to fork Juce (or simply use a private build).

1 Like
28

The timing derived from processBlock, from within processBlock, is accurate regardless of buffer size. You know the sample rate and the block size, so any calculations that are based on that are sample accurate. And this information can be used to timestamp midi, inside of processBlock. But this information cannot be used outside of processBlock.

1 Like
29

I’m not debating its accuracy, it’s very accurate. You just may not get accurate timestamps frequently enough to satisfy your needs because how often you get these very accurate callbacks is dependent on block size.

1 Like
30

Me neither - but I’m willing to be educated on that. :wink:

I’m already using a private version of JUCE with many modifications - so one more isn’t a problem. I’m just glad to know how to fix it.

I’d still hope that @oli1 or someone else from the juce team can explain what’s going on here.

1 Like
31

Hello!

Sorry, I didn’t notice the breaking behavorial change in my testing when I was putting this new threading code together! I’m putting together a fix for this!

8 Likes
32

One of us in not understanding the other. what is the use case you are describing?

I will try to be more clear, if one has a 4096 byte block of samples, one can create midi timestamps during that processing of the 4096 bytes that are fully accurate. the frequency of the callback is not involved in timing at all. in the callback you know how many samples you have, and you know the sample rate, so you have a ‘block of time’ defined by the size of the buffer and sample rate. you can generate accurate midi timestamps anywhere within the block of time.

1 Like
33

Thanks so much @oli1! I was sorta freaking out. :slight_smile:

2 Likes
34

Thank you, @oli1 !

1 Like
35

@oli1 - JFYI - After playing with this a bit more, I can say that changing that one line fixes the overall accumulated drift (i.e. over 30 or 60 seconds) pretty much, but there is still a lack of tightness between the original callbacks that wasn’t present in the previous version. There is quite a bit more jitter in the 7.0.3+ version between individual 1 ms callbacks - even with that one line change.

I have uploaded my revised HiResTimerTest3:

HiResTimerTest3.zip (13.6 KB)

There are now three additional buttons that display the amount of jitter between 1ms callbacks, broken down into:
+/- greater than 1 ms
+/- greater than a 10th of a ms
+/- greater than 100th of a ms

hires
hires1200×844 32.9 KB

With the previous “good” commit 621e14d:

MacOS:
Turning on/off the Jitter 1 ms button: nothing (good!)

Turning on/off the Jitter 10th ms button: nothing (good!)

Turning on/off the Jitter 100th ms button:

0004: timer 100th jitter +0.014420
0005: timer 100th jitter -0.013164
0006: timer 100th jitter +0.012538
0034: timer 100th jitter +0.010487
0054: timer 100th jitter +0.010615
0063: timer 100th jitter -0.011656
0103: timer 100th jitter -0.010430
0127: timer 100th jitter -0.013541
0139: timer 100th jitter +0.011239
0168: timer 100th jitter -0.012771
0169: timer 100th jitter +0.014859
0181: timer 100th jitter +0.012339

So finally we see some jitter of +/- 100th ms (acceptable) - and they are pretty far apart.
(The first number is a count of callbacks.)

With the “problematic” commit d3cff37 (with the one line change):

Turning on/off the Jitter 1 ms button: nothing

Turning on/off the Jitter 10th ms button:

0008: timer 10th  jitter +0.134752
0010: timer 10th  jitter -0.116478
0046: timer 10th  jitter +0.252243
0048: timer 10th  jitter -0.109060
0084: timer 10th  jitter +0.178718
0085: timer 10th  jitter -0.188060
0086: timer 10th  jitter +0.149044
0088: timer 10th  jitter -0.148321
0092: timer 10th  jitter +0.120370
0093: timer 10th  jitter -0.122607
0097: timer 10th  jitter +0.126488
0101: timer 10th  jitter +0.214626

So here we have jitter of more than a 10th of a ms, when before we had none.

Turning on/off the Jitter 100th ms button:

0001: timer 100th jitter -0.031225
0011: timer 100th jitter +0.010650
0021: timer 100th jitter -0.075860
0022: timer 100th jitter -0.037490
0028: timer 100th jitter +0.016284
0030: timer 100th jitter -0.052496
0038: timer 100th jitter +0.014145
0054: timer 100th jitter -0.093510
0063: timer 100th jitter +0.010451
0073: timer 100th jitter +0.013913
0080: timer 100th jitter +0.087408
0081: timer 100th jitter -0.032108

With both the 10th and 100th turned on:

0376: timer 100th jitter +0.020557
0378: timer 100th jitter +0.010878
0379: timer 10th  jitter -0.148319
0380: timer 100th jitter -0.034530
0381: timer 10th  jitter +0.230236
0382: timer 100th jitter -0.055659
0385: timer 100th jitter -0.011785
0389: timer 10th  jitter -0.148877
0393: timer 10th  jitter +0.137483
0394: timer 100th jitter +0.022499
0395: timer 10th  jitter -0.164549
0400: timer 100th jitter -0.042067

I don’t know how accurate this is as it probably takes some time to print this stuff out, but it does show that there is more jitter in the “problematic commit” even with the one line fix - and they are closer together (more often).

On Windows, it’s worse (as expected):

With the “good” commit 621e14d:

Turning on/off the Jitter 1 ms button:

0142: timer 1 ms  jitter +1.005700
0884: timer 1 ms  jitter +1.010900
0892: timer 1 ms  jitter +1.004500
0896: timer 1 ms  jitter +1.001500
1269: timer 1 ms  jitter +1.009700
2681: timer 1 ms  jitter +1.007400
3059: timer 1 ms  jitter +1.001700
5307: timer 1 ms  jitter +1.007600
6430: timer 1 ms  jitter +1.033900

We see a very few jitters of +/-1 ms, and they are far apart.

Turning on/off the Jitter 10th button:

0269: timer 10th  jitter +0.970400
0643: timer 10th  jitter +0.994600
0645: timer 10th  jitter -0.998600
1031: timer 10th  jitter +0.980400
1305: timer 10th  jitter +0.100200
1306: timer 10th  jitter -0.108800
1313: timer 10th  jitter +0.134300
1314: timer 10th  jitter -0.106000
1479: timer 10th  jitter +0.254100
1480: timer 10th  jitter -0.254100
1596: timer 10th  jitter +0.174500

More than Mac, but relatively far apart.

Turning on/off the Jitter 100th button:

0894: timer 100th jitter -0.013500
0896: timer 100th jitter -0.031800
0897: timer 100th jitter +0.025400
0900: timer 100th jitter -0.013500
0904: timer 100th jitter +0.012300
0905: timer 100th jitter -0.017400
0909: timer 100th jitter +0.010600
0910: timer 100th jitter -0.016200
0917: timer 100th jitter -0.011600
0921: timer 100th jitter -0.015200
0924: timer 100th jitter -0.037400
0928: timer 100th jitter +0.014700
0929: timer 100th jitter +0.014800

Now, with the “problematic” commit d3cff37 (with the one line change):

Turning on/off the Jitter 1 ms button:

0001: timer 1 ms  jitter +1.002100
0006: timer 1 ms  jitter +1.028600
0011: timer 1 ms  jitter +1.001700
0020: timer 1 ms  jitter +1.027100
0032: timer 1 ms  jitter +1.003300
0047: timer 1 ms  jitter +1.000400
0051: timer 1 ms  jitter +1.009200
0058: timer 1 ms  jitter +1.002400
0063: timer 1 ms  jitter +1.013700
0071: timer 1 ms  jitter +1.017700
0080: timer 1 ms  jitter +1.006800
0084: timer 1 ms  jitter +1.017600
0095: timer 1 ms  jitter +1.001100
0099: timer 1 ms  jitter +1.035500
0103: timer 1 ms  jitter +1.019500

A lot more, and much more frequent!

Turning on/off the Jitter 10th button:

0001: timer 10th  jitter -0.999300
0002: timer 10th  jitter +0.990400
0003: timer 10th  jitter -0.819900
0004: timer 10th  jitter +0.813200
0005: timer 10th  jitter -0.817900
0006: timer 10th  jitter +0.802700
0007: timer 10th  jitter -0.761800
0008: timer 10th  jitter +0.731600
0009: timer 10th  jitter -0.917400
0010: timer 10th  jitter +0.918300
0011: timer 10th  jitter -0.964900
0012: timer 10th  jitter +0.961200

Way more, every single callback. And so on. Again, I’m not sure how accurate this is, but I think it shows there’s way more jitter on the “problematic” commit, even with that one line fix, so it’s likely more involved than that.

I don’t know if this is helpful at all, but I sure hope it is!

1 Like
36

Thanks for the in-depth analysis.

I agree, time += period vs time += now + period is not a suitable fix. It just masks the drift instead of accounting for it.

I’ve re-implemented the previous Windows version and upgraded the macOS version to use an OS Timer API coupled with a real-time thread. This results in very predictable and consistent results.

I hope to put it in the review pipeline ASAP.

6 Likes
37

@oli1 - just wondering how this is going.

And a question: would this also affect the accuracy of the standard Timer class? Thanks!

1 Like
38

@oli1 - just wondering if there’s any update on this fix? Thank you kindly!

39

Hi! whatever happened to this issue?

40

Hi, apologies this issue has been more of time sink than you might imagine we found a number of other subtle issues. After several iterations I’m currently making some final changes, tests, and tweaks. Once the new version goes up it will also be accompanied by a number of unit tests so hopefully we don’t see similar regressions again.

Thanks.

3 Likes
41

Thanks, Anthony! I appreciate all you guys do. :slight_smile: