xbmc icon indicating copy to clipboard operation
xbmc copied to clipboard
verified publisher icon xbmc

Large Audio Sync, sound skipping and dissorted

Open MMan1982 opened this issue 1 year ago • 12 comments

Bug report

Describe the bug

Here is a clear and concise description of what the problem is: When playing video files queued, sometimes when a new episode starts no sound, and then video will played faster, and sound comes back but dissorted and sometimes cut out for a second.

Expected Behavior

It works normally.

To Reproduce

Steps to reproduce the behavior:

  1. Queue a directory with video files
  2. Wait to happen.

Possible Fix

Restarting the SAME video works ok, or select from the queue and restart it.

Debuglog

2024-02-13 19:53:10.918 T:18911 info : Creating InputStream 2024-02-13 19:53:10.962 T:18911 info : Creating Demuxer 2024-02-13 19:53:10.993 T:18911 info : Opening stream: 0 source: 256 2024-02-13 19:53:10.993 T:18911 info : Creating video codec with codec id: 27 2024-02-13 19:53:10.993 T:18911 info : CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper 2024-02-13 19:53:11.002 T:18911 info : Creating video thread 2024-02-13 19:53:11.002 T:18912 info : running thread: video_thread 2024-02-13 19:53:11.002 T:18911 info : Opening stream: 1 source: 256 2024-02-13 19:53:11.002 T:18911 info : Finding audio codec for: 86018 2024-02-13 19:53:11.003 T:18911 info : CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac 2024-02-13 19:53:11.003 T:18911 info : OpenStream: Allowing max Out-Of-Sync Value of 70 ms 2024-02-13 19:53:11.003 T:18911 info : Creating audio thread 2024-02-13 19:53:11.003 T:18913 info : running thread: CVideoPlayerAudio::Process() 2024-02-13 19:53:11.013 T:18913 info : Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through) 2024-02-13 19:53:11.039 T:18912 error : CDVDVideoCodecDRMPRIME::FilterOpen - avfilter_graph_config: Function not implemented (-38) 2024-02-13 19:53:11.178 T:1991 info : PulseAudio: Opened device Default in pcm mode with Buffersize 150 ms Periodsize 50 ms 2024-02-13 19:53:11.180 T:1991 info : CActiveAESink::OpenSink - initialize sink 2024-02-13 19:53:12.386 T:18913 error : CDVDAudio::AddPacketsRenderer - timeout adding data to renderer 2024-02-13 19:53:16.181 T:1990 info : Skipped 3 duplicate messages.. 2024-02-13 19:53:16.181 T:1990 error : ActiveAE::InitSink - failed to init 2024-02-13 19:53:16.181 T:1990 warning : CActiveAE::StateMachine - signal: 11 from port: OutputControlPort not handled for state: 2 2024-02-13 19:53:16.181 T:1990 warning : CActiveAE::StateMachine - signal: 12 from port: OutputControlPort not handled for state: 2 2024-02-13 19:53:16.181 T:1990 warning : CActiveAE::StateMachine - signal: 7 from port: OutputControlPort not handled for state: 2 2024-02-13 19:53:18.506 T:18913 error : CDVDAudio::AddPacketsRenderer - timeout adding data to renderer 2024-02-13 19:53:29.363 T:18913 info : Skipped 5 duplicate messages.. 2024-02-13 19:53:29.363 T:18913 error : CDVDAudio::AddPacketsRenderer - timeout adding data to renderer 2024-02-13 19:53:40.220 T:18913 info : Skipped 5 duplicate messages.. 2024-02-13 19:53:40.220 T:18913 error : CDVDAudio::AddPacketsRenderer - timeout adding data to renderer 2024-02-13 19:53:42.328 T:1991 info : Skipped 1 duplicate messages.. 2024-02-13 19:53:42.328 T:1991 info : PulseAudio: Opened device Default in pcm mode with Buffersize 150 ms Periodsize 50 ms 2024-02-13 19:53:42.334 T:1990 warning : ActiveAE - large audio sync error: -25532.882541 2024-02-13 19:53:42.335 T:1990 warning : ActiveAE - large audio sync error: -25474.746818 2024-02-13 19:53:42.336 T:1990 warning : ActiveAE - large audio sync error: -25424.744949

