Hello,
Since the upgrade to buster (made yesterday), kodi freeze for a few (EDIT : 25) seconds when asked to play a video.
Except this issue, the video plays fine and i haven’t spotted anything else.
Here’s my Vero 4k logs : https://paste.osmc.tv/hikuwaxuxo
Library is stored on a mysql database, hosted on my NAS, where the video files are.
Regards.
It looks like UPnP is refreshing at the start of playback for some reason so perhaps that is what is causing it. If your not using UPnP then you might turn it off. I also noticed that your Video settings might not be optimal. I would suggest turning refresh rate adjustment to on start/stop and adding at least the rest of the 1080 resolution frame rates to your whitelist if your going to use that feature.
Thanks, i followed all your advices and rebooted (i also disabled airplay and zeroconf which i don’t use).
But i still have this freeze (around 30s).
Here’s the new log file : https://paste.osmc.tv/ihecoxawiz.hs
I’m not sure as you only uploaded the kodi log but are you sure you…
You’re right, i only added the rest of the 1080 resolutions but forgot to turn on refresh rate adjustment, sorry.
Ok, now everything is in place, but the issue still persists :
In your last log, you pressed the Stop button:
2020-11-05 20:32:58.310 T:4064796688 DEBUG: HandleKey: stop (0xf0bc) pressed, action is Stop
In your display settings can you enable “Lock HDMI HPD” and test again.
Also, and this is not related, you probably want your audio set to “best match” and not “optimized” as you currently have it set.
Additionally it would be appreciated if any future logs were the full set and not just the Kodi log by itself.
Yes, i let the video play for a few seconds once it finally started, then stopped it.
Ok, i made the 2 changes you mentioned then enabled debug and rebooted.
Here’s the full logs : https://paste.osmc.tv/cawayolige
I played one video (waited almost 30s again), then jumped 2 times to reach the end, and it played the second video (with the same wait issue). Jumped again and it went back to the library as expected.
So this is where in that log your seeing a freeze?
020-11-06 10:50:50.955 T:3542085856 DEBUG: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:20447.604376, adjusted:41708.333333
2020-11-06 10:50:53.705 T:3500392672 DEBUG: CPtsTracker: detected pattern of length 1: 41708.24, frameduration: 41708.333333
and
2020-11-06 10:51:14.951 T:4024430816 DEBUG: ActiveAE::SyncStream - average error of 117.613773, start adjusting
2020-11-06 10:51:15.036 T:4024430816 DEBUG: ActiveAE::SyncStream - average error 21.613773 below threshold of 30.000000
I’m at a loss here as when I play the same file I get the same initial audio syncs but playback with both audio and video is flawless.
2020-11-06 10:55:27.934 T:4071698448 DEBUG: ------ Window Init (VideoFullScreen.xml) ------
2020-11-06 10:55:27.957 T:4071698448 NOTICE: Whitelist search for: width: 1920, height: 1080, fps: 23.976, 3D: false
2020-11-06 10:55:27.957 T:4071698448 DEBUG: Whitelist is empty using default one
2020-11-06 10:55:27.957 T:4071698448 DEBUG: Trying to find exact refresh rate
2020-11-06 10:55:27.958 T:4071698448 DEBUG: Matched exact whitelisted Resolution 1920x1080 @ 23.98 - Full Screen (23)
2020-11-06 10:55:27.958 T:4071698448 NOTICE: Display resolution ADJUST : 1920x1080 @ 23.98 - Full Screen (23) (weight: 0.194)
2020-11-06 10:55:27.961 T:3308396768 DEBUG: OnAVChange: CApplication::OnAVChange
2020-11-06 10:55:27.963 T:4071698448 DEBUG: ------ Window Deinit (DialogBusy.xml) ------
2020-11-06 10:55:28.005 T:4029567200 DEBUG: ActiveAE::SyncStream - average error of -49.717028, start adjusting
2020-11-06 10:55:28.005 T:4029567200 DEBUG: ActiveAE::SyncStream - average error -17.717028 below threshold of 30.000000
2020-11-06 10:55:28.007 T:4062179552 DEBUG: CEGLNativeTypeAmlogic: Detected HDMI switch
2020-11-06 10:55:28.102 T:3870503136 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnAVChange - data: {"item":{"title":"DuckTales.2017.S03E13.Escape.from.the.ImpossiBin.1080p.AMZN.WEB-DL.DDP2.0.H.264-LAZY.mkv","type":"movie"},"player":{"playerid":1,"speed":1}}
2020-11-06 10:55:28.104 T:3870503136 DEBUG: Previous line repeats 1 times.
2020-11-06 10:55:28.104 T:3870503136 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnAVStart - data: {"item":{"title":"DuckTales.2017.S03E13.Escape.from.the.ImpossiBin.1080p.AMZN.WEB-DL.DDP2.0.H.264-LAZY.mkv","type":"movie"},"player":{"playerid":1,"speed":1}}
2020-11-06 10:55:28.105 T:3870503136 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnAVChange - data: {"item":{"title":"DuckTales.2017.S03E13.Escape.from.the.ImpossiBin.1080p.AMZN.WEB-DL.DDP2.0.H.264-LAZY.mkv","type":"movie"},"player":{"playerid":1,"speed":1}}
2020-11-06 10:55:29.072 T:3468681440 DEBUG: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-27544.665404, adjusted:-27544.665404
2020-11-06 10:55:32.834 T:3838013664 DEBUG: CPtsTracker: detected pattern of length 1: 41708.24, frameduration: 41708.333333
2020-11-06 10:55:57.962 T:3543167200 DEBUG: Thread JobWorker 3543167200 terminating (autodelete)
2020-11-06 10:55:57.963 T:3300004064 DEBUG: Thread JobWorker 3300004064 terminating (autodelete)
2020-11-06 10:55:57.963 T:3308396768 DEBUG: Thread JobWorker 3308396768 terminating (autodelete)
2020-11-06 10:59:14.965 T:4043301088 DEBUG: CLibInputKeyboard::ProcessKey - using delay: 500ms repeat: 50ms
2020-11-06 10:59:14.966 T:3308396768 DEBUG: Thread Timer start, auto delete: false
2020-11-06 10:59:14.972 T:4071698448 DEBUG: Keyboard: scancode: 0x80, sym: 0x0151, unicode: 0x0000, modifier: 0x0
2020-11-06 10:59:14.979 T:3308396768 DEBUG: Thread Timer 3308396768 terminating
2020-11-06 10:59:15.012 T:4071698448 DEBUG: Keyboard: scancode: 0x80, sym: 0x0151, unicode: 0x0000, modifier: 0x0
2020-11-06 10:59:15.013 T:4071698448 DEBUG: HandleKey: stop (0xf0bc) pressed, action is Stop
2020-11-06 10:59:15.013 T:4071698448 NOTICE: CVideoPlayer::CloseFile()
Maybe @grahamh has a clue that I don’t. I’m out of ideas.
You will probably want to turn the HPD lock back off since it didn’t help with your issue.
I never said something about seeing it in the logs.
I said that between the time i press the play button and when the video starts, there is a something 30s delay (during this time kodi becomes unresponsive).
Maybe these lines show it ?
2020-11-06 10:50:22.168 T:4065583120 DEBUG: HandleKey: return (0xf00d) pressed, action is Select
…
2020-11-06 10:50:47.936 T:4065583120 DEBUG: CPlayerCoreFactory::GetPlayers(/mnt/nas/Séries TV/DuckTales (2017)/Season 3/DuckTales.2017.S03E13.Escape.from.the.ImpossiBin.1080p.AMZN.WEB-DL.DDP2.0.H.264-LAZY.mkv)
…
2020-11-06 10:50:47.941 T:3893596384 DEBUG: Thread VideoPlayer start, auto delete: false
…
2020-11-06 10:50:48.653 T:3893596384 NOTICE: Creating video thread
2020-11-06 10:50:48.654 T:3500392672 DEBUG: Thread VideoPlayerVideo start, auto delete: false
I haven’t thought about it before, but the issue may be with the access time to the nas since the upgrade.
I’m gonna try with a local file and run some tests.
Ok, it’s not related to the nas, it really is caused by kodi and/or osmc :
I had just found those lines - a 25 second gap where nothing is happening.
I can only suggest a backup and reinstall unless @sam_nazarko can offer anything.
Apologies, I was misunderstanding the issue. I thought you were saying the video started, and then after a period of time a freeze happened.
No harm done 
I found out that kodi goes from ~50% cpu (before playing) to ~100% during the 25s wait, and falls to 25% when the video finally starts to play.
Here a trace from kodi (strace -o kodi.trace -p 2854 -t -T -f).
It starts right before i play the video, then the 25s waits occurs, i let the video plays for a few seconds, then stop it, and wait for the display to come back on the library to stop the trace.
Here’s the trace file (9 Mb, expire in 5 days) : https://drop.chapril.org/download/df1bf819e8a275f2/#KmR5vwqSNEAYQO9RB1vURA
I noticed the wait period cames after process 3258 is attached and stop once the next one (3271) comes.
root@HTPC:~# strace -o kodi.trace -p 2854 -t -T -f
strace: Process 2854 attached with 35 threads
strace: Process 3258 attached
strace: Process 3271 attached
strace: Process 3272 attached
strace: Process 3273 attached
strace: Process 3274 attached
strace: Process 3275 attached
strace: Process 3276 attached
strace: Process 3277 attached
strace: Process 3278 attached
strace: Process 3279 attached
strace: Process 3281 attached
strace: Process 3282 attached
strace: Process 3286 attached
strace: Process 3287 attached
strace: Process 3288 attached
strace: Process 3289 attached
strace: Process 3290 attached
strace: Process 3291 attached
strace: Process 3292 attached
strace: Process 3295 attached
strace: Process 3298 attached
strace: Process 3301 attached
strace: Process 3302 attached
strace: Process 3303 attached
strace: Process 3304 attached
strace: Process 3305 attached
strace: Process 3306 attached
strace: Process 3307 attached
strace: Process 3308 attached
strace: Process 3309 attached
strace: Process 3310 attached
strace: Process 3311 attached
strace: Process 3312 attached
strace: Process 3313 attached
strace: Process 3314 attached
strace: Process 3315 attached
strace: Process 3316 attached
strace: Process 3317 attached
strace: Process 3318 attached
^Cstrace: Process 2854 detached
strace: Process 2856 detached
strace: Process 2908 detached
strace: Process 2909 detached
strace: Process 2910 detached
strace: Process 2911 detached
strace: Process 2912 detached
strace: Process 2913 detached
strace: Process 2914 detached
strace: Process 2915 detached
strace: Process 2928 detached
strace: Process 2929 detached
strace: Process 2930 detached
strace: Process 2931 detached
strace: Process 2932 detached
strace: Process 2933 detached
strace: Process 2935 detached
strace: Process 2936 detached
strace: Process 2937 detached
strace: Process 2938 detached
strace: Process 2939 detached
strace: Process 2940 detached
strace: Process 2941 detached
strace: Process 2942 detached
strace: Process 2943 detached
strace: Process 2944 detached
strace: Process 2945 detached
strace: Process 2946 detached
strace: Process 2947 detached
strace: Process 2951 detached
strace: Process 2953 detached
strace: Process 2954 detached
strace: Process 2957 detached
strace: Process 2959 detached
strace: Process 2960 detached
strace: Process 3298 detached
strace: Process 3272 detached
strace: Process 3310 detached
strace: Process 3311 detached
Now, i started kodi without my original .kodi folder and the issue doesn’t occur. It means this is caused by a setting, the hardest part will be to figure which one (i tried without audio passthrough, amcodec acceleration and 422 color subsampling, no luck).