[Bug] Serious Problem with HighResolutionTimer since JUCE 7.0.3

General JUCE discussion
1

I have found that since JUCE 7.0.3, the HighResolutionTimer is way off from what it should be, unlike JUCE 7.02 where it was rock-solid. (I’m using 7.0.3 at the moment but I just tested 7.0.5 and for this it is the same).

Since JUCE 7.0.3 and later it is not even close to accurate:
On Mac it is nearly 10% slower between callbacks.
On Windows it is nearly 56% slower between callbacks.

I have a MIDI-generating app that I have been working on with JUCE for over three years now. (Standalone GUI App. Not using AudioProcessor.) It’s sort of a super-arpeggiator phrase-generator that generates MIDI data in real-time. It depends on a solid 1 ms Timer callback. For this, I have been successfully using the HighResolutionTimer. But since JUCE 7.0.3, the timing is way off (slower on Mac, and even much worse on Windows.)

It’s likely this is related to the threading changes in 7.0.3 but I have no idea what to fool with.

So I created a simple test app that calls HighResolutionTimer::startTimer(1) for a 1 ms callback. The app then has a button that turns on debugging printout, where it stores the start time and prints out some data every 1 second (1000 callbacks). Here it is:

HiResTimerTest.zip (9.7 KB)
(EDIT: updated to include both Xcode and VS2019 Exporters)

So these DBG printouts show 30 seconds of receiving 1ms TimerCallbacks, where the startTime is stored and subtracted from the current Time to show time from zero.

The first column shows my internal 1 ms counter, which is just incremented by 1 ms for each callback received.

The second column shows the actual value returned by Time::getMillisecondCounterHiRes() (minus the start time).

The third column shows the accumulated difference between the two.

First, on the Mac:

JUCE 7.0.2 Mac
             -internal 1 ms-   -hiResTime ms-    --difference--
            sec  ms   micro   sec  ms   micro   sec  ms   micro
callback:    00.000    000     00.000    000     00.000    000
callback:    01.000    000     00.999    993     00.000    -06
callback:    02.000    000     02.000    002     00.000    002
callback:    03.000    000     02.999    997     00.000    -02
callback:    04.000    000     03.999    995     00.000    -04
callback:    05.000    000     04.999    994     00.000    -05
callback:    06.000    000     06.000    006     00.000    006
callback:    07.000    000     07.000    001     00.000    001
callback:    08.000    000     07.999    994     00.000    -05
callback:    09.000    000     09.000    004     00.000    004
callback:    10.000    000     10.000    016     00.000    016
callback:    11.000    000     11.000    001     00.000    001
callback:    12.000    000     12.000    006     00.000    006
callback:    13.000    000     13.000    002     00.000    002
callback:    14.000    000     14.000    008     00.000    008
callback:    15.000    000     15.000    014     00.000    014
callback:    16.000    000     15.999    994     00.000    -05
callback:    17.000    000     16.999    998     00.000    -01
callback:    18.000    000     17.999    995     00.000    -04
callback:    19.000    000     18.999    993     00.000    -06
callback:    20.000    000     20.000    004     00.000    004
callback:    21.000    000     20.999    993     00.000    -06
callback:    22.000    000     22.000    006     00.000    006
callback:    23.000    000     22.999    992     00.000    -07
callback:    24.000    000     24.000    010     00.000    010
callback:    25.000    000     24.999    996     00.000    -03
callback:    26.000    000     26.000    003     00.000    003
callback:    27.000    000     27.000    003     00.000    003
callback:    28.000    000     27.999    995     00.000    -04
callback:    29.000    000     28.999    997     00.000    -02
callback:    30.000    000     30.000    005     00.000    005

In JUCE 7.0.2 Mac, we can see that there is a very slight jitter of +/-20 microseconds, with the actual time keeping very accurately to the number of callbacks received (internal 1 ms column). At the end of 30 seconds, The MIDI data generated fills 30 seconds of time exactly. 1ms is 1ms.

(And previously, I have measured the jitter between each 1 ms callback and it is infinitesimal.)

JUCE 7.0.3 Mac
             -internal 1 ms-   -hiResTime ms-    --difference--
            sec  ms   micro   sec  ms   micro   sec  ms   micro