Your Environment

Used Operating system:

  • [ ] Android

  • [ ] iOS

  • [ ] tvOS

  • [X] Linux

  • [ ] macOS

  • [ ] Windows

  • [ ] Windows UWP

  • Operating system version/name: Raspbian Bookworm, Linux raspberrypi 6.1.69-v7l+ 1710 SMP Thu Dec 21 13:17:38 GMT 2023 armv7l GNU/Linux

  • Kodi version: kodi 3:20.3-3~bookworm

  • RPi4

  • config.txt relevant lines: gpu_mem=256 dtoverlay=vc4-kms-v3d

note: Once the issue is made we require you to update it with new information or Kodi versions should that be required. Team Kodi will consider your problem report however, we will not make any promises the problem will be solved.

MMan1982 avatar Feb 14 '24 10:02 MMan1982

I will do more testing,but it looks when i switched off drm prime it works! But it eating the cpu of course. Anyone can help me solve this?

MMan1982 avatar Mar 22 '24 12:03 MMan1982

What about with "Allow using DRM PRIME decoder" enabled, but "Allow hardware acceleration with DRM PRIME" disabled?

Does it occur with all files? E.g. if you add this to a playlist and enable repeat do you get the issue? If not, does making a second copy of it and queuing that have the issue?

popcornmix avatar Mar 22 '24 12:03 popcornmix

Sorry,till now worked,but now when i looked at it,again got the large audio sync error again. No,it looks it never occured when looking films,only on series. Yesterday i had this problem with queued 3 series on playlist. When error occured,i selected just the problematic episode and started it again from files menu(without queueing) and the problem reoccured again. I did a reboot,and problem disappeared,and the problematic file plays without error.

MMan1982 avatar Mar 22 '24 12:03 MMan1982

But it looks all of them h 264 encoded,mpeg4 avc / part 10

MMan1982 avatar Mar 22 '24 12:03 MMan1982

Can you link to a freely available file (like the big buck bunny view I linked to) that shows your issue? If not can you create a sample file that shows the issue (e.g. use ffmpeg, or similar to produce a 1 minute sample) and upload it somewhere (e.g. google drive).

popcornmix avatar Mar 22 '24 13:03 popcornmix

Will try your suggestions when i will at home,because via some stupid error i cant access kodi gui with vnc now,but i queued the file now with the current drm settings.

MMan1982 avatar Mar 22 '24 13:03 MMan1982

Can you link to a freely available file (like the big buck bunny view I linked to) that shows your issue? If not can you create a sample file that shows the issue (e.g. use ffmpeg, or similar to produce a 1 minute sample) and upload it somewhere (e.g. google drive).

It caused not a specific file. Any file with h264 can cause it,but not always,and usualky restart the same file or click again the same playlist item solves it. In the worst case it needs a reboot only.

MMan1982 avatar Mar 22 '24 13:03 MMan1982

I linked a publicly available h264 file (big buck bunny). Can you confirm it happens with that file? if so, explain exactly what you did to reproduce the error.

popcornmix avatar Mar 22 '24 13:03 popcornmix

I linked a publicly available h264 file (big buck bunny). Can you confirm it happens with that file? if so, explain exactly what you did to reproduce the error.

Will do,tested with linked file and till now no error. Now i cutted a 2min from my file and testing with it queued multiple times. Usually the error comes out when the next file opened from queue,and i see a spinning bar before it plays. Usually that cannot seen(as it fast) I am using an usb hdd with external powered usb 2.0hub,but i dont think this is the problem because as i mentioned Films are playing flawless..i hope.i can show you how to reproduce because tearing out my hair from that error..

MMan1982 avatar Mar 22 '24 14:03 MMan1982

I linked a publicly available h264 file (big buck h bunny). Can you confirm it happens with that file? if so, explain exactly what you did to reproduce the error.

