Playback consistently speeds up after set amount of time

tablemaker · August 6, 2022 at 1:06 AM

Hello,

I have been using LibreElec on a Raspberry Pi for many years, most recently on a Pi4. Recently, I upgraded to the latest version of LibreElec/Kodi and have noticed something very strange. Consistently, after about ~40 min of constant playback, the audio starts glitching while the video starts speeding up as if it was 1.5 speed. This becomes the way playback functions until I fully stop the playback of the video and then restart the video. I first thought this was due to overheating but even after ensuring the temperature of the device was sound, this continues. Thining resources, I don't see a noticible load on the CPU, hoving around a ~2.3 during even 4k playback and memory usage is quite minimal, barely using near 1GB in a 4GB system. This seems to occur no matter the quality of the video, 1080 or 4k.

Of note, I have also observed this while watching shorter video files but in succession, making it a constant 40-ish minutes of playback. However, if I stop the stream and then start the next episode, the issue seems to not happen.

Below I just have basic informatoin of the Kodi version and kernel version. I am unsure where else to look as the log doesn't seem to push out any other information at the moment. Any help or suggestion on where to go from here would be greatly appreciated.

Thanks!

Code

tablekodi:~ # grep Kodi /storage/.kodi/temp/kodi.log 
2022-08-02 18:01:06.479 T:788      INFO <general>: Starting Kodi (19.4 (19.4.0) Git:19.4-Matrix). Platform: Linux ARM 32-bit
2022-08-02 18:01:06.479 T:788      INFO <general>: Using Release Kodi x32
2022-08-02 18:01:06.479 T:788      INFO <general>: Kodi compiled 2022-03-05 by GCC 10.2.0 for Linux ARM 32-bit version 5.10.95 (330335)
2022-08-02 18:01:06.479 T:788      INFO <general>: FFmpeg version/source: 4.3.2-Kodi


tablekodi:~ # uname -a
Linux tablekodi 5.10.95 #1 SMP Sat Mar 5 15:50:44 CET 2022 aarch64 GNU/Linux

GDPR-7 · August 6, 2022 at 7:49 PM

just some thoughts:

- set debug to on and reboot

- start a video and wait

- when your issue occurs memorize the time

- upload the log files

read:

https://wiki.libreelec.tv/support/log-files

tablemaker · August 10, 2022 at 4:37 PM

Ah, that's a neat little tool. Here is the resulting link:

http://ix.io/47d3

Looks like we do hit the consistent issue @ around `19:24`

Code

[...]
2022-08-09 18:47:30.948 T:1013    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: CVideoPlayer::HandleMessages - player started 2
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: CVideoPlayer::SetCaching - caching state 3
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: CVideoPlayer::SetCaching - caching state 0
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: VideoPlayer::Sync - Audio - pts: 751488000.000000, cache: 320000.052452, totalcache: 800000.011921
2022-08-09 18:47:31.022 T:1003    DEBUG <general>: VideoPlayer::Sync - Video - pts: 751084000.000000, cache: 50000.000000, totalcache: 100000.000000
2022-08-09 18:47:31.022 T:1014    DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(750984000.000000), level: 99, cache: 515439.793452
2022-08-09 18:47:31.022 T:1014    DEBUG <general>: CDVDAudio::Resume - resume audio stream
2022-08-09 18:47:31.022 T:797     DEBUG <general>: ActiveAE - start sync of audio stream
2022-08-09 18:47:31.023 T:1013    DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(750984000.000000)
2022-08-09 18:47:31.023 T:1013    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
2022-08-09 18:47:31.168 T:797     DEBUG <general>: ActiveAE::SyncStream - average error of -11.074048, start adjusting
2022-08-09 18:47:31.168 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -0.011548 below threshold of 30.000000
2022-08-09 18:47:31.295 T:970     DEBUG <CWebserver[8080]>: request received for /jsonrpc
2022-08-09 18:47:33.048 T:787      INFO <general>: Skipped 6 duplicate messages..
2022-08-09 18:47:33.048 T:787     DEBUG <general>: ------ Window Deinit (DialogSeekBar.xml) ------
2022-08-09 18:47:33.080 T:787     DEBUG <general>: ------ Window Deinit (Custom_1109_TopBarOverlay.xml) ------
2022-08-09 18:47:33.581 T:1013    DEBUG <general>: CPtsTracker: detected pattern of length 1: 41708.33, frameduration: 41708.333333
2022-08-09 18:47:33.751 T:970     DEBUG <CWebserver[8080]>: request received for /jsonrpc
2022-08-09 18:48:00.277 T:999      INFO <general>: Skipped 11 duplicate messages..
2022-08-09 18:48:00.277 T:999     DEBUG <general>: Thread JobWorker 3489100416 terminating (autodelete)
2022-08-09 18:48:00.277 T:997     DEBUG <general>: Thread JobWorker 3447136896 terminating (autodelete)
2022-08-09 18:48:00.277 T:998     DEBUG <general>: Thread JobWorker 3351671424 terminating (autodelete)
2022-08-09 18:48:00.278 T:996     DEBUG <general>: Thread JobWorker 3390202496 terminating (autodelete)
2022-08-09 19:24:23.918 T:1002    DEBUG <general>: CVideoReferenceClock: detected 2 vblanks, missed 3, refreshrate might have changed
2022-08-09 19:24:40.350 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:24:56.281 T:1002     INFO <general>: Skipped 2 duplicate messages..
2022-08-09 19:24:56.281 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:07.281 T:1002     INFO <general>: Skipped 2 duplicate messages..
2022-08-09 19:25:07.281 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:17.313 T:1002     INFO <general>: Skipped 12 duplicate messages..
2022-08-09 19:25:17.313 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:18.401 T:797      INFO <general>: Skipped 1 duplicate messages..
2022-08-09 19:25:18.401 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -249.088625 above threshold of 200.000000
2022-08-09 19:25:18.403 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -0.005292 below threshold of 30.000000
2022-08-09 19:25:18.501 T:797   WARNING <general>: ActiveAE - large audio sync error: -89456.936787
2022-08-09 19:25:18.913 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:22.451 T:797      INFO <general>: Skipped 10 duplicate messages..
2022-08-09 19:25:22.451 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -247.656294 above threshold of 200.000000
2022-08-09 19:25:22.453 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -0.010460 below threshold of 30.000000
2022-08-09 19:25:22.546 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:26.501 T:797      INFO <general>: Skipped 15 duplicate messages..
2022-08-09 19:25:26.501 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -328.743563 above threshold of 200.000000
2022-08-09 19:25:26.503 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -28.743563 below threshold of 30.000000
2022-08-09 19:25:26.551 T:797   WARNING <general>: ActiveAE - large audio sync error: -89637.091612
2022-08-09 19:25:26.679 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:27.551 T:797      INFO <general>: Skipped 3 duplicate messages..
2022-08-09 19:25:27.551 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -293.806190 above threshold of 200.000000
2022-08-09 19:25:27.567 T:797     DEBUG <general>: ActiveAE::SyncStream - average error -0.014524 below threshold of 30.000000
2022-08-09 19:25:27.679 T:1002    DEBUG <general>: CVideoReferenceClock: detected 1 vblanks, missed 2, refreshrate might have changed
2022-08-09 19:25:31.239 T:823      INFO <general>: Skipped 13 duplicate messages..
2022-08-09 19:25:31.239 T:823     DEBUG <general>: JSONRPC Server: New connection detected
2022-08-09 19:25:31.239 T:823      INFO <general>: JSONRPC Server: New connection added
2022-08-09 19:25:31.253 T:1253    DEBUG <CWebserver[8080]>: request received for /jsonrpc
2022-08-09 19:25:31.254 T:1254     INFO <general>: Skipped 2 duplicate messages..
2022-08-09 19:25:31.254 T:1254    DEBUG <general>: JSONRPC: Value does not lay between minimum and maximum in type playlistid
2022-08-09 19:25:31.279 T:1253    DEBUG <CWebserver[8080]>: request received for /jsonrpc
[...]

