Long pause before videos start to play

tony-r · 4 September 2021 05:17

I have two Vero devices, a 4k and 4k+. Both are running the latest s/w versions, and have similar configurations. They are used for playing videos and TV recordings.

The ‘+’ works as expected.

The vanilla Vero takes a very long time to start to play a video, up to a minute from pressing the start button, before seeing anything happening on the screen.

Logs are here:

I did notice that while waiting for something to happen after pressing ‘start’, the information display at the top left hand corner of the screen that appears when debug logging is set, freezes, ie, shows no activity.

I’ve gone through the settings and can’t find anything unusual.

Apart from the long delays, the Vero works as expected.

Hopefully, you’ll see something in the logs that may explain this behaviour.

dwardor · 4 September 2021 07:28

I’m seeing the same thing (and worse… sometimes up to 4 minutes before video start) on my pi3 and pi2 running 2021-08-1.

fzinken · 4 September 2021 07:34

Then provide Debug enabled logs if you want to find a solution

dwardor · 4 September 2021 07:37

Will get to it !

dwardor · 4 September 2021 10:39

Clicked play at 11:58:37 (UTC+0200)
Logging info in top left corner froze until
Play started on screen around ~12:01:20 (UTC+0200)

Below is the relevant part of kodi.log after activating debbug

