[popcornmix]

Wait another idea: Can you change SetSilenceTimer() to always return infinite? So that we "never timeout"?

Played the 12m track without a dropout.
Running again. Nope, got a dropout. Again visualisation pause was visible.

Added this commit to disable SetSilenceTimer.
Log file (sorry - too big for the normal paste sites).

Dropout occurred here (line 138256)

Code:

18:13:22 6262.822266 T:1971082320  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::TIMEOUT S_TOP_CONFIGURED_SILENCE

[fritsch]

We need FernetMenta's visualization of the state machine to find out why we end up in this state at all ...

[FernetMenta]

If you end up with output of silence, sink was close to run dry. after OutputSamples https://github.com/popcornmix/xbmc/blob/...k.cpp#L326
AE sets a timer to delay / 2. Within that time it expects a new buffer from AE. Actually it should never get into this state because the next buffer should already be queued. AE queues buffers until WaterLevel reaches a threshold of .25 sec. In this case here there should be always 4-5 messages queued for ActiveAESink.
For further investigation you can log delay (the link above) and CEngineStats::GetWaterLevel

[popcornmix]

Added logging commit.

Failed earlier, so can pastebin this log

Code:

19:49:51 657.027710 T:1971844176  NOTICE: ---------------- delay: 99 GetWaterLevel:0.050000
19:49:51 657.027771 T:1971844176  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::SAMPLE
19:49:51 657.028076 T:1971844176  NOTICE: ---------------- GetDelay: 99.041667
19:49:51 657.028137 T:1971844176  NOTICE: ---------------- AddPackets: 50.000000
19:49:51 657.036682 T:1971844176  NOTICE: ---------------- GetDelay: 140.416667
19:49:51 657.077026 T:1971844176  NOTICE: ---------------- AddPackets: Slept for 40 ms
19:49:51 657.077820 T:1971844176  NOTICE: ---------------- GetDelay: 99.354167
19:49:51 657.077881 T:1971844176  NOTICE: ---------------- delay: 99 GetWaterLevel:0.000000
19:49:51 657.127197 T:1971844176  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::TIMEOUT S_TOP_CONFIGURED_SILENCE
19:49:51 657.127625 T:1971844176  NOTICE: ---------------- GetDelay: 49.520833
19:49:51 657.127747 T:1971844176  NOTICE: ---------------- AddPackets: 50.000000
19:49:51 657.137085 T:1971844176  NOTICE: ---------------- GetDelay: 90.062500
19:49:51 657.137329 T:1971844176  NOTICE: ---------------- GetDelay: 89.750000
19:49:51 657.137451 T:1971844176  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::TIMEOUT S_TOP_CONFIGURED_SILENCE

[FernetMenta]

you see that water level goes down from 200ms to 0 and then sink outputs silence. next I would add a log to the other end where player adds packets to the stream.

[popcornmix]

Added logmessage, and:
http://paste.ubuntu.com/10700497/

So, looks like paplayer goes awol causing the stutter. Any suggestions for where to log next?

[popcornmix]

Added extra log message. Got:
http://paste.ubuntu.com/10700697/

I don't understand this sequence:

Code:

12:17:49 59934.957031 T:1971926096  NOTICE: ---------------- delay: 99 GetWaterLevel:0.050000
12:17:49 59934.957031 T:1971926096  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::SAMPLE
12:17:49 59934.957031 T:1971926096  NOTICE: ---------------- GetDelay: 98.750000
12:17:49 59934.957031 T:1971926096  NOTICE: ---------------- AddPackets: 50.000000
12:17:49 59934.964844 T:1971926096  NOTICE: ---------------- GetDelay: 139.333333
12:17:49 59935.003906 T:1971926096  NOTICE: ---------------- AddPackets: Slept for 39 ms
12:17:49 59935.007812 T:1971926096  NOTICE: ---------------- GetDelay: 99.625000
12:17:49 59935.007812 T:1971926096  NOTICE: ---------------- delay: 99 GetWaterLevel:0.000000
12:17:49 59935.054688 T:1971926096  NOTICE: CActiveAESink::StateMachine CSinkDataProtocol::TIMEOUT S_TOP_CONFIGURED_SILENCE