Can confirm that no erros with that file,nor my 2 min cutted file from the same series. Watched 20min long series then with the suggested prime settings,and when the third episode started from queue the error reappaered again. Selected the file from the queue again,the error again was there. Selected the same file again,and there was no error..i will try to attach logs again with more debug.

MMan1982 avatar Mar 23 '24 07:03 MMan1982

Reappeared,attaching debug log!(Sadly only with my full size file only.) debuglog.log

MMan1982 avatar Mar 23 '24 20:03 MMan1982

I'm on Windows, but I'm also having this problem on Android.

This are my two cents with a log

2024-04-02 20:03:50.984 T:20664    info <general>: VideoPlayer::OpenFile: pvr://channels/tv/All%20channels/[email protected]_530809091.pvr
2024-04-02 20:03:50.984 T:22280    info <general>: Creating InputStream
2024-04-02 20:03:50.987 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: inputstream.ffmpegdirect: OpenStream() - Num Props: 3
2024-04-02 20:03:50.987 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: inputstream.ffmpegdirect property: inputstream.ffmpegdirect.is_realtime_stream = true
2024-04-02 20:03:50.987 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: inputstream.ffmpegdirect property: inputstream.ffmpegdirect.manifest_type = hls
2024-04-02 20:03:50.987 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: inputstream.ffmpegdirect property: inputstream.ffmpegdirect.stream_mode = timeshift
2024-04-02 20:03:50.987 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: Stream mimetype: application/x-mpegURL
2024-04-02 20:03:50.988 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpegdirect::TimeshiftBuffer::TimeshiftBuffer - On disk length limit 'enabled', length limit set to 1.00 hours
2024-04-02 20:03:50.988 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpegdirect::FFmpegStream::OpenWithFFmpeg - IO handled by FFmpeg's AVFormat
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]: Input #0, hls, from 'https://rtvelivestream.akamaized.net/rtvesec/la1/la1_main_dvr.m3u8|origin=http://www.rtve.es':
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:   Duration: N/A, start: 50556.421333, bitrate: N/A
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:   Program 0 
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:     Metadata:
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:       variant_bitrate : 3615130
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:   Stream #0:0: Video: h264 (High) ([27][0][0][0] / 0x001B), yuv420p(progressive), 1280x720 [SAR 1:1 DAR 16:9], 25 fps, 25 tbr, 90k tbn, 50 tbc
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:     Metadata:
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:       variant_bitrate : 3615130
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:   Stream #0:1(spa): Audio: aac (LC) ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp, 195 kb/s (default)
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:     Metadata:
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:       variant_bitrate : 3615130
2024-04-02 20:03:51.325 T:22280    info <general>: AddOnLog: inputstream.ffmpegdirect: ffmpeg[A4A46C60]:       comment         : Castellano
2024-04-02 20:03:51.326 T:22280    info <general>: Creating Demuxer
2024-04-02 20:03:51.326 T:22280    info <general>: Opening stream: 0 source: 256
2024-04-02 20:03:51.326 T:22280    info <general>: Creating video codec with codec id: 27
2024-04-02 20:03:51.326 T:22280    info <general>: CDVDVideoCodecFFmpeg::Open() Using codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2024-04-02 20:03:51.326 T:22280    info <general>: Creating video thread
2024-04-02 20:03:51.326 T:20088    info <general>: running thread: video_thread
2024-04-02 20:03:51.326 T:22280    info <general>: Opening stream: 1 source: 256
2024-04-02 20:03:51.326 T:22280    info <general>: Finding audio codec for: 86018
2024-04-02 20:03:51.326 T:22280    info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2024-04-02 20:03:51.326 T:22280    info <general>: CVideoPlayerAudio::OpenStream: Allowing max Out-Of-Sync Value of 10 ms
2024-04-02 20:03:51.326 T:22280    info <general>: Creating audio thread
2024-04-02 20:03:51.327 T:2800     info <general>: running thread: CVideoPlayerAudio::Process()
2024-04-02 20:03:51.327 T:20088    info <general>: DXVA::CContext::CreateContext: creating discrete d3d11va device for decoding.
2024-04-02 20:03:51.337 T:2800     info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2024-04-02 20:03:51.337 T:2800     info <general>: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2024-04-02 20:03:51.346 T:22192    info <general>: CActiveAESink::OpenSink - initialize sink
2024-04-02 20:03:51.374 T:20088    info <general>: DXVA::CDecoder::Open: Total video memory available is 24360 MB (dedicated = 8018 MB, shared = 16342 MB)
2024-04-02 20:03:51.411 T:20664    info <general>: DXVA::CProcessorHD::InitProcessor: supported deinterlace methods: blend:yes, bob:yes, adaptive:yes, mocomp:no.
2024-04-02 20:03:51.412 T:20664 warning <general>: CRendererHQ::CheckVideoParameters: chosen scaling method 1 is not supported by renderer
2024-04-02 20:03:51.420 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.727351
2024-04-02 20:03:51.420 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.728748
2024-04-02 20:03:51.420 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.727840
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.728748
2024-04-02 20:03:51.421 T:6504     info <general>: Skipped 1 duplicate messages..
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.729237
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.729167
2024-04-02 20:03:51.421 T:6504     info <general>: Skipped 1 duplicate messages..
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.729237
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.729167
2024-04-02 20:03:51.421 T:6504     info <general>: Skipped 1 duplicate messages..
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.728678
2024-04-02 20:03:51.421 T:6504  warning <general>: ActiveAE - large audio sync error: 12441.728259
2024-04-02 20:03:51.452 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.732313
2024-04-02 20:03:51.468 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.740846
2024-04-02 20:03:51.484 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.727708
2024-04-02 20:03:51.500 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.732888
2024-04-02 20:03:51.516 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.741561
2024-04-02 20:03:51.532 T:6504  warning <general>: ActiveAE - large audio sync error: 12426.734519
2024-04-02 20:03:51.532 T:6504  warning <general>: ActiveAE - large audio sync error: 12411.735008
2024-04-02 20:03:51.548 T:6504  warning <general>: ActiveAE - large audio sync error: 12396.732276
2024-04-02 20:03:51.564 T:6504  warning <general>: ActiveAE - large audio sync error: 12381.740459
2024-04-02 20:03:51.580 T:6504  warning <general>: ActiveAE - large audio sync error: 12366.741030
2024-04-02 20:03:51.596 T:6504  warning <general>: ActiveAE - large audio sync error: 12351.742509
2024-04-02 20:03:51.612 T:6504  warning <general>: ActiveAE - large audio sync error: 12336.738311
2024-04-02 20:03:51.627 T:20088    info <general>: CDVDVideoCodecFFmpeg::CDropControl: calculated diff time: 40000
2024-04-02 20:03:51.628 T:6504  warning <general>: ActiveAE - large audio sync error: 12321.740348
2024-04-02 20:03:51.644 T:6504  warning <general>: ActiveAE - large audio sync error: 12306.748043
2024-04-02 20:03:51.660 T:6504  warning <general>: ActiveAE - large audio sync error: 12291.736231
2024-04-02 20:03:51.676 T:6504  warning <general>: ActiveAE - large audio sync error: 12276.741217
2024-04-02 20:03:51.691 T:6504  warning <general>: ActiveAE - large audio sync error: 12261.739008
2024-04-02 20:03:51.707 T:6504  warning <general>: ActiveAE - large audio sync error: 12246.746284
2024-04-02 20:03:51.723 T:6504  warning <general>: ActiveAE - large audio sync error: 12231.736428
2024-04-02 20:03:51.739 T:6504  warning <general>: ActiveAE - large audio sync error: 12216.743983
2024-04-02 20:03:51.755 T:6504  warning <general>: ActiveAE - large audio sync error: 12201.743646
2024-04-02 20:03:51.771 T:6504  warning <general>: ActiveAE - large audio sync error: 12186.735697
2024-04-02 20:03:51.771 T:6504  warning <general>: ActiveAE - large audio sync error: 12171.735766

forestrf avatar Apr 02 '24 18:04 forestrf