callback:    00.000    000     00.000    000     00.000    000
callback:    01.000    000     01.099    666     00.099    666
callback:    02.000    000     02.199    072     00.199    072
callback:    03.000    000     03.302    303     00.302    303
callback:    04.000    000     04.401    938     00.401    938
callback:    05.000    000     05.508    542     00.508    542
callback:    06.000    000     06.607    307     00.607    307
callback:    07.000    000     07.702    652     00.702    652
callback:    08.000    000     08.786    031     00.786    031
callback:    09.000    000     09.879    499     00.879    499
callback:    10.000    000     10.978    429     00.978    429
callback:    11.000    000     12.070    584     01.070    584
callback:    12.000    000     13.164    801     01.164    801
callback:    13.000    000     14.253    678     01.253    678
callback:    14.000    000     15.345    196     01.345    196
callback:    15.000    000     16.439    011     01.439    011
callback:    16.000    000     17.534    295     01.534    295
callback:    17.000    000     18.626    020     01.626    020
callback:    18.000    000     19.718    178     01.718    178
callback:    19.000    000     20.807    242     01.807    242
callback:    20.000    000     21.897    735     01.897    735
callback:    21.000    000     22.983    616     01.983    616
callback:    22.000    000     24.077    274     02.077    274
callback:    23.000    000     25.169    486     02.169    486
callback:    24.000    000     26.270    512     02.270    512
callback:    25.000    000     27.360    884     02.360    884
callback:    26.000    000     28.454    947     02.454    947
callback:    27.000    000     29.548    967     02.548    967
callback:    28.000    000     30.643    480     02.643    480
callback:    29.000    000     31.733    584     02.733    584
callback:    30.000    000     32.823    893     02.823    893    2.823 seconds behind

In JUCE 7.0.3 Mac, at the end of 30 seconds (30,000 1ms callbacks), my app has generated 30 seconds of MIDI, but in actuality, 32.83 seconds have elapsed. The HighResolutionTimer is running 2.83 seconds behind. I can hear it - it generates the MIDI slower and with less accuracy than before! 120 BPM is no longer 120 BPM. 1 ms is actually about 1.1 ms.

On WINDOWS, it’s far worse.

JUCE 7.0.2 WINDOWS
             -internal 1 ms-   -hiResTime ms-    --difference--
            sec  ms   micro   sec  ms   micro   sec  ms   micro
callback:    00.000    000     00.000    000     00.000    000
callback:    01.000    000     00.999    813     00.000    -186
callback:    02.000    000     02.000    017     00.000    017
callback:    03.000    000     02.999    955     00.000    -44
callback:    04.000    000     03.999    774     00.000    -225
callback:    05.000    000     04.999    447     00.000    -552
callback:    06.000    000     05.999    832     00.000    -167
callback:    07.000    000     06.999    667     00.000    -332
callback:    08.000    000     07.999    830     00.000    -169
callback:    09.000    000     08.999    293     00.000    -706
callback:    10.000    000     10.000    104     00.000    104
callback:    11.000    000     11.000    194     00.000    194
callback:    12.000    000     12.000    126     00.000    126
callback:    13.000    000     12.999    800     00.000    -199
callback:    14.000    000     14.000    096     00.000    096
callback:    15.000    000     14.999    835     00.000    -164
callback:    16.000    000     15.999    410     00.000    -589
callback:    17.000    000     16.999    909     00.000    -90
callback:    18.000    000     17.999    662     00.000    -337
callback:    19.000    000     19.000    088     00.000    088
callback:    20.000    000     19.999    376     00.000    -623
callback:    21.000    000     20.999    898     00.000    -101
callback:    22.000    000     21.999    248     00.000    -751
callback:    23.000    000     22.999    518     00.000    -481
callback:    24.000    000     23.999    934     00.000    -65
callback:    25.000    000     24.999    956     00.000    -43
callback:    26.000    000     25.999    819     00.000    -180
callback:    27.000    000     26.999    685     00.000    -314
callback:    28.000    000     27.999    619     00.000    -380
callback:    29.000    000     28.999    979     00.000    -20
callback:    30.000    000     30.000    108     00.000    108

