Dropouts when fetching time from NTP server [Resolved - Update to High Sierra]

Support
1

Hi,

I have a dedicated Windows 10 PC running Roon server and playing to Sonore microRendu, which is connected to my DAC (Marantz SA-10) with USB. Both PC and microRendu are in the same local network connected by a switch. Software versions should be the latest ones available.

Everything is working fine, with no audio dropouts, except when Roon fetches time from an NTP server. This seems to be causing dropuots, either a short silence, or the music stops and starts again from the next song on the playlist. I usually play flac/dsd files from a local storage. Please, see below for a log file example (I masked the IP address with xxx):

06/20 20:43:08 Trace: [realtime] fetching time from NTP server
06/20 20:43:08 Trace: [realtime] Got time from NTP: 20.6.2017 17.43.08 (3706969388203ms)
06/20 20:43:08 Trace: [realtime] Updated clock skew to -00:00:00.0066157 (-6,6157ms)
06/20 20:43:10 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":82168}
06/20 20:43:11 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:11 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:12 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:12 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:13 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:13 Trace: [transport/raatclient] [Sonore microRendu @ 192.168.xxx] GOT [7] {"status":"Dropout","samples":1411200}
06/20 20:43:13 Warn: [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
06/20 20:43:13 Trace: [zoneplayer/raat] too many dropouts. stopping stream

How could I solve this problem? Other than this, I can play for hours with no problems.

2

Is that about 6s adjustment or 60s? It’s a bit ambiguous with the comma followed by four digits. Seems like maybe Roons talking to NTP but not expecting the clock change?

3

As I read it, it is adjustment of about 6.6 ms.

4

Hi @AnttiT ----- Thank you for the report and sharing your observations with us, the feedback is always appreciated!

Moving forward, can you verify/provide the following information for me to help aide in my evaluation of this behavior you’ve reported:

  1. Please provide the make, model, and specs of the Win10 PC hosting your core.

  2. Please confirm the make and model of the switch that you are implementing.

" Both PC and microRendu are in the same local network connected by a switch."

Furthermore, I always find that when addressing dropouts the best course of action is to shorten the chain of communication between your devices, see if the behavior is reproducible, and if it is not, start to expand back out. With this in mind, have you by chance tried connecting the Rendu directly to your router during your troubleshooting of this issue? If so , what was the experience like?

-Eric

5

Hi,

Thanks for your help. Here is some data.

  1. PC is built by me using: Asus ROG STRIX Z270I Gaming motherboard, Intel i7-7700T, 2 x 8GB Kingston HyperX Fury 2400MHz CL15, Samsung 500GB 960 EVO SSD M.2 NVMe. It is running Windows 10 Home 64 bit. Music files are stored in a Melco N1A.

  2. PC, Melco and microRendu are all connected to a ZyXEL GS-108B V3 switch with fixed IP addresses in my local network.

A direct connection to my router has not been tested and, unfortunately, it would not be an easy test to do. I hope that these information help to solve the problem.

6

Hi @AnttiT ------ Thank you for touching base with me and providing the requested feedback, both are appreciated!

I wanted to let you know that I can certainly check with our devs about the fetching time from the NTP server, but I would like to point out that this behavior you are experiencing is most likely related to something environmental and in my most humble opinion, the logical next step(s) should be to isolate some variables to determine where this issue is occurring.

Moving forward with the above in mind, I would like to have you run two very small tests:

  1. I would like to (temporarily of course), remove the Melco N1A from the equation and ask you kindly to please try to reproduce this behavior with some locally stored content on the PC hosting your Roon core. If there is an album or track(s) that you know suffer from dropouts constantly, this will be the media to test with.

  2. While performing the above test, I would also like you to please bypass the Marantz SA-10 zone and play directly out of the internal speakers on the PC.

FYI: More information on diagnosing and troubleshooting dropouts can be found in our knowledge base.

Let me know how it goes!
-Eric

7

Hi,

I most certainly will do some tests as suggested but due to holidays it may take some time before I am able to do it. Meanwhile, it would be interesting to know if the time fetching from NTP server could somehow be disabled in Roon. Is there some setting for this, can I block it from firewall etc? Also, what NTP server is Roon using, is it the one defined in Windows for system time or something different?

PS. these dropouts are not specific to any particular files or formats, I usually can listen for hours with only one dropout problem and when I check the log file, I can see that it happened right after Roon updated the clock skew.

8

Hi,

I have now stored all my music content locally (SSD drive) on the PC running Roon server but the same problem remains: fetching time from NTP server causes dropouts. Other than that, everything is working fine. Can you, please, tell me, what is the NTP server Roon is using and is there a way to change/disable that?

Yours,

Antti

9

Hi @AnttiT ----- Thank you for touching base me with me and sharing the observation you have made with your musical content stored locally. Sorry to hear of the continued troubles.

Moving forward, may I very kindly ask you to please reproduce the issue, note the time when the observation is made (i.e receiving dropouts), and then using the instructions found here to send us a set of logs.

Lastly, I would like to also ask you to please conduct a small test to see if we can trigger a change in behavior here. Could you please disable the internet access on your core machine and try to playback some of your locally stored musical content. Please note that being as this machine will not be communicating with your network, I would recommend performing this test either with the internal speakers of your Roon core or with a pair of directly connected head phones.

-Eric

10

Have you tried connecting the Marantz SA-10 directly to the Windows 10 PC running Roon Server?

1 Like
11

Hi,

I am having a nearly identical problem in a very different configuration.
I am running ROON on the latest Mac Mini Mac OS 10.12.6, the ROON app and database are on the internal SSD.
All my music is on an external Thunderbolt 2 drive connected to the Mac Mini
My DAC is an original Peachtree Nova using the USB connection to the Mini
Music files are 16/44 AIFF.
Drop outs only and always occur after “fetching time from NTP” while music is playing. The problems occur very infrequently, a few times a week.
One difference is that in my case time goes backward 3 to 5 seconds in the log. Here is one recent example (from build 262. Note that the log time goes from 15:04:14 to 15:04:09);

09/09 15:04:12 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 4:12/7:23] As It Is Before - Earth Opera
09/09 15:04:14 Info: [stats] 3736mb Virtual, 979mb Physical, 337mb Managed, 47 Threads, FDs
09/09 15:04:09 Trace: [realtime] fetching time from NTP server
09/09 15:04:09 Trace: [realtime] Got time from NTP: 9/9/2017 10:04:09 PM (3713983449516ms)
09/09 15:04:09 Trace: [realtime] Updated clock skew to -00:00:00.0414560 (-41.456ms)
09/09 15:04:12 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:15097,“status”:“Dropout”}
09/09 15:04:13 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:22050,“status”:“Dropout”}
09/09 15:04:13 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:22050,“status”:“Dropout”}
09/09 15:04:14 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:22050,“status”:“Dropout”}
09/09 15:04:14 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:24255,“status”:“Dropout”}
09/09 15:04:15 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:22050,“status”:“Dropout”}
09/09 15:04:15 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“samples”:22050,“status”:“Dropout”}
09/09 15:04:15 Warn: [Nova] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream

