Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2210. #99
Comments
|
Hi Nick. Many thanks for your very interesting report. On the face of it, it seems that there is a large divergence in the rate at which iTunes on the PC is sending audio and the rate at which the Shairport Sync device consumes the audio, as disclosed by the almost -1,000 ppm correction being made by the algorithm. Quite why this might be so – if it is indeed so – is a bit of a mystery. The log of activity when the source is iTunes on the Mac over WiFi looks perfectly normal. One thing to do is to turn off resync behaviour of Shairport Sync – use If this looks like it might work and you're interested in a bit of detective work, we might follow up to see what seems to be going on in terms of clock rates and drift, etc. Can you say what kind of PC and what kind of audio output device you are using on the PC itself? Is it possible, at all, that there's something special about the PC's clock or its audio output device's clock? |
|
Hi Mike, Thanks for taking the time to give this some thought - I'm more than happy to do some detective work. You've done a great job with shairport-sync and if we can solve my problem I'd be very grateful. I can't test anything right now as I'm at work but I have tried -r=0 before and this does eliminate the dropouts but the audio tends to drift out of sync with other output devices over time. Particularly if the audio has been running for a while. The PC is a self build HTPC. Audio output is PCM over HDMI through an ATI HD 4000 series graphics card. I'll have a look at the sample rate settings in iTunes and windows audio output when I get home if you think that might be something to do with it. I'll also run a log with -r=0 and see what output that gives just to test it again. Thanks, Nick |
|
Hi Nick. Thanks for the reply, and I'd be interested in that log. |
|
Hi Mike, I've tried -r=0 and played a whole album (approx 45 minutes). Link to log here: https://www.dropbox.com/s/noze7gadc10cbba/shairport-synclog.txt?dl=0 This stops the audio drop outs (confirming they are caused by the sync process) but the audio now drifts out of sync. The drift was in both directions - shairport-sync at first went ahead of the other audio output and and then went behind. You can see the change in the log. The audio drifted out of sync by over a second. I've also tried changing the audio sample rate on the PC sound card and iTunes from 48kHz to 44.1kHz (which matches the file) with no difference and I've also tried disabling the sound device in windows so iTunes was only able to use Airplay output devices - again with no difference. I've tried this with a Raspberry Pi B+ connected to HiFiBerry DAC+ (I2C DAC) running Pi Musicbox which comes with shairport-sync pre-installed with the image. I've also tried this with a Raspberry Pi 2 running Raspbian and the latest version of shairport-sync installed from git today connected by HDMI. The results are exactly the same on both so I think we can rule out anything to do with hardware or software on the Pi. Please let me know if there's any more info you'd like. Your help and efforts are very much appreciated. Regards, Nick |
|
I've done some further tests with iTunes output on my windows PC connected to combinations of 4 output devices: 2 Raspberry Pis running shairport-sync, system sound over HDMI and an official Airplay supported Amplifier.
It seems there is something different about the timing output from the PC compared to the Mac which is handled differently by Shairport-sync than it is by the official Airplay devices but it is handled sufficiently well for 2 instances of shairport-sync to remain syncronised providing -r=0 is used. It would be great if we could get this figured out. Regards, Nick |
I guess the problem is caused by the PC. We did a lot of investigation in #89 and I can confirm that shairport-sync is working properly. Please verify the clock on your PC and the clock that is used to drive the sound card. What clock is used? How is the clock for the sound card generated? |
|
Hi Nick. I just plotted the net corrections, and you can see the result below. It's quite intriguing. A possible interpretation is that much the time, the stuffing algorithm is saturated trying to compensate for a source clock considerably faster than the Shairport Sync clock, and then the rest of the time, it's saturated trying to compensate for a source clock that's way slower than the Shairport Sync clock. It would be very interesting to log the clock drift figures as was done in the reference @joerg-krause makes. I guess the data would indicate that the clock on your PC exhibits long-term stability but considerable short-term inaccuracy that is adjusted periodically. If you are willing to do an experiment to gather the data, the first thing would be to download and compile the latest version of Shairport Sync in the I was wondering about why this should show up in Shairport Sync and not with AirPlay, and I can only make a guess: with true AirPlay devices, the output rate of the output device can be adjusted to match the incoming rate, whereas with Shairport Sync, the output rate is fixed, and the incoming data is either stuffed or stripped to match it. I put a limit of about 1,000 ppm in the range of adjustments because I thought that anything above that would actually be audible as a tone shift, and not just as an occasional crackle. My reasoning was as follows: in music, the key A4 is defined to be 440 Hz. However there is plenty or argument about whether it should be a few hertz higher or lower. It follows that some people must be able to hear a tone difference of around 4 parts per thousand, so anything approaching that would be unacceptable. |
|
[Update] Actually, there is another explanation for the sudden switchover from stripping to stuffing – a buffer overflow. When you look at the log, it seems that audio is coming in so fast that the audio buffers in Shairport Sync – 512 of them – overflow (the normal usage is around 260 maximum). So, trying to ignore that, we have an apparent situation where the PC is producing data at a rate very much higher than nominal. Trying to develop something from the data you posted, statistics are gathered for every 3,758 packets and each packet has 352 frames. Taking statistics from before the buffer overflow only, and adding back in the corrections made, I get the following graph:
So it looks like the clock on your PC is running about 2100 PPM (0.0021%) faster than it should. Is that plausible at all? It would much nicer to get the straight clock drift rather than infer it like this, TBH, but it does indicate something odd. Whadda think? |
|
Thanks Mike, |
|
Hi Nick. The diagnostics I referred to earlier seem to provide two figures for clock divergence ("drift"). One should give the divergence between the source system clock (i.e. the PC system clock) and the local system clock (i.e. the Shairport Sync computer clock). The other seems to give a divergence between the iTunes clock and the source clock, so if you use iTunes, we may get an understanding of both types of drift. I say "seem" because I'm fairly sure -- but not certain -- of my interpretation ;) |
|
Hi Mike. Diagnostics available here: First is shairport-sync running default options playing iTunes audio from my Mac (as a benchmark) for a couple of minutes. I don't know exactly what the numbers are (I'm sure you'll enlighten me) but they seem to match your theory of the PC clock running faster than it should running steadily out of sync always in the same direction. Cheers, Nick. |
|
Hi Nick. Many thanks for this data. First, the numbers on a row are:
Apart from the first few rows, each row is three seconds apart, so it's possible to work out trends, etc. The first graph is Mac to Shairport Sync. It all looks pretty good. I've omitted (3) and (5).
The second graph is the PC to Shairport Sync with -r=0. This seems to show a PC system clock running about 2,200 ppm faster than the SS system clock. It shows that the algorithm is correcting by about 1,000 ppm, with the source DAC drift of about -80 ppm (same as with the Mac, as you'd expect, as it's independent of SS), with the net situation being that audio is coming in about 1,150 ppm faster than the algorithm is coping with.
It would be great to get some kind of independent evidence that this is a valid interpretation. If this is a proper interpretation, then it seems to me that if you played a piece of music on iTunes the Mac alone that lasted about an hour, and if you placed the identical piece on iTunes on the PC alone, the time difference should be measurable using a stopwatch; after all, 3,600 * 2.25 ÷ 1,000 comes to 8.1 seconds. Do you think you could do that kind of test? Does it sound reasonable? If it all turns out to be true, we can allow Shairport Sync to be more aggressive in making corrections – up to 0.3% should be possible without altering the code. |
|
Hi Mike, Thanks for your explanation of what is going on with the timing. Am I right in thinking the aim is to get the orange line (shairport-sync corrections) to follow the yellow line (audio as output by the DAC on the source machine)?. A clock running too quickly on the PC seems to describe the symptoms perfectly. The clock is so out of step that it is beyond what shairport-sync is programmed to adjust the audio by so without -r=0 it hits the re-sync threshold every 30 seconds or so. With -r=0 it just fails to keep up with the amount of adjustments necessary (the gradient of the green line in the second graph is as steep as it is permitted to be but it needs to be steeper). So, convinced we'd found the problem I've conducted the experiment you suggested. I ripped a whole album from CD to 1 continuous Apple Lossless file using default settings of 44.1kHz and 16bit stereo. This would eliminate any gaps between tracks giving false readings. I copied the same file to my PC and MacBook and started playing them both in iTunes on the respective machines. The PC connected by HDMI to my amp and the MacBook playing through inbuilt speakers. I managed to start the two off in perfect sync and 50 minutes later as the album drew to a close..... They were still in perfect sync. Impossible to detect even the slightest variation. So... I thought what's different to how we've been getting the problems? The PC is not doing Airplay! So, I started the experiment again but this time with the PC outputting to an Airplay device too. Started the Mac and PC off in perfect sync and bingo! After only 1-2 minutes you could clearly hear the PC output was running ahead of the Mac. I timed the difference at about 3.1 seconds at 26 minutes - approx 2000ppm - pretty close to what we were seeing in the shairport-sync logs. So there you have it - regular sound output on my PC is fine but start Airplay up in iTunes and it suddenly starts racing through tracks 0.2% quicker than it should. The 0.3% you mention in your last post should cover this - how can I go about enabling this for testing? Do you have any idea why iTunes would start playing audio so much quicker when Airplaying audio when regular playback seems to be at the right speed? Thanks for all the work you do on this, both for myself and everyone else who is able to benefit. It's also proving most interesting for me in understanding how it all works too. Cheers, Nick |
|
That's quite a discovery, Nick, and thanks for your work, which must have taken some time! I never would have imagined that the timing was different between using the local output and using AirPlay, so I would have given up at the first hurdle. You experiments tend to confirm the nature of the problem, which is that the PC's system clock is running too fast. TBH, I have no idea why this should be so. What's supposed to happen is that every three seconds, the AirPlay device asks the iTunes source for its time now. The AirPlay device uses the returned value to calculate a source-to-local conversion factor, which varies over time due to drift. I don't know how the iTunes source generates the time value that it returns, but I was guessing it was the regular system clock. Separately, to allow Shairport Sync to compensate for up to (I think) 0.028% drift, comment out lines 1012 to 1016, inclusive in I'll write a comment on interpreting the graph later – it's a bit complicated, I think... |
|
... As promised, here is an account of the graphs. The important figure is always the Corrections figure. All the other numbers are for general sanity checking – for example "does the drift between global and local clocks make sense?" and so on. First of all, there is the divergence between the source system clock (e.g. the iTunes computer's clock) and the local clock – the Shairport Sync computer's clock. Let's call this the Global Clock Drift, or simply the Clock Drift. I think that if both clocks are of good quality – i.e. having not more than half a second per day of inaccuracy with respect to real time – this should not be greater than about 25 ppm. However, the clocks in some devices, e.g. the Raspberry Pi, are much less accurate, so I'd say the drift should not exceed about 200 ppm. More than that suggests a problem, IMHO. Next, there is the divergence between the audio source and the source clock – in other words, it appears that the protocol allows for the audio source to run faster or slower than the source system clock. Let's call this the Global DAC Drift, or simply the DAC Drift. This facility seems to be used by iTunes but not by AirPlay. To summarise, the overall divergence between the source device and the local system clock is given by the sum of the Clock Drift and the DAC Drift. We can use this information to calculate very precisely when, on the local (Shairport Sync) device, any frame of audio should be output. Now, if the local output device (the "Local DAC”) was clocked relative to the local computer clock, we could actually calculate how much of an adjustment to make using the Clock Drift and the DAC drift. This would be the case, I believe, with an output device like a Pi-DAC, which is clocked by a derivative of the local computer clock. In such a case, the sum of Clock Drift, DAC Drift and Corrections (i.e. the “Net”) should equal zero. See this graph, for example: https://cloud.githubusercontent.com/assets/4265913/8455736/bd1b2732-1ffe-11e5-853e-e7a853cdcda5.jpg where 'Trend 4' is the "Net" outcome. In general, however, and particularly for USB-connected DACs, the Local DAC has its own internal clock and we have no direct access to it. The only way we can infer anything about it is by monitoring the rate at which it consumes frames of audio, nominally 44,100 frames per second, and this is what Shairport Sync does. Shairport Sync 2.3 and later releases frames of audio to the Local DAC at precisely the right time to have a buffer of a particular size (6,615 frames by default) in the Local DAC. If the rate at which the frames are released to the buffer is the same as the rate at which they are taken from the buffer to be played, then that means the Local DAC is running at the same rate as the source. If the size of the buffer is tending to increase, the Local DAC is not keeping up with the input and so we remove a frame from the buffer occasionally. Conversely we will add a frame if the buffer is tending to decrease in size. The upshot of all this is that the rate of correction is dependent specifically on the difference between the rate at which audio is produced at the source and consumed by the Local DAC. |
|
Hi Mike, Thanks for the info on how everything works. I've been using the development branch with 1012 to 1016 commented out of player.c running on Raspberry Pi B+ attached to HiFiBerry DAC and it is working in perfect sync with either Mac or PC source with all the default options. No dropouts either which were caused by the major re-syncs. I've graphed the clock drift data over around 50 minutes (seconds on the x axis and microseconds on the 7 axis). You can see the PC clock runs fast by around 7 seconds over the course of 50 minutes (about 0.23%) but the corrections done by SS keep up with this. The audio sounds fine, you can't hear the corrections. If I enable soxr "stuffing" then the Pi struggles to keep up with the volume of corrections required when playing from my PC but if fine when playing audio from the Mac (fewer corrections required). If I'm understanding the difference correctly the "default" option would just delete approx. 1 in every 2000 audio frames in my case (about 22 per second) whereas the soxr option deletes the frames and adjusts the frames either side of the deletions to smooth it out. I am still at a loss to explain the cause of the problem on my PC playing audio faster than it should - particularly since the audio plays at perfect speed when not "Airplaying" but I may well try some further experiments with different hardware in the future. May I suggest making this change to your code on a permanent basis? Unless there is some reason I've missed as to why the audio adjustments (from insertions and deletions) need to be limited to approx 1/1000 frames? Thanks for all your help in getting to the bottom of this problem for me and for providing such a fantastic multi-room audio solution. I've found all the tinkering at my end quite fascinating too. Regards, Nick |
|
Thanks Nick – I'm glad it's worked out, and thanks for your help. I will incorporate the change alright, since it seems useful, but I might try to throttle it for the first thirty seconds or so, to prevent an over-abrupt correction. Regards |
|
Hi Nick. I've incorporated a version of the change in 2.3.12. Basically it allows full correction after about 30 seconds. I'd be glad of your view of it, if you can get the time. Regards |
|
Hi Mike, I've just downloaded and installed the latest development release (2.3.12) with all the default options and without making any changes to the source. All working perfectly with my set up - multiple outputs staying in sync with both Mac and PC iTunes and working fine with iOS too. No audible drift in the first 30 seconds either. Thanks again for working on this fix and for doing such a great job with shairport-sync. Regards, Nick |
|
Thanks Nick. |
Hi Mike,
Hope you can help me with this one.
My setup: - raspberry pi running shairport-sync (wifi but have tried ethernet with no difference)
My problem: iPhone, iPad and Mac all stream audio to shairport-sync perfectly. iPhone, iPad, Mac and PC all stream airplay audio to my Airplay compatible Amplifier perfectly. Mac is able to airplay to amplifier and shairport-sync at the same time in perfect synchronisation with no drop-outs - it works great. However, whenever I airplay audio from iTunes on my PC to shairport-sync I get audio dropouts every 30-60 seconds or so. This is a copy of the shirport-sync output with -v and --statistics options. First streaming audio from windows iTunes and secondly streaming from my Mac. Each "Lost sync with source for 4 consecutive packets -- flushing and resyncing" error message results in a pause in sound output while it re-syncs. The Mac output, although it has several late packets, is perfect.
new RTSP connection.
Play connection from "iTunes/12.2 (Windows; Microsoft Windows 7 x64 Home Premium Edition Service Pack 1 (Build 7601); x64)".
Connection from IPv4: 192.168.1.2:22045
Sync error: 630.9 (frames); net correction: -991.1 (ppm); corrections: 991.1 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5767, min and max buffer occupancy 262 and 269.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2276.
Sync error: 1065.0 (frames); net correction: -930.6 (ppm); corrections: 930.6 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5962, min and max buffer occupancy 263 and 270.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2338.
Sync error: 1268.1 (frames); net correction: -1013.0 (ppm); corrections: 1013.0 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5829, min and max buffer occupancy 263 and 271.
Sync error: 993.6 (frames); net correction: -1016.8 (ppm); corrections: 1016.8 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5978, min and max buffer occupancy 263 and 269.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2288.
Sync error: 1008.0 (frames); net correction: -948.0 (ppm); corrections: 948.0 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5992, min and max buffer occupancy 262 and 271.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2228.
Sync error: 1054.3 (frames); net correction: -923.0 (ppm); corrections: 923.0 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5607, min and max buffer occupancy 262 and 270.
Sync error: 1213.6 (frames); net correction: -981.2 (ppm); corrections: 981.2 (ppm); missing packets 0; late packets 0; too late packets 0; resend requests 0; min DAC queue size 5737, min and max buffer occupancy 264 and 270.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2210.
RTSP shutdown requested.
closing RTSP connection.
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing RTP thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
new RTSP connection.
RTSP connection closed.
closing RTSP connection.
new RTSP connection.
Play connection from "iTunes/12.2.1 (Macintosh; OS X 10.10.4)".
Connection from IPv4: 192.168.1.42:50850
Sync error: -56.1 (frames); net correction: 12.1 (ppm); corrections: 12.1 (ppm); missing packets 0; late packets 1; too late packets 0; resend requests 1; min DAC queue size 6011, min and max buffer occupancy 258 and 264.
Sync error: -83.6 (frames); net correction: 48.4 (ppm); corrections: 48.4 (ppm); missing packets 0; late packets 1; too late packets 0; resend requests 1; min DAC queue size 5318, min and max buffer occupancy 258 and 264.
Sync error: -82.5 (frames); net correction: 48.4 (ppm); corrections: 48.4 (ppm); missing packets 0; late packets 2; too late packets 0; resend requests 2; min DAC queue size 6000, min and max buffer occupancy 258 and 264.
Sync error: -84.1 (frames); net correction: 60.5 (ppm); corrections: 60.5 (ppm); missing packets 0; late packets 3; too late packets 0; resend requests 3; min DAC queue size 6093, min and max buffer occupancy 258 and 264.
Sync error: -79.7 (frames); net correction: 40.1 (ppm); corrections: 40.1 (ppm); missing packets 0; late packets 3; too late packets 0; resend requests 3; min DAC queue size 5942, min and max buffer occupancy 258 and 264.
Sync error: -84.1 (frames); net correction: 52.2 (ppm); corrections: 52.2 (ppm); missing packets 0; late packets 3; too late packets 0; resend requests 3; min DAC queue size 5901, min and max buffer occupancy 258 and 264.
Sync error: -83.3 (frames); net correction: 54.4 (ppm); corrections: 54.4 (ppm); missing packets 0; late packets 3; too late packets 0; resend requests 3; min DAC queue size 5900, min and max buffer occupancy 258 and 264.
Sync error: -81.5 (frames); net correction: 54.4 (ppm); corrections: 54.4 (ppm); missing packets 0; late packets 5; too late packets 0; resend requests 5; min DAC queue size 5994, min and max buffer occupancy 257 and 264.
RTSP shutdown requested.
closing RTSP connection.
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing RTP thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
I have disabled the firewall in Windows but am still getting the same problem. I have tried with raspberry pi connected to WiFi and ethernet but it makes no difference. Do you have any ideas or at least some pointers as to where I should look? It seems strange that the PC is able to output sound perfectly to my other Airplay device.
Thanks,
Nick
The text was updated successfully, but these errors were encountered: