Ticket #12984 (closed Bugs: Fixed)

Opened 2 years ago

Last modified 22 months ago

Non-flushed seeking with CDVDMsgPlayerSeek results in large delay before playback resumes

Reported by: dteirney Owned by: dteirney
Priority: 4 - Normal Milestone: 12.0
Component: Video playback (inc. audio in video and codecs) Version: 11.0 "Eden"
Severity: Normal Keywords: seek dvdplayer
Cc: elupus Blocked By:
Blocking: Platform: All
Revision:

Description

I've been looking into a playback problem that was being experienced by some MythTV users when commercial breaks were being automatically skipped. When the automatic seek was triggered playback would halt for a long time >10 seconds on my test machine and much longer for some other users.

I've tracked it down to non-flushed seeking in dvdplayer.

With non-flushed seeking it has a long delay. With flushed seeking it's as fast as normal seeking. The automated seeking looks like the only place that uses non-flushed seeking.

I've attached log files showing behaviour with flushed and non-flushed automatic seeks. Someone who knows more about how all the different caching states and synchronize mechanisms might be able to point out any potential problem areas faster than I could.

Attachments

flushed-commskip.log Download (164.4 KB) - added by dteirney 2 years ago.
not-flushed.log Download (167.3 KB) - added by dteirney 2 years ago.
backtrace.txt Download (10.3 KB) - added by dteirney 2 years ago.
backtrace.2.txt Download (18.1 KB) - added by dteirney 2 years ago.
backtrace.3.txt Download (16.2 KB) - added by dteirney 2 years ago.
sample.edl Download (11 bytes) - added by dteirney 23 months ago.
Sample EDL file with one commercial break from 5 seconds to 2 minutes
xbmc.log Download (161.5 KB) - added by dteirney 22 months ago.
Log file showing the "go slow mode" after the automated commskip seek
xbmc-short-edl-cuts.log Download (831.1 KB) - added by dteirney 22 months ago.
Log file showing some strange behavior with several close together EDL cuts
xbmc-slow-mo.log Download (194.5 KB) - added by dteirney 22 months ago.
Log file showing the "go slow mode" after the automated commskip seek

Change History

Changed 2 years ago by dteirney

Changed 2 years ago by dteirney

comment:1 Changed 2 years ago by dteirney

Searching for "Automatically skipping" helps get to the interesting part.

comment:2 Changed 2 years ago by dteirney

I've spent a while looking at this tonight. The behaviour changes based on the duration of the non-flushed seek. If the seek duration is shorter than around 10 seconds everything works as expected. Packets are dropped according to the logs and the playback is more or less seamless. However, if the seek duration is longer than around 10 seconds there is a halt in playback.

The GeneralSynchronize in CDVDPlayer::SynchronizePlayers called from CDVDPlayer::FlushBuffers is timing out when the non-flushed seek is longer than around 10 seconds. Whatever I set the timeout to be in SynchronizePlayers that's appears to be how long playback stalls for.

I can't easily follow why that lock isn't being released. I'm not sure if the video and audio queues are being put into the right state within FlushBuffers prior to SynchronizePlayers being called, or whether something else is supposed to be done after the GeneralSynchronize message is set for the startsync member on the audio and video streams as these only then get queued in the CheckPlayerInit method.

Also, I don't follow why a VIDEO_NOSKIP message would be sent to the video stream prior to trying to synchronize.

Setting the timeout to be something small, e.g. 100 rather than 10*1000 in SynchronizePlayers fixes the apparent problem but doesn't resolve why it is happening.

@elupus, any advice on what to look for?

comment:3 Changed 2 years ago by dteirney

  • Owner set to dteirney
  • Status changed from new to assigned

Pull request for review up at  https://github.com/xbmc/xbmc/pull/944

comment:4 Changed 2 years ago by sho

  • Component changed from Other (un-categorized) to Video playback (inc. audio in video and codecs)

comment:5 Changed 2 years ago by dteirney

Having some issues getting debugging working with Eclipse so I've got a backtrace using gdb. My gdb foo is weak though and don't know how to get more than the listing of the frames.

Below is the backtrace while XBMC is stalled after CDVDMsgGeneralSynchronize object is created in SynchronizePlayers through non-flushed seeking triggered by a commercial break. Curiously I couldn't reproduce the behaviour with an .avi test file I had lying around from previous EDL tests but could with an .mpg file being played off disk (which is a copy of a MythTV recording).

Doesn't seem all that useful other than confirming that 3 threads are waiting on the lock... Let me know if I can make this more useful.

(gdb) bt
#0  0x00130416 in __kernel_vsyscall ()
#1  0x00cd3e04 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
#2  0x08ab0181 in wait (lock=<optimized out>, milliseconds=<optimized out>, this=<optimized out>)
    at /home/david/workspace/xbmc/xbmc/threads/platform/pthreads/Condition.h:81
#3  wait (milliseconds=<optimized out>, lock=<optimized out>, this=<optimized out>)
    at /home/david/workspace/xbmc/xbmc/threads/platform/pthreads/Condition.h:85
#4  wait<CSingleLock> (milliseconds=100, lock=<optimized out>, this=<optimized out>) at threads/Condition.h:66
#5  CApplication::Render (this=0x8e7ba80) at Application.cpp:2069
#6  0x08b5cfd6 in CXBApplicationEx::Run (this=0x8e7ba80) at XBApplicationEx.cpp:145
#7  0x082381b1 in main (argc=1, argv=0xbffff904) at xbmc.cpp:97

comment:6 Changed 2 years ago by elupus

Thread apply all bt

to get from all threads.

Changed 2 years ago by dteirney

Changed 2 years ago by dteirney

comment:7 Changed 2 years ago by dteirney