I’ve had similar problems with previous builds. Can provide more info if needed. Hope this helps.

12

@support not sure if I posted the above item correctly. But I am having a very similar problem to the original post. Should I have started a new thread?

13

Hi @Inner_ear ----- Thank you for the report and sharing your feedback with us.

Moving forward, I brought your report up in a meeting yesterday with my techs and they don’t believe that the NTP server is causing this issue. In light of their feedback, I set up a quick test scenario which I have been running all day without any issues (Macbook pro Core, Library on an external drive, Peachtree Nova65SE).

During your troubleshooting, have you tried hosting some 16/44 content on the internal storage of the MacMini to confirm if you still have dropouts with the the mentioned Thunderbolt 2 drive temporarily removed from the equation?

Knowledge Base: Troubleshooting Audio Dropouts

-Eric

14

Hi @Eric

Thanks for your response.
I just hosted some tunes on the the internal SSD and will give them a spin.
As the occurrence of the dropouts is intermittent and infrequent it could take a while.
I will let you know what I find out.

-Ron (aka Inner_ear)

15

That detail is super suspicious. I don’t remember it from the call that @eric mentioned–but it makes me think about this theory very differently.

Inside Roon, we pay attention to clocks–the system clock, and "real time’–which is based on our private NTP interactions.

We do the private NTP interaction to protect our cloud services from people with bad system clocks. We want to be sure that certain timestamps can be trusted within a known margin, and that they aren’t broken by someone who’s motherboard battery sent them back to 1970, or something like that. So we do our own time sync + manage that internally to Roon in a place that’s safe from that kind of error.