Display More

GDPR-7 · August 12, 2022 at 7:39 PM

sorry, *I* can't help any further, cause I'm not the best - if at all - log file reader.

anyone ?

**chewitt** · August 13, 2022 at 9:56 AM

I'm not sure what the issue is, but (unrelated) I did notice that you've set the 'desktop' resolution to 4K which probably isn't going to give you the best GUI experience. Using 1080p and the whitelist to switch to 4K modes only when needed will be faster/smoother/better.

GDPR-7 · August 13, 2022 at 8:19 PM

Quote from tablemaker

However, if I stop the stream and then start the next episode, the issue seems to not happen.

thinking about your issue some more:

I could image that sort of a buffer/mechanic/cache in LE/Kodi "see's" an error or such and could self repair/heal it for some amount of time until it can't anymore ( after playing a movie for 40 min ?)

maybe this:

2022-08-09 18:34:51.981 T:797 DEBUG <general>: ActiveAE::SyncStream - average error of -94.787318, start adjusting

I could image that this error increases of time and self healing mechanics take all the power, resources (here: somehow not the CPU) are "contentrated" on audio processing and lowered on video until audio catches up. all power goes again on previous lowered video processing and you'll notice a (temp. ? ) speedup in video play.

IOW: the box seems to "loop" somehow somewhere on audio/video/etc. processing...

Questions (cause I couldn't fetch it out of your description)

- test allways with the same video ! -

1. what happens with local videos (otherwise smb seems to be involed) ?

2. when playing a video and the issue occured, does the same video after a restart of the video play without issues then ?
3. and if so: does the first occurence of the issue always happen when the box was fresh started and it was the first video play (of the day)

theory:

a buffer/cache/? isn't "configures" after the start of the box and somehow it is "set correct" after the issue occured

maybe debugging on components (audio/video/etc) ?

GDPR-7 · August 14, 2022 at 5:14 AM

- old man with limited (KB range) and slow (1MHz) memory here again -

thinking somewhat further:

...

4. what does your memory usage looks like before/after the issue occur ?

=> tools: top or htop (sytem-tools addon)

or

on a command line: "watch -n3 free -wh" (prints every 3 sec ...)

tablemaker · August 25, 2022 at 6:15 AM

Just to close some kind of loop on this. I ended up downgrading back to the latest available kodi 18.9 as the issue was starting to become intermittent and frankly frustrating. I had tried most of the troubleshooting steps provided and found no consistent solution.

At this point the best i can point to is that something with this RPi4 combined with the latest LibreElec just was not happy playing videos. I appreciate the suggestions I was given

GDPR-7 · August 25, 2022 at 9:04 PM

care to mark this thread as resolved (if so), see just under the thread title.

P.S.

sometimes it helps to install from the scratch (and -IIRC- is was the recommended way somewhere between some stable LE releases, see the forum menu point "Blog")

Ralfix · December 20, 2023 at 11:22 AM

Hello,

i had the same Problem. Did you try to edit the advancedsettings.xml? Remove the entries "skiploopfilter" if you use them.

Playback consistently speeds up after set amount of time

Similar Threads

Ive broken something / need a new NUC