backtrace.2.txt has the good stuff in it.

Changed 2 years ago by dteirney

comment:8 Changed 2 years ago by dteirney

Also another backtrace.3.txt file for good measure.

comment:9 Changed 23 months ago by elupus

I didn't have any edl samples, but I did spot one issue with non flushed seeks if i hacked normal seeks to be non flushed, that should be fixed in 5de9c47f9fa11d08c5300361f021ad1d798a5bf9

I'd need some edl file that exhibits the issue to debug it furhter if above doesn't fix it.

comment:10 Changed 23 months ago by dteirney

Thanks so much elupus. I'm between ISPs at the moment so don't have internet at home. Goodness only knows why it's so hard to change ISPs here in New Zealand. I'll test this as soon as I'm connected back to the internet.

I'll attach a sample.edl file that should perform a commercial skip at 5 seconds into the file and end up at 2 minutes into the file. It would need to be renamed to be the same as the video file.

Note that I couldn't reproduce the problem with .avi files but could with mpeg(ts) files.

Changed 23 months ago by dteirney

Sample EDL file with one commercial break from 5 seconds to 2 minutes

comment:11 Changed 22 months ago by dteirney

I've tested the changes. The synchronize timeout occurring now seems to be related to the length of the file. The automatic commercial skip still seems to timeout after 10 seconds on a large file but if I trim the file using dd (so it's not 6Gb to download) then the seeking seems to work quickly.

I don't know if it's related but the commskip also seems to trigger "go slow mode" where the playback seems to go down to 1fps after the skip. This was the case before the change as well. I've put a couple of sample files up on my Amazon S3 account that shows that problem. Not sure if it should be a new ticket.

 http://s3.teirney.net/xbmc/samples/dvb-t-h264-1080i-sample.mpg (95Mb)  http://s3.teirney.net/xbmc/samples/dvb-t-h264-1080i-sample.edl

 http://s3.teirney.net/xbmc/samples/1003_20090318213000.mpg (205Mb)  http://s3.teirney.net/xbmc/samples/1003_20090318213000.edl

Changed 22 months ago by dteirney

Log file showing the "go slow mode" after the automated commskip seek

comment:12 Changed 22 months ago by elupus

I think:  https://github.com/xbmc/xbmc/pull/1084 should resolve this issue.

Changed 22 months ago by dteirney

Log file showing some strange behavior with several close together EDL cuts

comment:13 Changed 22 months ago by dteirney

The log file recently attached was generated with a test EDL file that has EDL cuts configured so there is a 2 second cut followed by 2 seconds of playback and so on. It sounds like some of the audio packets get played over more than once. The phenomenon is worse with another test file configured to have a 1 second cut followed by 1 second of playback.

Muting seems to be fine.

The log was with  https://github.com/xbmc/xbmc/pull/1084 merged in.

comment:14 Changed 22 months ago by elupus

It would seem to be re-triggering the same cut multiple times. The seek ends up furhter back, and we then decode until we get to the starting point.

2182	22:28:28 T:2815466352   DEBUG: CheckPlayerInit - dropping packet type:2 dts:13960000.000000 to get to start point at 14000000.000000
2183	22:28:28 T:2815466352   DEBUG: CheckAutoSceneSkip - Clock in EDL cut [00:00:12.000 - 00:00:14.000]: 00:00:14.000. Automatically skipping over.

When it's done with getting to the expected time, 14.000 current time is something like 13.9999 and it re-triggers the cut.

comment:15 Changed 22 months ago by dteirney

I'll look into how to fix that tomorrow night. Would have spent more time tonight but I have an early meeting tomorrow.

comment:16 Changed 22 months ago by dteirney

Fixes for the retriggering of the seeks is in  https://github.com/xbmc/xbmc/pull/1091

Changed 22 months ago by dteirney

Log file showing the "go slow mode" after the automated commskip seek

comment:17 Changed 22 months ago by dteirney

I've attached a log file showing the "go slow mode" that happens after the commercial break is skipped. Search for "Automatically skipping to end of commercial break" to find interesting stuff.

As mentioned this was a problem before the fixes in pull 1091 were created. The problem is still there with those fixes. Consistently reproducing seems to be a problem though. I managed to get it every time I was playing one of my samples (the one in the log file) and was testing variations of that file at different lengths to see if that shed any light. All the shorter versions worked fine but now so is the original.

We are definitely seeing the problem on our HTPC with MythTV recordings (the sample is a copied recording). We need to stop playback and restart from the resume position as the "go slow mode" doesn't seem to end.

I've looked at the differences between the not working fine log and a working fine log. It appears that when the problem occurs there is a second

CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available

Followed by:

17:09:01 T:2715044720 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
17:09:01 T:2706652016   DEBUG: CSoftAEStream::Flush
17:09:01 T:2797661040   DEBUG: CDVDPlayer::SetCaching - caching state 1
17:09:01 T:2715044720    INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback

And then a repeated cycle (with some variations) of:

17:09:07 T:2706652016   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
17:09:07 T:2706652016   ERROR: AddPackets - failed to add leftover bytes to render
17:09:07 T:2706652016   DEBUG: CDVDPlayerAudio:: Discontinuity - was:121744966.887221, should be:120566200.222221, error:-1178766.665001

I don't have any more time this weekend to look any further.

comment:18 Changed 22 months ago by dteirney

The remaining problems experienced after a non-flushed seek seem to be related to #13133, which was spawned from  https://github.com/opdenkamp/xbmc/issues/548

comment:19 Changed 22 months ago by dteirney

  • Status changed from assigned to closed
  • Resolution set to Fixed
  • Milestone changed from Future / Pending to 12.0

Since core problem has been resolved remaining issues are best tracked in #13133.

Note: See TracTickets for help on using tickets.