However–we don’t use that information at all for anything related to audio playback. It’s used in a few critical places related to communication with cloud services–that’s it. That’s why the idea–at first–that our NTP exchange was impacting audio playback made no sense.

But–we also don’t use our private NTP-derived clock for log timestamps. Those come straight off of the system clock.

So this is what’s concerning–your log timestamps changed right around the time of the NTP exchange–but the log timestamps are directly derived from the system clock. We don’t change the system clock as a result of our NTP interaction–we just record the skew privately. This means that your system clock moved by a few seconds. Right when we did the sync. But not because we were mucking with the system clock.

This makes me think–maybe Windows is seeing the NTP response packet from our private interaction and acting upon it by changing the system clock without our intent/knowledge. That could potentially have impact on playback, since we use the system clock to perform short-term interpolation as part of the clock recovery algorithm used by RAAT.

If this is what is happening, this is pretty gross behavior for Windows to have. I’m sure we can re-work the playback stuff to prevent it from being affected, but I still don’t want our private communications with an NTP server to have global impact on the system…

We’ll be investigating further. Thanks for the report.

16

I believe this is an all-Apple system and so it would be OS X sneaking a peek at your NTP packets, not Windows.

Doug

17

Ok. It looks like we are doing an NTP update because the system clock moved for some outside reason. We use system clock changes as a cue to re-check with the time server. So back to the original interpretation–our NTP check is an effect, not a cause.

Any idea why your system clock is hopping around several seconds at a time? That’s a huge amount of drift for a typical NTP-managed system.

I think we can do more to isolate the system clock from playback…there are some platform specific complexities to deal with here. That will fix the problem on our end…but those big adjustments are still concerning.

18

Hi all, here is an update on my end.

First there was another dropout since my initial report. The music was on the external Thunderbolt drive. Again, it happened right after fetching time from the NTP server. However, in this case the Roon log time did not go backward.

Based on Eric’s question I copied 9+ hours of 16/44 AIFF files onto my internal SSD. According to the log and history everything played correctly. It looked like time was fetched from the NTP server about 6 hours into the session while music was playing. I then played the same files on the external thunderbolt 2 drive and got the same results. There were no dropouts and no time anomalies. I am retrying the test today.

I did make one configuration change last week, I changed the Mac Mini internet connection from Wi-Fi to a wired Ethernet connection. Unfortunately, I do not remember exactly when I did it. So, I am not sure if the last dropout happened before or after that. After I finish my retest of playing music from the external drive, I will switch back to Wi-Fi and see if the dropouts return.

Finally, if I see another instance where the log time goes backward, I will check the Mac OS system logs to see if they reveal anything.

Ron (aka Inner_ear)

1 Like
19

Correction -

I was wrong, the last dropout incident did have time go backwards at least 10 seconds. So in every case I have seen (that is have log for) there is a time anomaly before the dropout. This is consistent with your analysis that something is going on with time on my Mini which triggers an NTP server request by Roon. For your reference here is the log extract for the last dropout