In JUCE 7.0.2 Windows, we can see that it is still solid (more jitter than Mac, but still within +/-500 microseconds of where it should be, and after 30 seconds (30,000 1ms callbacks), 30 realtime seconds has occurred. 1 ms is 1 ms.

JUCE 7.0.3 WINDOWS
             -internal 1 ms-   -hiResTime ms-    --difference--
            sec  ms   micro   sec  ms   micro   sec  ms   micro
callback:    00.000    000     00.000    000     00.000    000
callback:    01.000    000     01.604    174     00.604    174
callback:    02.000    000     03.174    739     01.174    739
callback:    03.000    000     04.790    289     01.790    289
callback:    04.000    000     06.377    858     02.377    858
callback:    05.000    000     07.973    723     02.973    723
callback:    06.000    000     09.574    455     03.574    455
callback:    07.000    000     11.181    865     04.181    865
callback:    08.000    000     12.803    037     04.803    037
callback:    09.000    000     14.401    873     05.401    873
callback:    10.000    000     16.000    592     06.000    592
callback:    11.000    000     17.577    725     06.577    725
callback:    12.000    000     19.156    730     07.156    730
callback:    13.000    000     20.806    755     07.806    755
callback:    14.000    000     22.383    309     08.383    309
callback:    15.000    000     23.994    883     08.994    883
callback:    16.000    000     25.597    909     09.597    909
callback:    17.000    000     27.205    626     10.205    626
callback:    18.000    000     28.803    494     10.803    494
callback:    19.000    000     30.381    940     11.381    940
callback:    20.000    000     32.017    642     12.017    642
callback:    21.000    000     33.598    949     12.598    949
callback:    22.000    000     35.150    333     13.150    333
callback:    23.000    000     36.742    656     13.742    656
callback:    24.000    000     38.293    149     14.293    149
callback:    25.000    000     39.872    513     14.872    513
callback:    26.000    000     41.449    424     15.449    424
callback:    27.000    000     43.050    336     16.050    336
callback:    28.000    000     44.613    216     16.613    216
callback:    29.000    000     46.183    615     17.183    615
callback:    30.000    000     47.757    880     17.757    880.  17.757 seconds behind!

In JUCE 7.0.3 Windows, after 30 seconds, 47.757 realtime seconds have elapsed. The HighResolutionTimer is a whopping 17.757 seconds behind where it should be for 30,000 callbacks. My app sounds like it’s on drugs. 1 ms is like 1.59 ms.

I was busy working on the interface the last few months or I would have noticed this sooner; I haven’t been testing the stuff that already worked.

I’m really hoping that @reuk or someone from the juce team can look into this. My whole app depends on the HighResolutionTimer working solidly like it always has, since I started with JUCE 5.

My Mac System:
MacPro (Mid 2012) 12-core
2 x 3.06 GHz 6-Core Intel Xeon
MacOS 10.14.6 Mojave

My Windows System:
Dell XPS 8930
Intel Core i9-9900 CPU @ 3.10GHz
Windows 10 Home

2

HighResolutionTimer updates its target timestamp at each iteration, relative to the current timestamp. This prioritizes relative time accuracy over absolute time accuracy. The alternative would be to assign a fixed timestamp when the thread first starts, and calculate the target timestamp as a function of this and the number of completed iterations.

I would suggest implementing your own timer thread where you have the control to implement using the above mechanism. Note that you will lose relative time accuracy and you will need to consider how to handle dropped frames (your due time is significantly in the past because the system is saturated with work).

AI Prompt: “implement a simple C++ timer mechanism which prioritizes accuracy of absolute timing (rather than relative timing)”

3

This probably isn’t the answer your looking for, and maybe there is a reason you chose not to do this, but isn’t the best practice method to calculate time in an audio app to use the audio callback to drive a synched clock?

1 Like
4

I’m a bit curious as to why you don’t use the timing that processblock brings you for precise timing of Midi. Or maybe that’s not a part of your application?

I tried to build your test app, but didn’t succeed. You don’t happen to have a visual studio .sln file for it?

5

But how come it’s rock-solid in JUCE 5 ~ 7.0.2 and terrible in JUCE 7.0.3+?

6

I’m sorry, I see that the project I included above did not have the Visual Studio Exporter as part of it, just the XCode. I have updated the link in the original post to have both, if you’d like to try it again.

7

I think the simple answer is that the semantics you’re relying on weren’t ever specified in the documentation for this class, and it was majorly rehauled fairly recently. Like others are saying, you’re most likely better off handling timing using processBlock which gives you sample-accurate timing and will implicitly allow you to work properly during offline processing (Freeze/Export).

8

It would appear the original poster is working with a pure MIDI standalone application, not one where the audio callback (processBlock or getNextAudioBlock) would be available. But the poster didn’t exactly say if that is the case or not.

9

Still no .sln file. Only a jucer file. I’m not familiar with the jucer so I don’t think I can help you there.

10

Thanks, but what does that mean? The documentation states:

Is it reasonable to assume that an “accurately-timed regular callback” falls behind by 17 seconds during a 30 second period on Windows? When it used to work fine for 3 years of development?

That is correct. It is a “GUI App”, which is a JUCE project type that does not use the whole AudioProcessor thing. And I did it this way because it is a 20-year old project that was originally implemented in MacOS 32-bit Carbon and WIN32, I’m porting it, and it has always worked and been sold and even incorporated into hardware products using a 1 ms clock-based scheduler system.

11

Just so this doesn’t get lost, the issue is not what I’m using the HighResolutionTimer for.

It’s the fact that there is a massive degradation in the performance of a HighResolutionTimer from JUCE 7.0.2 to 7.0.3. The introduction of a “new thread backend” has completely destroyed it.

It’s no longer even close to accurate.

I narrowed this down to exactly which commit caused the massive degrade. As suspected, it is the breaking change commit named “Thread: introduce a new Thread backend”:

So when compiled with the previous commit, the HighResTimer works as it should. 30,000 1 ms callbacks takes exactly 30 seconds.

With the “new Threading” commit ‘d3cff375’, 30,000 1 ms callbacks takes around 33.269 seconds to occur on MacOS, and on Windows it takes an astounding 59 seconds (and these results are different each time).

Here is my updated simple test project that now includes “elapsed” as column 3, showing how long each 1000 callback chunk took (which should be 1.0 seconds).

HiResTimerTest 2.zip (13.1 KB)

Compiled with the (good) commit ‘621e14d0’:

MacOS:
                 --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    997     00.999    997     00.000    -02
1000 callbacks:    02.000    000     01.999    998     01.000    001     00.000    -01
1000 callbacks:    03.000    000     02.999    999     01.000    001     00.000    000
1000 callbacks:    04.000    000     03.999    997     00.999    997     00.000    -02
1000 callbacks:    05.000    000     05.000    000     01.000    003     00.000    000
   <snip>   			:			:		:			:		 :			:		  :		     :
1000 callbacks:    25.000    000     24.999    989     00.999    989     00.000    -10
1000 callbacks:    26.000    000     25.999    993     01.000    004     00.000    -06
1000 callbacks:    27.000    000     26.999    995     01.000    002     00.000    -04
1000 callbacks:    28.000    000     27.999    994     00.999    999     00.000    -05
1000 callbacks:    29.000    000     28.999    997     01.000    002     00.000    -02
1000 callbacks:    30.000    000     30.000    003     01.000    005     00.000    003

MacOS:
30,000 1 ms callbacks takes 30 real-time seconds. 1000 callbacks takes 1 ms. Slight jitter of a few microseconds. The accumulated difference is virtually 0.

Windows:
                  --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     01.000    328     01.000    328     00.000    328
1000 callbacks:    02.000    000     02.000    620     01.000    291     00.000    620
1000 callbacks:    03.000    000     02.999    982     00.999    362     00.000    -17
1000 callbacks:    04.000    000     04.000    300     01.000    317     00.000    300
1000 callbacks:    05.000    000     05.000    644     01.000    344     00.000    644
   <snip>   			:			:		:			:		 :			:		  :		     :
1000 callbacks:    25.000    000     25.000    408     01.000    295     00.000    408
1000 callbacks:    26.000    000     25.999    731     00.999    322     00.000    -268
1000 callbacks:    27.000    000     27.000    083     01.000    352     00.000    083
1000 callbacks:    28.000    000     28.000    388     01.000    304     00.000    388
1000 callbacks:    29.000    000     28.999    742     00.999    354     00.000    -257
1000 callbacks:    30.000    000     30.000    056     01.000    314     00.000    056

Windows:
30,000 1 ms callbacks takes 30 real-time seconds. 1000 callbacks takes 1 ms. Slight jitter of a few hundred microseconds (worse than Mac, but still very accurate). The accumulated difference is virtually 0.

Compiled with the (problematic) commit ‘d3cff375’:

MacOS:

                 --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     01.111    951     01.111    951     00.111    951
1000 callbacks:    02.000    000     02.222    041     01.110    090     00.222    041
1000 callbacks:    03.000    000     03.329    352     01.107    310     00.329    352
1000 callbacks:    04.000    000     04.440    688     01.111    335     00.440    688
1000 callbacks:    05.000    000     05.551    385     01.110    696     00.551    385
   <snip>   			:			:		:			:		 :			:		  :		     :
1000 callbacks:    25.000    000     27.730    893     01.110    517     02.730    893
1000 callbacks:    26.000    000     28.841    954     01.111    061     02.841    954
1000 callbacks:    27.000    000     29.950    496     01.108    541     02.950    496
1000 callbacks:    28.000    000     31.064    247     01.113    750     03.064    247
1000 callbacks:    29.000    000     32.173    693     01.109    446     03.173    693
1000 callbacks:    30.000    000     33.269    361     01.095    668     03.269    361

MacOS:
30,000 1 ms callbacks took 33.269 seconds, with 1 ms (1000 callbacks) taking somewhere around 1.110 ms! 11% slower than real-time.

Windows:
                  --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     01.969    772     01.969    772     00.969    772
1000 callbacks:    02.000    000     03.946    467     01.976    695     01.946    467
1000 callbacks:    03.000    000     05.919    154     01.972    686     02.919    154
1000 callbacks:    04.000    000     07.904    837     01.985    683     03.904    837
1000 callbacks:    05.000    000     09.872    597     01.967    759     04.872    597
   <snip>   			:			:		:			:		 :			:		  :		     :
1000 callbacks:    25.000    000     49.273    459     01.987    753     24.273    459
1000 callbacks:    26.000    000     51.256    085     01.982    625     25.256    085
1000 callbacks:    27.000    000     53.219    817     01.963    732     26.219    817
1000 callbacks:    28.000    000     55.196    527     01.976    709     27.196    527
1000 callbacks:    29.000    000     57.173    274     01.976    747     28.173    274
1000 callbacks:    30.000    000     59.109    124     01.935    849     29.109    124

Windows:
30,000 1 ms callbacks took 59.109 seconds, with 1 ms (1000 callbacks) taking somewhere around 1.978 ms! Almost 50% slower than real-time.

Here is the commit right before it, where the HighResolutionTimer works correctly:

5 Likes
12

I have essentially duplicated your results (comparing Juce 7.0.2 and Juce 7.0.5 with Windows 10, VS 2022, AMD Ryzen 9 5900).
The HighResolutionTimer thread is started as startThread (Thread::Priority::high);
(juce_HighResolutionTimer.cpp line 51 in Juce 7.0.5).
I might have expected that startRealtimeThread would be called, or at least Thread::Priority::highest would be used. I tried making each of these changes, with no change in performance.

From
d3cff375be396580439ef287159b0665dbf2f259/BREAKING-CHANGES.txt

Workaround
Rather than using an integer thread priority you must instead use a value from
the Thread::Priority enum. Thread::setPriority and Thread::getPriority should
only be called from the target thread. To start a Thread with a realtime
performance profile you must call startRealtimeThread.

However, the problem may be deeper than this.

6 Likes
13

The resolution of any timing you’d get using a process block is dependent on the size of the block the DAW is calling at. Great for precision sure, but at large block sizes it’s not that great for timing resolution as the calls may not be coming in very often and may not even be consistently sized.

2 Likes
15

I can’t say I completely understand what your saying.

If you want to precisely time your midi events, when using the processblock, you just sum upp the samples of the process blocks starting at some given point in time. It could be the start of your application, the moment you press a button or when some information from the play head of the daw (if this is a plugin) is fullfilled. Or what ever.

This doesn’t depend on the individual size of the process blocks. They could be say 768, 32, 137, 3 000, and if you wan’t your midi event to play at say 1234 ms from time zero, you just sum the block samples up. In this case, it should play at sample pos 2 063 of the 4:th process block.

I can’t see what a timer, high resolution or not, would fit in here. And as the juce timers as far as I know resides in different threads than than the audio thread, any use of them to position events in the audio stream will always give “sync” problems. It just a question of how much you’ll accept.

Now OP doesn’t seem to use the process block in his app, how he puts the midi events timely in the audio stream, I haven’t a clue.

4 Likes
16

@bswh42 - thank you for duplicating my results!

I also tried editing juce_HighResolutionTimer.cpp and trying a startRealtimeThread() or Thread::Priority::highest - and it has no effect. Which I found peculiar.

The problem is indeed deeper.

1 Like
17

i think whether he wants to use/can use process block is one thing, but even apart from that there is clearly as issue that has been introduced with the timer. He already status this is a GUI app so probably doesn’t even have a processBlock() that gets called.

1 Like
18

I could get into a whole discussion about how exactly I am doing things, but that just seems to be secondary to the purpose of the post. I’m sorry I even mentioned it in the first post. I should have just reported the issue without the background.

19

The issue at hand here is :

It worked.

Now it doesn’t.

There is no mention of HighResolutionTimer behaviour being fundamentally altered here either.

1 Like
20

@oli1 checked in the threading changes. I hope he, or another member of the Juce team will look into this.

To me, it looks like the problem may be in the interface between Juce threads and native OS threads. I looked at Win32 threads a long time ago (in the MFC days), and it’s not fun dealing with them.

1 Like
21

I was merely answering Verbonaut s claim

The resolution of any timing you’d get using a process block is dependent on the size of the block the DAW is calling at.

not discussing if OP should or can use the processblock or not.