Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[AMLCodec] dont poll decoder rate when seeking #15835

Merged
merged 1 commit into from Mar 29, 2019

Conversation

Projects
None yet
2 participants
@jahutchi
Copy link
Contributor

commented Mar 29, 2019

Description

The following commit (submitted by me) has introduced a regression whereby playback can freeze following seek operations: #15667

This commit builds on the previous one, to ensure the decoder fps rate is only queried when in normal playback mode.

Motivation and Context

Following #15667 playback may freeze following seek operations when using AML H/W acceleration.

I added extra debugging here to show the values of vs.fps following a series of SkipForward actions:

2019-03-26 18:28:35.104 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(0)
2019-03-26 18:28:35.105 T:3571430128   DEBUG: CAMLCodec::Reset
2019-03-26 18:28:35.105 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:35.114 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=-1345504273
2019-03-26 18:28:35.248 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(1000)
2019-03-26 18:28:35.272 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:35.405 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:35.807 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:38.453 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(0)
2019-03-26 18:28:38.453 T:3571430128   DEBUG: CAMLCodec::Reset
2019-03-26 18:28:38.454 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=-1378086889
2019-03-26 18:28:38.464 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=-1346224265
2019-03-26 18:28:38.552 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(1000)
2019-03-26 18:28:38.577 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:38.709 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:39.442 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:39.710 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:41.394 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(0)
2019-03-26 18:28:41.394 T:3571430128   DEBUG: CAMLCodec::Reset
2019-03-26 18:28:41.429 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=-1349443209
2019-03-26 18:28:41.520 T:3571430128   DEBUG: CAMLCodec::SetSpeed, speed(1000)
2019-03-26 18:28:41.551 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29
2019-03-26 18:28:41.683 T:4071772160   DEBUG: CAMLCodec::GetDecoderVideoRate fps=29

During seek/skip operations the decoder rate is being queried in the middle of CAMLCodec::Reset. This yields unpredictable results, since the fps value being returned from the AML API appears to be undefined (depends what is on the stack at the time).

If the value happens to be positive then this can lead to undesirable results, as shown here where the video completely froze following a seek; notice the rate was adjusted to 41 (vs.fps would have been approx 2341):

2019-03-25 20:45:10.753 T:4072038400   DEBUG: HandleKey: sleep (0xdf) pressed, action is StepForward
2019-03-25 20:45:10.753 T:4072038400   DEBUG: HandleKey: 0 (0x00, obc255) pressed, action is
2019-03-25 20:45:10.806 T:3247112944   DEBUG: CPtsTracker: detected pattern of length 1: 41708.33, frameduration: 41708.333333
2019-03-25 20:45:12.255 T:4072035056   DEBUG: CAnnouncementManager - Announcement: OnSeek from xbmc
2019-03-25 20:45:12.256 T:4072035056   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnSeek
2019-03-25 20:45:12.258 T:3625972464   DEBUG: CVideoPlayer::SetCaching - caching state 1
2019-03-25 20:45:12.259 T:3625972464   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2019-03-25 20:45:12.259 T:3625972464   DEBUG: demuxer seek to: 98345.063202
2019-03-25 20:45:12.259 T:3625972464   DEBUG: SeekTime - seek ended up on time 100136
2019-03-25 20:45:12.259 T:3625972464   DEBUG: demuxer seek to: 98345.063202, success
2019-03-25 20:45:12.259 T:3625972464   DEBUG: CVideoPlayer::FlushBuffers - flushing buffers
2019-03-25 20:45:12.270 T:3247112944   DEBUG: CAMLCodec::SetSpeed, speed(0)
2019-03-25 20:45:12.270 T:3247112944   DEBUG: CAMLCodec::Reset
2019-03-25 20:45:12.281 T:3609187056   DEBUG: CDVDAudio::Pause - pausing audio stream
2019-03-25 20:45:12.308 T:4072038400   DEBUG: CAMLCodec::SetVideoRect: decoder fps has changed, video_rate adjusted from 4174 to 41
2019-03-25 20:45:12.374 T:3609187056   DEBUG: CDVDAudio::Flush - flush audio stream
2019-03-25 20:45:12.374 T:3609187056   DEBUG: CDVDAudio::Pause - pausing audio stream
2019-03-25 20:45:12.374 T:3609187056   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
2019-03-25 20:45:12.374 T:3625972464   DEBUG: CVideoPlayer::SetCaching - caching state 2
2019-03-25 20:45:12.374 T:3247112944   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
2019-03-25 20:45:12.374 T:3625972464   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2019-03-25 20:45:12.375 T:3247112944    INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback
2019-03-25 20:45:12.384 T:3609187056   DEBUG: CDVDAudio::Pause - pausing audio stream
2019-03-25 20:45:12.392 T:3625972464   DEBUG: CVideoPlayer::HandleMessages - player started 1
2019-03-25 20:45:12.392 T:3238720240   DEBUG: OnAVChange: CApplication::OnAVChange
2019-03-25 20:45:12.392 T:4072035056   DEBUG: CAnnouncementManager - Announcement: OnAVChange from xbmc
2019-03-25 20:45:12.392 T:4072035056   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnAVChange
2019-03-25 20:45:12.449 T:3625972464   DEBUG: VideoPlayer::Sync - Audio - pts: 100425000.000000, cache: 301859.408617, totalcache: 785759.627819
2019-03-25 20:45:12.450 T:3625972464   DEBUG: CVideoPlayer::SetCaching - caching state 0
2019-03-25 20:45:12.450 T:3609187056   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(62039708.333333), level: 100, cache: 301859.408617
2019-03-25 20:45:12.450 T:3625972464   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2019-03-25 20:45:12.450 T:3609187056   DEBUG: CDVDAudio::Resume - resume audio stream
2019-03-25 20:45:12.450 T:4041208560 WARNING: ActiveAE - large audio sync error: 38096.385102
2019-03-25 20:45:12.450 T:4041208560   DEBUG: ActiveAE - start sync of audio stream
2019-03-25 20:45:12.450 T:3247112944   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(62039708.333333)
2019-03-25 20:45:12.451 T:4041208560 WARNING: ActiveAE - large audio sync error: 38095.161484
2019-03-25 20:45:12.451 T:3247112944   DEBUG: CAMLCodec::SetSpeed, speed(1000)
2019-03-25 20:45:12.451 T:4041208560 WARNING: ActiveAE - large audio sync error: 38094.002700
2019-03-25 20:45:12.452 T:4041208560 WARNING: ActiveAE - large audio sync error: 38092.969874
2019-03-25 20:45:12.453 T:4041208560 WARNING: ActiveAE - large audio sync error: 38092.903756
2019-03-25 20:45:12.512 T:4041208560 WARNING: ActiveAE - large audio sync error: 37933.428138
2019-03-25 20:45:12.558 T:4041208560 WARNING: ActiveAE - large audio sync error: 37932.957014
2019-03-25 20:45:12.558 T:4041208560   DEBUG: ActiveAE::SyncStream - average error of 5000.000000, start adjusting
2019-03-25 20:45:12.605 T:4041208560 WARNING: ActiveAE - large audio sync error: 37886.502222
2019-03-25 20:45:12.651 T:4041208560 WARNING: ActiveAE - large audio sync error: 37840.031430
2019-03-25 20:45:14.044 T:4041208560 WARNING: ActiveAE - large audio sync error: 36447.253221
2019-03-25 20:45:14.090 T:4041208560 WARNING: ActiveAE - large audio sync error: 36408.924432
2019-03-25 20:45:14.111 T:4062180080   DEBUG: LIRC: - NEW a4 0 KEY_PLAYPAUSE linux-input-layer (KEY_PLAYPAUSE)
2019-03-25 20:45:14.111 T:4062180080   DEBUG: LIRC: - NEW a4 0 KEY_PLAYPAUSE_UP linux-input-layer (KEY_PLAYPAUSE_UP)
2019-03-25 20:45:14.131 T:4072038400   DEBUG: HandleKey: homepage (0xea) pressed, action is PlayPause
2019-03-25 20:45:14.132 T:4072035056   DEBUG: CAnnouncementManager - Announcement: OnPause from xbmc
2019-03-25 20:45:14.132 T:4072035056   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPause
2019-03-25 20:45:14.137 T:4041208560 WARNING: ActiveAE - large audio sync error: 36362.488223
2019-03-25 20:45:14.183 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.411265
2019-03-25 20:45:14.230 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.398765
2019-03-25 20:45:14.276 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.389765
2019-03-25 20:45:14.323 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.393931
2019-03-25 20:45:14.369 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.389307
2019-03-25 20:45:14.416 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.410306
2019-03-25 20:45:14.462 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.402432
2019-03-25 20:45:14.478 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:14.509 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.435432
2019-03-25 20:45:14.555 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.418015
2019-03-25 20:45:14.602 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.419223
2019-03-25 20:45:14.648 T:4041208560 WARNING: ActiveAE - large audio sync error: 36357.420973
2019-03-25 20:45:14.679 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:14.679 T:3609187056   DEBUG: CDVDAudio::Pause - pausing audio stream
2019-03-25 20:45:15.007 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:17.433 T:3609187056 WARNING: Previous line repeats 4 times.
2019-03-25 20:45:17.433 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:17.551 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:19.444 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:19.444 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:19.595 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:21.454 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:21.454 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:21.597 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:23.466 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:23.466 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:23.599 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:25.476 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:25.476 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:25.601 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:27.487 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:27.488 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:27.603 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:29.499 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:29.499 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:29.605 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:31.509 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:31.509 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:31.607 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:33.521 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:33.521 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:33.609 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:35.531 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:35.531 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:35.652 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
2019-03-25 20:45:37.544 T:3609187056 WARNING: Previous line repeats 3 times.
2019-03-25 20:45:37.544 T:3609187056   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2019-03-25 20:45:37.655 T:3247112944 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer

The issue occurs entirely at random, as it all depends what is on the memory stack at the time, but is easy to reproduce (just perform a few SkipFoward actions).

I think this was introduced when we made a final change to #15667, just prior to merge, to use C++ style casts. I had previously tested for over a week with no issues; however, I started to notice this issue pretty soon after the final version was merged.

This patch fixes things by skipping the decoder rate check and video_rate (re)-calculation if either:

  1. We're not in normal playback mode: m_speed != DVD_PLAYSPEED_NORMAL
  2. We're in the middle of a Reset: m_pollDevice < 0

Thus avoiding us trying to read an undefined fps rate variable from the AML API (which leads to "undefined" behaviour).

It also ensures the fps rate is >0 before running the calculation, so there's no chance we ever attempt to divide by zero.

How Has This Been Tested?

With a sample 60 minute video...

Without this fix, playback freezes after performing a few SkipForward actions.

With this fix in place, I skipped through the same entire file, from start to finish in 10 second SkipFoward increments (>300 skips) without any playback freezes whatsoever. I repeated this same test with samples using other various frame rates; again without any problems.

Screenshots (if appropriate):

Types of change

  • Bug fix (non-breaking change which fixes an issue)
  • Clean up (non-breaking change which removes non-working, unmaintained functionality)
  • Improvement (non-breaking change which improves existing functionality)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that will cause existing functionality to change)
  • Cosmetic change (non-breaking change that doesn't touch code)
  • None of the above (please explain below)

Checklist:

  • My code follows the Code Guidelines of this project
  • My change requires a change to the documentation, either Doxygen or wiki
  • I have updated the documentation accordingly
  • I have read the Contributing document
  • I have added tests to cover my change
  • All new and existing tests passed
@jahutchi

This comment has been minimized.

Copy link
Contributor Author

commented Mar 29, 2019

@peak3d would you mind taking a look?

@peak3d peak3d added this to the Leia 18.2-rc1 milestone Mar 29, 2019

@peak3d peak3d merged commit 9114f65 into xbmc:master Mar 29, 2019

1 check passed

default You're awesome. Have a cookie
Details

@jahutchi jahutchi deleted the jahutchi:aml-dont-poll-fps-when-seeking branch Mar 29, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.