09/14 16:52:06 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 1:55/2:15] We Can Work It Out - The Beatles
09/14 16:51:56 Trace: [realtime] fetching time from NTP server
09/14 16:51:57 Trace: [realtime] Got time from NTP: 9/14/2017 11:51:56 PM (3714421916972ms)
09/14 16:51:57 Trace: [realtime] Updated clock skew to -00:00:00.0379600 (-37.96ms)
09/14 16:51:57 Info: [stats] 3730mb Virtual, 952mb Physical, 301mb Managed, 44 Threads, FDs
09/14 16:51:59 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:11203}
09/14 16:52:00 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:22050}
09/14 16:52:00 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:22050}
09/14 16:52:01 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:22050}
09/14 16:52:01 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:24255}
09/14 16:52:02 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:22050}
09/14 16:52:03 Trace: [USB Audio DAC ] [raatclient] GOT [17] {“status”:“Dropout”,“samples”:22050}
09/14 16:52:03 Warn: [Nova] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream

Since that incident I have been unable to recreate the problem. Roon seems to be checking pool.ntp.org every 6 hours. Mac OS (Mac process ntpd) is making frequent checks of time.apple.com. The intervals I have seen on checks of time.apple.com vary from a little over 1 minute to around 18 minutes. I have not determined why system time on my Mini went backward 3 to 10 seconds.

Ron

20

After a week of heavy use a new incident with similar but different symptoms and log sequence.

09/21 12:42:53 Debug: [library/index] updating search indices: 8 ops 0 adds, 0 removes
09/21 12:42:53 Info: [Nova] [zoneplayer] Queueing: /Volumes/Music 3TB/iTunes/iTunes Music/Music/Klaus Thunemann_ I Musici/Vivaldi_ 6 Bassoon Concertos/14 Vivaldi_ Bassoon Concerto In C, RV 473 - 2. Largo.aif
09/21 12:42:54 Info: [Nova] [zoneplayer] Open result (Queueing): Result[Status=Success]
09/21 12:42:54 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/200 sec
09/21 12:42:54 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 0:00/3:25] Bassoon Concerto, for bassoon, strings & continuo in C major, RV 473: Allegro - Klaus Thunemann: I Musici / I Musici / Antonio Vivaldi (1678-1741)
09/21 12:42:54 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“status”:“Dropout”,“samples”:7777}
09/21 12:42:55 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“status”:“Dropout”,“samples”:22050}
09/21 12:42:55 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“status”:“Dropout”,“samples”:22050}
09/21 12:42:56 Trace: [USB Audio DAC ] [raatclient] GOT [7] {“status”:“Dropout”,“samples”:15435}
09/21 12:42:59 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 0:10/3:25] Bassoon Concerto, for bassoon, strings & continuo in C major, RV 473: Allegro - Klaus Thunemann: I Musici / I Musici / Antonio Vivaldi (1678-1741)
09/21 12:43:01 Info: [stats] 3748mb Virtual, 922mb Physical, 262mb Managed, 72 Threads, FDs
09/21 12:43:03 Debug: KEYDOWN: SPACE

In this case there was a very brief (on the order of 1 second) audible dropout of playback of the track a few seconds after it started. After the dropout, playback resumed on the same track. At the same time as the dropout, Roon sent data to pool.ntp.org, but no data was read back. Also, the NTP request was not recorded in the log. I could see that the MacOS process ntpd had sent and received data from time.apple.com frequently including less than 10 seconds before the incident.

I suspect that system time did go backward again. I deduce that based playback of the track starting at 12:42:54

09/21 12:42:54 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 0:00/3:25] Bassoon Concerto, for bassoon, strings & continuo in C major, RV 473: Allegro - Klaus Thunemann: I Musici / I Musici / Antonio Vivaldi (1678-1741)

And then resuming 6 seconds later 10 seconds into playback at 12:42:59

09/21 12:42:59 Trace: [Nova] [Lossless, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 0:10/3:25] Bassoon Concerto, for bassoon, strings & continuo in C major, RV 473: Allegro - Klaus Thunemann: I Musici / I Musici / Antonio Vivaldi (1678-1741)

I was under the impression that an audible dropout was not supposed to happen in this scenario in this way. I thought it would either play uninterrupted or it would stop the current track and resume on the next one. Also, it is curious that the Roon NTP query was not logged and failed to get a response.

I have searched the MacOS logs and they are inconclusive; I could not find any indication a time anomaly occurred nor did I find any time stamped records when the anomaly apparently occurred.

I hope this is helpful.

Ron