Audio dropouts in RC2

Post by **sbooth** » Sun May 06, 2007 6:48 pm

jonof wrote:I've just grabbed the 755 and 764 revisions to upgrade the 632 version I had before and both of the new versions are exhibiting stutters when FLAC or MP3 is being played from my network server (100mbit Ethernet via AFP). 632 does not have the problem under the same conditions.

I split this thread from the other because it has potential to get lengthy.

I've just uploaded a Debug build to http://sbooth.org/files/Play-r769plus-debug.tar.bz2.

Would you play one of the problematic files from start to finish (with no seeking) and then post the Console output in this thread?

Post by **sbooth** » Sun May 06, 2007 7:20 pm

A few other thoughts-

Do the files that exhibit dropouts work properly if played from a local drive?

If they are converted to Apple Lossless, do they play properly over the network?

jonof · Post by **jonof** » Mon May 07, 2007 1:36 am

Before I post the debug chatter, here's what I've found:

Connecting to the music share via SMB gives continuous playback regardless of the Play version and the network traffic shows frequent (probably two per second or so) even-spaced transfers.
Connecting via AFP gives stuttered playback on >r632 and continuous playback on =r632. Network traffic is far more infrequent, and when it does happen, the transfer size is a much larger block.
MP3 is affected the same as FLAC, Vorbis, and Apple Lossless (ALAC converted from FLAC using Max).
Playback from local harddisk is continuous.
Symptoms are the same on my G4 Mac Mini and Core 2 Duo Macbook.

The test track for this output was Kraftwerk - Aéro Dynamik (FLAC 5min4sec). Play configuration and library were erased before running r769plus:

Code: Select all

2007-05-07 11:05:19.732 Play[6809] Loaded 0 streams in 0.000000 seconds (nan per second)
2007-05-07 11:05:19.736 Play[6809] Loaded 0 playlists in 0.000000 seconds (nan per second)
2007-05-07 11:05:19.738 Play[6809] Loaded 0 smart playlists in 0.000000 seconds (nan per second)
2007-05-07 11:05:19.741 Play[6809] Loaded 0 watch folders in 0.000000 seconds (nan per second)
2007-05-07 11:05:25.486 Play[6809] Loaded stream in 0.000000 seconds
2007-05-07 11:05:25.544 Play[6809] Stream insertion time = 0.000000 seconds
2007-05-07 11:05:36.120 Play[6809] MyRenderer returning 384 frames (512 requested)
2007-05-07 11:05:36.132 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.144 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.155 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.167 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.178 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.190 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:36.202 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.463 Play[6809] MyRenderer returning 384 frames (512 requested)
2007-05-07 11:05:47.487 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.498 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.510 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.522 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.533 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.545 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.556 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.568 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.580 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.591 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:47.603 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:05:58.400 Play[6809] MyRenderer returning 128 frames (512 requested)
2007-05-07 11:06:08.989 Play[6809] MyRenderer returning 128 frames (512 requested)
2007-05-07 11:06:19.693 Play[6809] MyRenderer returning 128 frames (512 requested)
2007-05-07 11:06:19.705 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.717 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.728 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.740 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.752 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.763 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.775 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.786 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.798 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:19.810 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.287 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.299 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.310 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.322 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.333 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.345 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.357 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.368 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.380 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.391 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.403 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:42.415 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.131 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:06:53.142 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.154 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.166 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.177 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.189 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.201 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:06:53.212 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:03.777 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:03.789 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:03.801 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:03.812 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:13.983 Play[6809] MyRenderer returning 128 frames (512 requested)
2007-05-07 11:07:14.006 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:14.018 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.898 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:07:23.910 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.921 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.933 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.944 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.956 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.968 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.979 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:23.991 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:24.002 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:24.014 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.103 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:07:34.126 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.138 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.150 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.161 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.173 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.185 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.196 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.208 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:34.219 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:44.622 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:07:54.978 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:54.990 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:55.002 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:55.013 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:07:55.025 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.527 Play[6809] MyRenderer returning 384 frames (512 requested)
2007-05-07 11:08:16.550 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.562 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.573 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.585 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.597 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.608 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.620 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:16.632 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.139 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:08:27.150 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.162 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.174 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.185 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.197 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.209 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.220 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.232 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:27.243 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.122 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.134 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.145 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.157 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.169 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.180 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.192 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.203 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.215 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.227 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:08:38.238 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.492 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.504 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.515 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.527 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.538 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.550 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.562 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.573 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.585 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.596 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.608 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.620 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.631 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:02.643 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.114 Play[6809] MyRenderer returning 384 frames (512 requested)
2007-05-07 11:09:14.137 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.149 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.160 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.172 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.183 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.195 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.207 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.218 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.230 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:14.241 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.480 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:09:25.503 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.515 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.527 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.538 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.550 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.561 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.573 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.585 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.596 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.608 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.619 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.631 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:25.643 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:36.591 Play[6809] MyRenderer returning 384 frames (512 requested)
2007-05-07 11:09:36.603 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:36.614 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:36.626 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:36.638 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:36.649 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.551 Play[6809] MyRenderer returning 128 frames (512 requested)
2007-05-07 11:09:47.574 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.586 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.598 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.609 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.621 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.632 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.644 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.656 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.667 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.679 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:47.690 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:58.987 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:58.999 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:59.010 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:59.022 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:59.034 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:59.045 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:09:59.057 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:10.040 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:10.052 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:21.186 Play[6809] MyRenderer returning 256 frames (512 requested)
2007-05-07 11:10:21.198 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:21.209 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:21.221 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:21.232 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:21.244 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:33.528 Play[6809] MyRenderer returning 304 frames (512 requested)
2007-05-07 11:10:33.551 Play[6809] MyRenderer returning silence (512 frames requested, none available)
2007-05-07 11:10:33.566 Play[6809] Stream update time = 0.010000 seconds

Post by **sbooth** » Mon May 07, 2007 3:26 am

I'm at a loss to explain this.

Especially puzzling is the fact that r632 works without dropouts. I've reviewed the code that changed for the portions that affect playback (only three files at work here: AudioPlayer.m, AudioStreamDecoder.m, and FLACStreamDecoder.m) and nothing has changed as far as how things work, and certainly nothing that would cause this to show up.

Play performs audio buffering internally, with a producer/consumer thread model, using a 128K ring buffer. If there is ever 16K or more available space in the buffer, the producer thread is woken to refill it.

Play decompresses all audio to its 32-bit floating point representation, so for standard 44.1/2-channel audio, 128K equates to approximately 0.371 seconds in reserve.

Is there a network latency issue with AFP that could be causing this? I'm no networking expert.

I guess the next thing to try would be doubling the size of the buffer to 256K and see if that helps.

jonof · Post by **jonof** » Mon May 07, 2007 7:01 am

I just tried something different to see if I could blame the issue on AFP implementations. My music is normally stored on a Linux server running Netatalk for AFP support, and this is the setup that is giving the issues. So, I enabled personal file sharing on my Macbook, copied some FLACs to it, connected to the share from my Mac Mini using AFP, and played the files. The result: no dropouts. The same long period between large spikes of network traffic is there as with Netatalk, but it doesn't seem to be choking Play like Netatalk does. Perhaps Netatalk's server is somehow causing the Mac to block on the read request just long enough that Play underruns. This would take the blame off Play, but I too suspect a larger buffer size would go a long way to solving the problem. I'll see if I can build Play here and tinker.

Jonathon