2021-09-04 11:58:37.932 T:556     DEBUG <general>: PushCecKeypress - received key  b duration 0
2021-09-04 11:58:37.989 T:460     DEBUG <general>: HandleKey: 11 (0x0b, obc244) pressed, action is Select
2021-09-04 11:58:37.990 T:460     DEBUG <general>: ------ Window Deinit (DialogVideoInfo.xml) ------
2021-09-04 11:58:38.094 T:556     DEBUG <general>: PushCecKeypress - received key  b duration 161
2021-09-04 11:58:38.185 T:542     DEBUG <general>: service.watchedlist: watch_user_changes: Check for user changes (no. 18)
2021-09-04 11:58:38.207 T:542     DEBUG <general>: service.watchedlist: get_watched_xbmc: Get all TV shows from Kodi database
2021-09-04 11:58:39.965 T:542     DEBUG <general>: RunQuery took 41 ms for 28 items query: SELECT * FROM tvshow_view 
2021-09-04 11:58:40.009 T:542     DEBUG <general>: service.watchedlist: get_watched_xbmc: Get all movies from Kodi database
2021-09-04 11:58:40.225 T:542     DEBUG <general>: RunQuery took 200 ms for 2318 items query: select * from movie_view 
2021-09-04 11:58:41.870 T:542     DEBUG <general>: service.watchedlist: get_watched_xbmc: Get all episodes from Kodi database
2021-09-04 11:58:42.066 T:542     DEBUG <general>: RunQuery took 185 ms for 2602 items query: select * from episode_view 
2021-09-04 11:58:45.407 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:58:45.443 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:58:55.882 T:4836    DEBUG <general>: Thread JobWorker 1799352512 terminating (autodelete)
2021-09-04 11:58:55.884 T:4841    DEBUG <general>: Thread JobWorker 1066668224 terminating (autodelete)
2021-09-04 11:58:55.902 T:4834    DEBUG <general>: Thread JobWorker 934846656 terminating (autodelete)
2021-09-04 11:59:00.958 T:4885    DEBUG <general>: Thread JobWorker start, auto delete: true
2021-09-04 11:59:01.071 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:01.072 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:07.356 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:07.356 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:12.383 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:12.406 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:20.875 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:20.876 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:25.384 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:25.385 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:30.959 T:4835    DEBUG <general>: Thread JobWorker 1324339392 terminating (autodelete)
2021-09-04 11:59:30.959 T:4885    DEBUG <general>: Thread JobWorker 934846656 terminating (autodelete)
2021-09-04 11:59:34.700 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:34.700 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:48.525 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:48.525 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 11:59:57.637 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 11:59:57.638 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:00:00.849 T:539     DEBUG <general>: service.libraryautoupdate-1.2.3 : Skipping scan, only run when idle
2021-09-04 12:00:00.973 T:4905    DEBUG <general>: Skipped 1 duplicate messages..
2021-09-04 12:00:00.973 T:4905    DEBUG <general>: Thread JobWorker start, auto delete: true
2021-09-04 12:00:10.559 T:2142    DEBUG <UPNP::CMediaBrowser>: Skipped 1 duplicate messages..
2021-09-04 12:00:10.559 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:00:10.559 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:00:21.083 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:00:21.083 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:00:30.986 T:4905    DEBUG <general>: Thread JobWorker 1324339392 terminating (autodelete)
2021-09-04 12:00:30.986 T:4906    DEBUG <general>: Thread JobWorker 934846656 terminating (autodelete)
2021-09-04 12:00:37.117 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:00:37.118 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:00:46.580 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:00:46.580 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:00:53.341 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:00:53.341 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:01:00.850 T:539     DEBUG <general>: service.libraryautoupdate-1.2.3 : Skipping scan, only run when idle
2021-09-04 12:01:04.861 T:2142    DEBUG <UPNP::CMediaBrowser>: Skipped 1 duplicate messages..
2021-09-04 12:01:04.861 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:01:04.861 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:01:10.496 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/library%3a%2f%2fvideo%2fmovies%2ftitles.xml%2f/
2021-09-04 12:01:10.496 T:2142    DEBUG <UPNP::CMediaBrowser>: notified container update upnp://41e39983-b298-7328-40e2-efa6348af574/videodb%3a%2f%2frecentlyaddedmovies%2f/
2021-09-04 12:01:14.454 T:460     DEBUG <general>: GetMovieId (/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4), query = select idMovie from movie where idFile=18004
2021-09-04 12:01:14.455 T:460     DEBUG <general>: GetEpisodeId (/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4), query = select idEpisode from episode where idFile=18004
2021-09-04 12:01:14.490 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers(/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4)
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: system rules
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: matches rule: system rules
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: streams
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: dvd
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: discimage
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: nsv
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerSelectionRule::GetPlayers: considering rule: radio
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
2021-09-04 12:01:14.491 T:460     DEBUG <general>: CPlayerCoreFactory::GetPlayers: added 1 players
2021-09-04 12:01:14.510 T:460     DEBUG <general>: Radio UECP (RDS) Processor - new CDVDRadioRDSData
2021-09-04 12:01:14.511 T:460      INFO <general>: VideoPlayer::OpenFile: /home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4
2021-09-04 12:01:14.515 T:4946    DEBUG <general>: Thread VideoPlayer start, auto delete: false
2021-09-04 12:01:14.516 T:460     DEBUG <general>: OnPlayBackStarted: CApplication::OnPlayBackStarted
2021-09-04 12:01:14.521 T:4947    DEBUG <general>: Thread BackgroundLoader start, auto delete: false
2021-09-04 12:01:14.536 T:4947    DEBUG <general>: Thread BackgroundLoader 926453952 terminating
2021-09-04 12:01:14.539 T:4948    DEBUG <general>: Thread JobWorker start, auto delete: true
2021-09-04 12:01:14.539 T:4946     INFO <general>: Creating InputStream
2021-09-04 12:01:14.548 T:4948    DEBUG <general>: Loading settings for /home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4
2021-09-04 12:01:14.601 T:4946    DEBUG <general>: CFileCache::Open - </home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4> opening
2021-09-04 12:01:14.608 T:4946    DEBUG <general>: CFileCache::Open - </home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4> source chunk size is 0, setting cache chunk size to 131072
2021-09-04 12:01:14.609 T:4946    DEBUG <general>: CFileCache::Open - </home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4> using double memory cache each sized 10485760 bytes
2021-09-04 12:01:14.609 T:4949    DEBUG <general>: Thread FileCache start, auto delete: false
2021-09-04 12:01:14.609 T:4946    DEBUG <general>: ScanForExternalSubtitles: Searching for subtitles...
2021-09-04 12:01:14.614 T:4946    DEBUG <general>: ScanForExternalSubtitles: END (total time: 5 ms)
2021-09-04 12:01:14.614 T:4946     INFO <general>: Creating Demuxer
2021-09-04 12:01:14.672 T:460     DEBUG <general>: CVideoGUIInfo::InitCurrentItem(/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4)
2021-09-04 12:01:14.672 T:460     DEBUG <general>: CPlayerGUIInfo::InitCurrentItem(/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4)
2021-09-04 12:01:14.686 T:492     DEBUG <UPNP::BuildObject>: Building didl for object '/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4'
2021-09-04 12:01:14.687 T:4946    DEBUG <general>: Open - probing detected format [mov,mp4,m4a,3gp,3g2,mj2]
2021-09-04 12:01:14.728 T:4949    DEBUG <general>: CFileCache::Process - </home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4> cache completely reset for seek to position 219898373
2021-09-04 12:01:14.772 T:460     DEBUG <general>: ------ Window Init (DialogBusy.xml) ------
2021-09-04 12:01:14.825 T:460     DEBUG <general>: ------ Window Init () ------
2021-09-04 12:01:14.864 T:539     DEBUG <general>: service.libraryautoupdate-1.2.3 : screen saver on
2021-09-04 12:01:15.169 T:4949    DEBUG <general>: CFileCache::Process - </home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4> source read hit eof
2021-09-04 12:01:20.349 T:4946    DEBUG <general>: Open - avformat_find_stream_info starting
2021-09-04 12:01:20.371 T:4946    DEBUG <general>: Open - av_find_stream_info finished
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]: Input #0, mov,mp4,m4a,3gp,3g2,mj2, from '/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4':
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:   Metadata:
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     major_brand     : isom
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     minor_version   : 512
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     compatible_brands: isomiso2avc1mp41
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     creation_time   : 2021-08-20T04:45:15.000000Z
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     title           : ShowA.S01E04
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     encoder         : Lavf58.20.100
2021-09-04 12:01:20.371 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     comment         : ShowA.S01E04
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:   Duration: 00:21:30.41, start: 0.000000, bitrate: 1368 kb/s
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     Stream #0:0(und), 1, 1/24000: Video: h264 (High) (avc1 / 0x31637661), yuv420p, 720x400 [SAR 80:81 DAR 16:9], 1107 kb/s, 23.98 fps, 23.98 tbr, 24k tbn, 47.95 tbc (default)
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     Metadata:
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:       creation_time   : 2021-08-20T04:45:15.000000Z
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:       handler_name    : VideoHandler
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     Stream #0:1(eng), 1, 1/48000: Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, stereo, fltp, 256 kb/s (default)
2021-09-04 12:01:20.372 T:4946     INFO <general>: ffmpeg[0x62b3640X]:     Metadata:
2021-09-04 12:01:20.373 T:4946     INFO <general>: ffmpeg[0x62b3640X]:       creation_time   : 2021-08-20T04:45:15.000000Z
2021-09-04 12:01:20.373 T:4946     INFO <general>: ffmpeg[0x62b3640X]:       handler_name    : SoundHandler
2021-09-04 12:01:20.373 T:4946    DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 0
2021-09-04 12:01:20.373 T:4946    DEBUG <general>: CDVDDemuxFFmpeg::AddStream ID: 1
2021-09-04 12:01:20.373 T:4946    DEBUG <general>: CDVDInputStreamFile::SetReadRate - set cache throttle rate to 188204 bytes per second
2021-09-04 12:01:20.373 T:4946     INFO <general>: Opening stream: 0 source: 256
2021-09-04 12:01:20.373 T:4946     INFO <general>: Creating video codec with codec id: 27
2021-09-04 12:01:20.499 T:4946     INFO <general>: CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2021-09-04 12:01:21.369 T:4946     INFO <general>: ffmpeg[0x62b3640X]: [h264_v4l2m2m] Using device /dev/video10
2021-09-04 12:01:21.369 T:4946     INFO <general>: ffmpeg[0x62b3640X]: [h264_v4l2m2m] driver 'bcm2835-codec' on card 'bcm2835-codec-decode' in mplane mode
2021-09-04 12:01:21.369 T:4946     INFO <general>: ffmpeg[0x62b3640X]: [h264_v4l2m2m] requesting formats: output=H264 capture=YU12
2021-09-04 12:01:21.390 T:4946     INFO <general>: ffmpeg[0x62b3640X]: [h264_v4l2m2m] v4l2_configure_contexts: avctx:0x515ca370 decoder:1
2021-09-04 12:01:21.390 T:4946    DEBUG <general>: CVideoPlayerVideo::OpenStream - open stream with codec id: 27
2021-09-04 12:01:21.391 T:4946     INFO <general>: Creating video thread
2021-09-04 12:01:21.392 T:4950    DEBUG <general>: Thread VideoPlayerVideo start, auto delete: false
2021-09-04 12:01:21.392 T:4950     INFO <general>: running thread: video_thread
2021-09-04 12:01:21.392 T:4950    DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_PAUSE: 0
2021-09-04 12:01:21.392 T:4946    DEBUG <general>: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: /home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4
2021-09-04 12:01:21.392 T:4946     INFO <general>: Opening stream: 1 source: 256
2021-09-04 12:01:21.392 T:4946     INFO <general>: Finding audio codec for: 86018
2021-09-04 12:01:21.395 T:4946     INFO <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2021-09-04 12:01:21.395 T:4946     INFO <general>: Creating audio thread
2021-09-04 12:01:21.400 T:4951    DEBUG <general>: Thread VideoPlayerAudio start, auto delete: false
2021-09-04 12:01:21.400 T:4951     INFO <general>: running thread: CVideoPlayerAudio::Process()
2021-09-04 12:01:21.400 T:4951    DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_PAUSE: 0
2021-09-04 12:01:21.400 T:4946    DEBUG <general>: CVideoPlayer::SetCaching - caching state 1
2021-09-04 12:01:21.400 T:4946    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CVideoPlayer::HandleMessages - player 2 reported state: 0
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CVideoPlayer::HandleMessages - player 1 reported state: 0
2021-09-04 12:01:21.401 T:4948    DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CVideoPlayer::SetCaching - caching state 1
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CVideoPlayer::SetCaching - caching state 2
2021-09-04 12:01:21.401 T:4950    DEBUG <general>: CVideoPlayerVideo - Stillframe left, switching to normal playback
2021-09-04 12:01:21.401 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.401 T:4946    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-09-04 12:01:21.406 T:4950     INFO <general>: ffmpeg[0x7039dc0X]: [h264_v4l2m2m] Post G selection ret=0, err=0 736x400
2021-09-04 12:01:21.410 T:4951    DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-09-04 12:01:21.411 T:4946    DEBUG <general>: Skipped 1 duplicate messages..
2021-09-04 12:01:21.410 T:4951    DEBUG <general>: CDVDAudio::Pause - pausing audio stream
2021-09-04 12:01:21.412 T:4951     INFO <general>: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2021-09-04 12:01:21.412 T:4951    DEBUG <general>: CVideoPlayerAudio:: synctype set to 0: clock feedback
2021-09-04 12:01:21.415 T:504      INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-09-04 12:01:21.415 T:504     DEBUG <general>: CActiveAESink::OpenSink - trying to open device ALSA:@
2021-09-04 12:01:21.415 T:504      INFO <general>: CAESinkALSA::Initialize - Attempting to open device "@"
2021-09-04 12:01:21.444 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.445 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.447 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.448 T:4950     INFO <general>: ffmpeg[0x7039dc0X]: [h264_v4l2m2m] Dq event 5
2021-09-04 12:01:21.457 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.459 T:4950    DEBUG <general>: CRenderManager::Configure - change configuration. 720x400. display: 711x400. framerate: 23.98.
2021-09-04 12:01:21.502 T:504      INFO <general>: CAESinkALSA::Initialize - Opened device "sysdefault"
2021-09-04 12:01:21.503 T:504     DEBUG <general>: CAESinkALSA::SelectALSAChannelMap - Selected ALSA map "FL FR"
2021-09-04 12:01:21.504 T:504      INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-09-04 12:01:21.504 T:504      INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE3
2021-09-04 12:01:21.504 T:504     DEBUG <general>: CAESinkALSA::InitializeHW - Request: periodSize 2400, bufferSize 9600
2021-09-04 12:01:21.510 T:460     DEBUG <general>: DeleteRenderer - deleting renderer
2021-09-04 12:01:21.510 T:460     DEBUG <general>: LinuxRendererGLES: Cleaning up GLES resources
2021-09-04 12:01:21.510 T:460     DEBUG <general>: CDRMPlane::SupportsFormatAndModifier - found plane format (YU12) and modifier (0x0)
2021-09-04 12:01:21.510 T:460     DEBUG <general>: CRenderManager::Configure - 5
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CAESinkALSA::InitializeHW - Got: periodSize 2400, bufferSize 9600
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CAESinkALSA::InitializeHW - Setting timeout to 200 ms
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CAESinkALSA::GetChannelLayout - Input Channel Count: 2 Output Channel Count: 2
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CAESinkALSA::GetChannelLayout - Requested Layout: FL, FR
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CAESinkALSA::GetChannelLayout - Got Layout: FL, FR (ALSA: FL FR)
2021-09-04 12:01:21.511 T:504     DEBUG <general>: CActiveAESink::OpenSink - ALSA Initialized:
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Output Device : Default (vc4-hdmi MAI PCM vc4-hdmi-hifi-0)
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Sample Rate   : 48000
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Sample Format : AE_FMT_S24NE3
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Channel Count : 2
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Channel Layout: FL, FR
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Frames        : 2400
2021-09-04 12:01:21.511 T:504     DEBUG <general>:   Frame Size    : 6
2021-09-04 12:01:21.516 T:503     DEBUG <general>: Skipped 1 duplicate messages..
2021-09-04 12:01:21.516 T:503     DEBUG <general>: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
2021-09-04 12:01:21.517 T:460     DEBUG <general>: CVideoLayerBridgeDRMPRIME::Configure - setting connector colorspace to Default
2021-09-04 12:01:21.518 T:503     DEBUG <general>: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
2021-09-04 12:01:21.523 T:460     DEBUG <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 206
2021-09-04 12:01:21.523 T:460     DEBUG <general>: CDRMUtils::DrmFbGetFromBo - using modifier: 0x700000000000001
2021-09-04 12:01:21.523 T:460     DEBUG <general>: CDRMAtomic::FlipPage - Execute modeset at next commit
2021-09-04 12:01:21.539 T:4946    DEBUG <general>: CVideoPlayer::HandleMessages - player started 2
2021-09-04 12:01:21.539 T:4946    DEBUG <general>: CVideoPlayer::HandleMessages - player started 1
2021-09-04 12:01:21.539 T:4948    DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-09-04 12:01:21.539 T:4946    DEBUG <general>: CVideoPlayer::SetCaching - caching state 3
2021-09-04 12:01:21.539 T:4946    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-09-04 12:01:21.540 T:4946    DEBUG <general>: CVideoPlayer::SetCaching - caching state 0
2021-09-04 12:01:21.540 T:4946    DEBUG <general>: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-09-04 12:01:21.540 T:4946    DEBUG <general>: VideoPlayer::Sync - Audio - pts: 298666.000000, cache: 515440.521785, totalcache: 800000.011921
2021-09-04 12:01:21.540 T:4946    DEBUG <general>: VideoPlayer::Sync - Video - pts: 41708.000000, cache: 50000.000000, totalcache: 100000.000000
2021-09-04 12:01:21.540 T:4951    DEBUG <general>: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(-216774.521785), level: 51, cache: 495614.844785
2021-09-04 12:01:21.540 T:4951    DEBUG <general>: CDVDAudio::Resume - resume audio stream
2021-09-04 12:01:21.540 T:4952    DEBUG <general>: Thread JobWorker start, auto delete: true
2021-09-04 12:01:21.540 T:4952    DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-09-04 12:01:21.540 T:503     DEBUG <general>: ActiveAE - start sync of audio stream
2021-09-04 12:01:21.542 T:4950    DEBUG <general>: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(-216774.521785)
2021-09-04 12:01:21.542 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 0
2021-09-04 12:01:21.542 T:4952    DEBUG <general>: OnAVStarted: CApplication::OnAVStarted
2021-09-04 12:01:21.545 T:4950    DEBUG <general>: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
2021-09-04 12:01:21.590 T:460     DEBUG <general>: Activating window ID: 12005
2021-09-04 12:01:21.597 T:460     DEBUG <general>: ------ Window Deinit (MyVideoNav.xml) ------
2021-09-04 12:01:21.598 T:460     DEBUG <general>: FreeVisualisation() done
2021-09-04 12:01:21.600 T:460     DEBUG <general>: ------ Window Init (VideoFullScreen.xml) ------
2021-09-04 12:01:21.606 T:460     DEBUG <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 209
2021-09-04 12:01:21.607 T:460     DEBUG <general>: CDRMUtils::DrmFbGetFromBo - using modifier: 0x700000000000001
2021-09-04 12:01:21.622 T:460     DEBUG <general>: ------ Window Deinit (DialogBusy.xml) ------
2021-09-04 12:01:21.626 T:460     DEBUG <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 208
2021-09-04 12:01:21.627 T:460     DEBUG <general>: CDRMUtils::DrmFbGetFromBo - using modifier: 0x700000000000001
2021-09-04 12:01:21.641 T:460     DEBUG <general>: CDRMUtils::DrmFbDestroyCallback - removing framebuffer: 207
2021-09-04 12:01:21.641 T:460     DEBUG <general>: CDRMUtils::DrmFbGetFromBo - using modifier: 0x700000000000001
2021-09-04 12:01:21.649 T:4952    DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-09-04 12:01:21.667 T:503     DEBUG <general>: ActiveAE::SyncStream - average error of 20.269490, start adjusting
2021-09-04 12:01:21.667 T:503     DEBUG <general>: ActiveAE::SyncStream - average error 0.269490 below threshold of 30.000000
2021-09-04 12:01:21.871 T:539     DEBUG <general>: service.libraryautoupdate-1.2.3 : screen saver off
2021-09-04 12:01:22.668 T:4951    DEBUG <general>: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-29869.980898, adjusted:-29869.980898
2021-09-04 12:01:22.824 T:460     DEBUG <general>: ------ Window Deinit () ------
2021-09-04 12:01:26.627 T:4950    DEBUG <general>: CPtsTracker: detected pattern of length 1: 41708.33, frameduration: 41708.333333