First can you explain the water level? How is delay (audio buffered in sink) 99ms, but waterlevel 0?
Note, the timestamps are microsecond. So at 59935.007812 the Pi sink reported it had 99ms of audio.
Then ~50ms later silence is being output? Why do that when we are going to be happy for another 50ms?

[FernetMenta]

GetDelay in this case shows audio buffered in sink. Water level relates to audio buffered in the engine, that's audio queued for processing by ActiveAESink. ActiveAESink pulls data from the input queue (water level) and sends it to the sink. If input is empty, it submits silence to the sink in order to protect from underruns.
Buffers are supposed to fill from bottom to the top, then we are in a stable state.

[FernetMenta]

Then ~50ms later silence is being output? Why do that when we are going to be happy for another 50ms?

we can't wait until buffers of sink ran dry. in general audio drivers don't accept data at any time but only after an interrupt. but this is not this issue here. the engine runs dry which should not happen.

[popcornmix]

we can't wait until buffers of sink ran dry. in general audio drivers don't accept data at any time but only after an interrupt. but this is not this issue here. the engine runs dry which should not happen.

How much buffering is there in the system when using paplayer? Is it just the 200ms inside audio engine?
I've tried with a USB stick and it didn't stutter (not conclusive as it's intermittent), but it might suggest the problem is underrun from network.

dvdplayer can play much higher bitrate files, but it does typically have a few seconds of data bufferered, so can cope with some delay from network.

[FernetMenta]

AE only buffers .25 sec of audio.
Currently there are vfs issues in particular for samba and nfs. I have seen quite a few problem reports related to those. MAybe something went wrong with all the rework on vfs.

[popcornmix]

AE only buffers .25 sec of audio.
Currently there are vfs issues in particular for samba and nfs. I have seen quite a few problem reports related to those. MAybe something went wrong with all the rework on vfs.

It looks like setting buffermode=1 is fixing my issue, so I think the current issue I have is just down to the pretty high bitrate of the file (6Mbit/s), the limited buffering in paplayer and my not-great network (I'm going through a wireless bridge at the moment).

Any other way of increasing buffering in paplayer?

I think there is still another issue. fritsch and MrNice were seeing an issue with local content (and I've seen sink underruns in the past), but I'm not seeing the issue at the moment.

One thing for fritsch/MrNice to try is adding (to config.txt):

Code:

hdmi_samples_limit=384000

You will need a firmware from March 25 or newer to try this (latest Milhouse build would be fine).
That will limit the physical audio rate to 8 channels @ 48kHz (by default it is double this).
This means Kodi (and Pi Sink) can run at e.g. 6 channels @ 96kHz, but audio will be resampled on GPU down to 48kHz (when multichannel).

If this fixes the problem, then there is GPU side problem of getting 6 channels @ 96kHz out through HDMI.
If it doesn't fix it, then the problem is more likely on Kodi end.

[MrNice]

@popcornmix

I did the test:
From fresh image, update to OpenELEC Isengard build #0328

Added in config.txt:
hdmi_samples_limit=384000

Play in file mode, no browsing
1 drop during 1.50 minute
Then change to full screen and no browsing for 2 more minutes
No drop
http://xbmclogs.com/pjwtcoo2n

[fritsch]

@MrNice - could you do the other test as well: Set Output to Fixed, 5.1 channels, samplerate 48000? Does this make it also work?

[popcornmix]

@MrNice can you try this test firmware:
https://dl.dropboxusercontent.com/u/3669...e_nice.zip

and add to config.txt

Code:

hdmi_mai_thresh=0x1412

and let me know if it helps.