[herrmeier01]

Debug log with video component included

The problem occurs with deinterleacer "auto" and "off"
- I use build #0109 (same as before)
- I start debugging when the problem occurs time-stamp 19:31
- I stop debugging wait some time and switch off the deinterleacer
- I start debugging time-stamp 19:35
- I switch of debugging and change chanel up and down
- I wait for the problem and enable debugging at time-stamp 20:01

[popcornmix]

I could do with a longer sequence. Ignore disabling deinterlace as that is not a factor.

I'd like you to enable logging, start playback and wait for problem to occur. Leave it running for a short while with the stuttering (e.g. 1 minute).
Post the complete log. Let me know when the stuttering occurred.

I know the log will get big, but otherwise there is a danger the interesting part is excluded.
xbmclog.com can handle larger logs than pastebin. If it's too big for that then use dropbox/google drive.

[herrmeier01]

Ok, debug is running, I hope the SD card is big engough otherwise I have to mount a USB disk as ~/.kodi/temp/

[popcornmix]

You say it goes wrong after 25-30 minutes.
Is that always the case?
Does it sometimes fail much sooner or last much longer?

[herrmeier01]

Exactliy, it happen always after 25-30min, always...
Maybe in one of 10 cases it happen sooner when it happen the seccond time after doing a channel change.
Now 97mb log size after 17min, it happen in another 10min ;-)

[herrmeier01]

Yes, it happen again

[herrmeier01]

Ok, before it happen just 1-2 times a seccond. I didn't stop loggin, not it happen strongly

[herrmeier01]

Here is the logfile as zip

[herrmeier01]

Now it happen again after zapping 22:42h and again at 23:14

[popcornmix]

Here is the logfile as zip

For this log file when did the stuttering start?

[herrmeier01]

It start here with short small stuttering
22:09:15 1561.365112 T:1559036832 ERROR: ffmpeg[5CED03A0]: [ac3] exponent out-of-range

Here begins the heavenly stuttering
22:11:28 1694.715332 T:1559036832 ERROR: ffmpeg[5CED03A0]: [ac3] exponent out-of-range

[popcornmix]

@FernetMena:

Code:

22:09:05 1551.338867 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01008 error:3.851400
22:09:06 1552.338867 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01000 error:3.679771
22:09:07 1553.339478 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01007 error:3.832338
22:09:08 1554.339355 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01019 error:4.069447
22:09:09 1555.339355 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01012 error:3.920610
22:09:10 1556.339355 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01004 error:3.770536
22:09:11 1557.339844 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.00996 error:3.611967
22:09:12 1558.340088 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01005 error:3.787136
22:09:13 1559.340210 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01027 error:4.227142
22:09:14 1560.340942 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01020 error:4.094111
22:09:15 1561.364746 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01010 error:3.876851
22:09:16 1562.366455 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.08495 error:147.684900
22:09:17 1563.389160 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.09796 error:167.017704
22:09:18 1564.389648 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.05995 error:87.497203
22:09:19 1565.389648 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.03856 error:42.999514
22:09:20 1566.389771 T:1876943776   DEBUG: CDVDPlayerAudio::SyncStream rr:1.01918 error:4.234458

it does look like the error gets big at that time. I don't see anything wrong from MMAL - I have pictures ready and return 4 (VC_PICTURE) or 6 (VC_PICTURE | VC_BUFFER) for all the calls near there.

Code:

22:09:15 1562.002319 T:1567425440   DEBUG: CMMALVideo::Decode - ret(6) pics(2) inputs(1) slept(0) queued(0.24) (65704.78:65704.54) full(0) flags(0)
22:09:15 1562.023926 T:1567425440   DEBUG: CMMALVideo::Decode - ret(6) pics(2) inputs(1) slept(0) queued(0.38) (65704.94:65704.56) full(0) flags(0)
22:09:15 1562.044312 T:1567425440   DEBUG: CMMALVideo::Decode - ret(4) pics(2) inputs(0) slept(0) queued(0.32) (65704.90:65704.58) full(0) flags(0)
22:09:15 1562.062744 T:1567425440   DEBUG: CMMALVideo::Decode - ret(6) pics(2) inputs(2) slept(0) queued(0.30) (65704.90:65704.60) full(0) flags(0)
22:09:15 1562.082031 T:1567425440   DEBUG: CMMALVideo::Decode - ret(6) pics(2) inputs(1) slept(0) queued(0.44) (65705.06:65704.62) full(0) flags(0)
22:09:16 1562.106079 T:1567425440   DEBUG: CMMALVideo::Decode - ret(4) pics(2) inputs(0) slept(0) queued(0.54) (65705.18:65704.64) full(0) flags(0)
22:09:16 1562.123657 T:1567425440   DEBUG: CMMALVideo::Decode - ret(6) pics(2) inputs(1) slept(0) queued(0.52) (65705.18:65704.66) full(0) flags(0)
22:09:16 1562.143921 T:1567425440   DEBUG: CMMALVideo::Decode - ret(4) pics(2) inputs(0) slept(0) queued(0.42) (65705.10:65704.68) full(0) flags(0)

[FernetMenta]

I found an issue that I think caused this problem: https://github.com/FernetMenta/xbmc/comm...e7fff0d6ec

I hope this fixes it.

[herrmeier01]

FernetMenta and popcornmix thanks you very much for your big effort.
I tested now with the latest build #0112 from Milhouse. While playback with logging enabled for 44min it was not possible to reproduce the issue. And also not while another 10min I preparing this post... I think the fix solved this problem.
Great job thanks again. I will observe this tomorrow when I'm watching TV for a longer time with this build.
I the log file there are no such errors as before. If you want have a look at the log I uploaded it here