fzinken · 4 September 2021 10:54

What’s all that UPNP stuff? Are you using UPNP somehow for your Library? Maybe provide full logs that could give an idea.
/home/media/Videos/Series/ShowA/Season01/ShowA.S01E04.mp4 are you playing from the emmc or is /home/media/ mount from a NAS?

dwardor · 4 September 2021 11:06

Yes /home/media is a nfs mount from my Synology NAS
(my pi 1 running 2020-11 is also nfs mounting and has no delay → I don’t think it is a nfs/network issue)

Yes pi3 is making its library available via upnp for my android devices (that aren’t going to nfs mount (been that way for years)

Full logs as in :

don’t provide just the time span during which the issue happens ?
activate all debugging for all components ?

Thanks for the help !

fzinken · 4 September 2021 11:11

Full logs in terms of not only the kodi.log but all logs available via MyOSMC LogUploader so that we understand your setup.
With your current reply we understand it now already a bit better.

Maybe disable UPNP during the testing.

Also if you use Kernel mounts maybe try CLI to /home/media with ls, cp,… to see if any delay is there.

dwardor · 4 September 2021 16:43

Here is the ful log (with some editing for privacy : ipv6, …)

fzinken · 5 September 2021 01:54

Looks like you have LAN and Wifi up at the same time that could lead to issues

eth0: flags=-28605<UP,BROADCAST,RUNNING,MULTICAST,DYNAMIC>  mtu 1500
        inet 192.168.2.31


wlan0: flags=-28605<UP,BROADCAST,RUNNING,MULTICAST,DYNAMIC>  mtu 1500
        inet 192.168.2.8

dwardor · 5 September 2021 13:27

Thought I had deactivated wlan0 when I tried to test on eth0 only to see if wifi was the culprit…

Anyways… pi2 and pi3 are doing better… and all I did was…

Change nfs from v3 to v4… (After adding Domain to /etc/idmap.conf to get nfs4 to worl properly) for both
Rebooted the wireless repeater (re450 running openwrt) the pi2 is connected to. My android phone had no connectivity issues with it, but given network issues was the main culprit you had in mind…
Deactived interal wifi and put an external usb 5Ghz-ac wifi dongle (with better reception due to 5dBi antenna) on the pi3 (had been on its internal 2.4 Ghz wifi which I suspect “has aged”…) iperf3 shows wifi speeds went from 10Mbits/s to 98 Mbits/s maybe that helped…

So its possible that :

nfs v3 was not an issue (but I’ll stay on v4 now…)
internal wifi on the pi3 was/is dying
repeater just needed a reboot for the pi2 (never had that issue in the over 3 years this setup has been working)

Thanks for guiding me in the right direction…

tony-r · 6 September 2021 03:28

It’s good that #dwardor got a solution after hijacking my post, but could someone have a look at my issue? Thanks!

fzinken · 6 September 2021 03:53

Can you name the movie you played for your logs which has shown the delay?
Also looks like you have sources defined via Kodi NFS access and kernel mounts. I suggest you migrate all sources to the kernel mounts.

tony-r · 6 September 2021 04:12

One was “Weiner,” the other “Batman Forever” while the debug logging was on.

I find the delay is on all video files.

I’ll have a look at the NFS settings. I recently edited the fstab file for the kernel mounts after reading a wiki entry about it. I thought I’d got rid of the kodi ones. I’ll check this evening.

I have the same setup on both Veros. Only one has this issue.

fzinken · 6 September 2021 04:42

For the Weiner movie clearly it was still be played via the Kodi NFS access. This seems to be a similar issue we have seen before.

For the time being I suggest you try to change all your sources to just use the fstab entries and rescan your library. Until we might find a solution for the original issues.

2021-09-04 14:56:00.150 T:2607    DEBUG <general>: CPlayerCoreFactory::GetPlayers(nfs://192.168.1.203/data/videos/Movies/Weiner (2016)/weiner.mkv)

tony-r · 6 September 2021 04:48

Thanks #fzinken. I’ll check and let you know.

tony-r · 8 September 2021 11:02

Hello @fzinken, you were correct, the mounts were kodi and not through fstab. (Brain fade). i’ve fixed this but the delay persists.

I’ve created new logs: https://paste.osmc.tv/usuvecosof

Logged video: A Beautiful Mind. Please let me know if I can help with diagnosing what’s going on.

fzinken · 8 September 2021 13:28

Good then we can exclude that as a possible issue.

Ok, was a bit harder to read the log this time as your library was rescanned filling quite some lines. But it seems we are still back to this strange error

2021-09-08 20:49:24.694 T:2607    ERROR <general>: GetDirectory - Unhandled exception
2021-09-08 20:49:24.694 T:2607    ERROR <general>: GetDirectory - Error getting /home/osmc/.kodi/temp/
2021-09-08 20:49:24.694 T:2607    ERROR <general>: GetDirectory - Error getting special://temp/

I still don’t have any explanation for this issue.

My next suggestion would be to try with a reset of the Kodi configuration and maybe just copying your sources.xml from the old config to the new config to just test if it works with a clean config you could then try to copy more back afterwards.

Let’s test with Kodi default settings. Enter the following commands with an SSH connection.

systemctl stop mediacenter
mv ~/.kodi ~/kodi.bak
systemctl start mediacenter

If needed you can restore:

systemctl stop mediacenter
mv ~/.kodi ~/kodi.bk2
mv ~/kodi.bak ~/.kodi
systemctl start mediacenter

If your original setup was restored as expected and you want get rid of the unneeded clean install you can delete that with the following command.

rm -r ~/kodi.bk2

DLD-UK · 8 September 2021 16:12

I don’t know if this helps work out what is going on but I have the same issue playing .TS files on a TrueNAS SMB share. The audio seems to play from the start but video starts later. Not sure if it is the same issue but it only started to happen after the last update.

fzinken · 9 September 2021 00:20

Sounds different, check if you also have GetDirectory - Unhandled exception in your Kodi.log. If yes same issue, if not then suggest to open a new thread with debug enabled logs.