Improving commercial break skip support for MythTV
#31
Here you go. It was pretty easy to spot where the EDL was loaded (right after I pressed play), so here's the log from 'play' to the first ad. Not so many lines:
Code:
17:06:31 T:2968646752   DEBUG: CecLogMessage - >> 01:8b:00
17:06:31 T:2968646752   DEBUG: CecLogMessage - >> TV (0) -> Recorder 1 (1): vendor remote button up (8B)
17:06:31 T:2968646752   DEBUG: CecLogMessage - key released: select (0)
17:06:31 T:2968646752   DEBUG: PushCecKeypress - received key  b duration 342
17:06:31 T:3062005760  NOTICE: COMXPlayer: Opening: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr
17:06:31 T:3062005760 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
17:06:31 T:3062005760   DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
17:06:31 T:3062005760   DEBUG: LinuxRendererGL: Cleaning up GL resources
17:06:31 T:3062005760   DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/avutil-52-arm.so)
17:06:31 T:3062005760   DEBUG: Loading: /usr/lib/xbmc/system/players/dvdplayer/avutil-52-arm.so
17:06:31 T:3062005760   DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/swscale-2-arm.so)
17:06:31 T:3062005760   DEBUG: Loading: /usr/lib/xbmc/system/players/dvdplayer/swscale-2-arm.so
17:06:31 T:2722100320  NOTICE: Thread OMXPlayer start, auto delete: false
17:06:31 T:2722100320  NOTICE: Creating InputStream
17:06:31 T:2722100320   DEBUG: PVRManager - OpenRecordedStream - opening recorded stream ''
17:06:31 T:2722100320   DEBUG: AddOnLog: MythTV cmyth PVR Client: Suspend
17:06:31 T:2722100320   DEBUG: AddOnLog: MythTV cmyth PVR Client: Suspend Stopping Thread
17:06:31 T:2832610400   DEBUG: AddOnLog: MythTV cmyth PVR Client: Process FileOps Thread Stopped
17:06:31 T:2722100320   DEBUG: AddOnLog: MythTV cmyth PVR Client: EnablePlayback
17:06:32 T:2722100320   DEBUG: Open - Recording has started on filename pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr
17:06:32 T:2722100320   DEBUG: CDVDInputStreamPVRManager::Open - stream opened: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr
17:06:32 T:2722100320  NOTICE: Creating Demuxer
17:06:32 T:2722100320   DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/avcodec-54-arm.so)
17:06:32 T:2722100320   DEBUG: Loading: /usr/lib/xbmc/system/players/dvdplayer/avcodec-54-arm.so
17:06:32 T:2722100320   DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/avformat-54-arm.so)
17:06:32 T:2722100320   DEBUG: Loading: /usr/lib/xbmc/system/players/dvdplayer/avformat-54-arm.so
17:06:32 T:2722100320   DEBUG: Open - probing detected format [mpegts]
17:06:32 T:2722100320   DEBUG: Open - avformat_find_stream_info starting
17:06:32 T:3062005760   DEBUG: ------ Window Init (DialogBusy.xml) ------
17:06:32 T:2840999008   DEBUG: AddOnLog: MythTV cmyth PVR Client: Process - Trigger PVR recording update: 1 recording(s)
17:06:32 T:2909922400   DEBUG: CPVRRecordings - Update - updating recordings
17:06:32 T:2909922400   DEBUG: CGUIWindowPVRRecordings - UpdateData - update window 'recordings'. set view to 13
17:06:32 T:2909922400   DEBUG: CGUIMediaWindow::GetDirectory (pvr://recordings/Default/-1/)
17:06:32 T:2909922400   DEBUG:   ParentPath = [pvr://recordings/Default/-1/]
17:06:32 T:2909922400   DEBUG: CPVRDirectory::GetDirectory(pvr://recordings/Default/-1)
17:06:33 T:2909922400   DEBUG: RunQuery took 4 ms for 1 items query: SELECT  files.strFilename, files.playCount,  bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files  LEFT JOIN bookmark ON    files.idFile = bookmark.idFile AND bookmark.type = 1  WHERE files.idPath=268
17:06:33 T:2909922400   DEBUG: RunQuery took 8 ms for 1 items query: SELECT  files.strFilename, files.playCount,  bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files  LEFT JOIN bookmark ON    files.idFile = bookmark.idFile AND bookmark.type = 1  WHERE files.idPath=30
17:06:33 T:2909922400   DEBUG: RunQuery took 2 ms for 2 items query: SELECT  files.strFilename, files.playCount,  bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files  LEFT JOIN bookmark ON    files.idFile = bookmark.idFile AND bookmark.type = 1  WHERE files.idPath=8
17:06:33 T:2909922400   DEBUG: RunQuery took 2 ms for 0 items query: SELECT  files.strFilename, files.playCount,  bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files  LEFT JOIN bookmark ON    files.idFile = bookmark.idFile AND bookmark.type = 1  WHERE files.idPath=20
17:06:33 T:2909922400   DEBUG: RunQuery took 2 ms for 1 items query: SELECT  files.strFilename, files.playCount,  bookmark.timeInSeconds, bookmark.totalTimeInSeconds FROM files  LEFT JOIN bookmark ON    files.idFile = bookmark.idFile AND bookmark.type = 1  WHERE files.idPath=278
17:06:33 T:2926699616  NOTICE: Thread BackgroundLoader start, auto delete: false
17:06:34 T:2722100320    INFO: AddOnLog: MythTV cmyth PVR Client: ReadRecordedStream: Read 0 Bytes!
17:06:34 T:2722100320    INFO: Previous line repeats 2 times.
17:06:34 T:2722100320   DEBUG: Open - av_find_stream_info finished
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]: Input #0, mpegts, from 'pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr':
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]:   Duration: 00:31:58.81, start: 71156.836300, bitrate: 18312 kb/s
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]:   Program 1
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]:     Stream #0:0[0x21]: Video: mpeg2video (Main) ([2][0][0][0] / 0x0002), yuv420p, 1920x1080 [SAR 1:1 DAR 16:9], 29.97 fps, 29.97 tbr, 90k tbn, 59.94 tbc
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]:     Stream #0:1[0x24](eng): Audio: ac3 (AC-3 / 0x332D4341), 48000 Hz, 5.1(side), fltp, 384 kb/s
17:06:34 T:2722100320    INFO: ffmpeg[A23FF460]:     Stream #0:2[0x25](fre): Audio: ac3 (AC-3 / 0x332D4341), 48000 Hz, stereo, fltp, 192 kb/s
17:06:34 T:2722100320   DEBUG: CDVDDemuxFFmpeg::AddStream(0, ...) -> 0
17:06:34 T:2722100320   DEBUG: CDVDDemuxFFmpeg::AddStream(1, ...) -> 1
17:06:34 T:2722100320   DEBUG: CDVDDemuxFFmpeg::AddStream(2, ...) -> 2
17:06:34 T:2722100320   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.clock input port 80 output port 81 m_handle 0x3a5a3e0
17:06:34 T:2722100320   DEBUG: OMXClock::OMXStop
17:06:34 T:2722100320   DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
17:06:34 T:2722100320  NOTICE: Opening video stream: 0 source: 256
17:06:34 T:2722100320   DEBUG: StereoscopicsManager: Detected stereo mode in string 'pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr' is 'mono'
17:06:34 T:2722100320   DEBUG: DllBcm: Using omx system library
17:06:34 T:2722100320   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_decode input port 130 output port 131 m_handle 0x3933b90
17:06:34 T:2722100320   DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.video_decode) - port(130), nBufferCountMin(1), nBufferCountActual(120), nBufferSize(81920), nBufferAlignmen(16)
17:06:34 T:2722100320   DEBUG: COMXVideo::Open - decoder_component(0x0x3933b90), input_port(0x82), output_port(0x83) deinterlace 0 hdmiclocksync 0
17:06:34 T:2722100320    INFO: OMXPlayerVideo::OpenDecoder : Video codec omx-mpeg2 width 1920 height 1080 profile 4 fps 29.970030
17:06:34 T:2722100320    INFO: OMXPlayerVideo::OpenDecoder fps: 29.970030 hdmi_ntsc_freqs 1
17:06:34 T:2722100320  NOTICE: Creating video thread
17:06:34 T:2883245152  NOTICE: Thread OMXPlayerVideo start, auto delete: false
17:06:34 T:2722100320  NOTICE: Opening audio stream: 1 source: 256
17:06:34 T:2722100320   DEBUG: DllBcm: Using omx system library
17:06:34 T:2722100320   DEBUG: SECTION:LoadDLL(special://xbmcbin/system/players/dvdplayer/swresample-0-arm.so)
17:06:34 T:2722100320   DEBUG: Loading: /usr/lib/xbmc/system/players/dvdplayer/swresample-0-arm.so
17:06:34 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
17:06:34 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
17:06:34 T:2722100320  NOTICE: Creating audio thread
17:06:34 T:2815833184  NOTICE: Thread OMXPlayerAudio start, auto delete: false
17:06:34 T:2722100320   DEBUG: ReadEditDecisionLists - Checking for edit decision list (EDL) for PVR recording: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr
17:06:34 T:2722100320   DEBUG: ReadPvr - Reading Edl for recording: Modern Family - Farm Strong
17:06:34 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
17:06:34 T:2722100320   DEBUG: AddOnLog: MythTV cmyth PVR Client: GetRecordingEdl - Found 3 commercial breaks for: Modern Family - Farm Strong
17:06:34 T:2722100320   DEBUG: AddOnLog: MythTV cmyth PVR Client: GetRecordingEdl - Found 0 cut list entries for: Modern Family - Farm Strong
17:06:34 T:2722100320   DEBUG: AddCut - Pushing new cut to back [00:06:49.432 - 00:09:40.647], 3
17:06:34 T:2722100320   DEBUG: ReadPvr - Added break [00:06:49.432 - 00:09:40.647] found in PVRRecording for: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr.
17:06:34 T:2722100320   DEBUG: AddCut - Pushing new cut to back [00:15:36.459 - 00:19:13.119], 3
17:06:34 T:2722100320   DEBUG: ReadPvr - Added break [00:15:36.459 - 00:19:13.119] found in PVRRecording for: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr.
17:06:34 T:2722100320   DEBUG: AddCut - Pushing new cut to back [00:27:17.427 - 00:32:08.194], 3
17:06:34 T:2722100320   DEBUG: ReadPvr - Added break [00:27:17.427 - 00:32:08.194] found in PVRRecording for: pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr.
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:06:49.432
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:09:40.647
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:15:36.459
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:19:13.119
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:27:17.427
17:06:34 T:2722100320   DEBUG: AddSceneMarker - Inserting new scene marker: 00:32:08.194
17:06:34 T:2722100320   DEBUG: WriteMPlayerEdl - MPlayer EDL file written to: special://temp/xbmc.edl
17:06:34 T:2722100320   DEBUG: OnPlayBackStarted : play state was 1, starting 1
17:06:34 T:2722100320   DEBUG: COMXPlayer::SetCaching - caching state 3
17:06:34 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 0
17:06:34 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
17:06:34 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 0
17:06:34 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 0
17:06:34 T:2883245152   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 392700.000011, 1)
17:06:34 T:2883245152    INFO: COMXPlayerVideo - Stillframe left, switching to normal playback
17:06:34 T:2883245152   DEBUG: OMXVideo::Decode VDec : setStartTime 0.492800
17:06:34 T:2883245152    INFO: Output - renderer not started
17:06:34 T:3062005760   DEBUG: PlayFile : OpenFile succeed, play state 2
17:06:34 T:3062005760   DEBUG: OnPlayBackStarted : play state was 2, starting 0
17:06:34 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started 2 (tpa:0,a:0,v:1)
17:06:34 T:2815833184   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 0)
17:06:34 T:2815833184   DEBUG: COMXAudio::SetCodingType OMX_AUDIO_CodingDDP
17:06:34 T:2815833184   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_decode input port 120 output port 121 m_handle 0x3ab8940
17:06:34 T:2815833184   DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.audio_decode) - port(120), nBufferCountMin(4), nBufferCountActual(16), nBufferSize(49152), nBufferAlignmen(16)
17:06:34 T:2866467936  NOTICE: 1Channel: Service: Playback started
17:06:34 T:2815833184   DEBUG: COMXAudio::Initialize Input bps 16 samplerate 48000 channels 6 buffer size 2880000 bytes per second 576000
17:06:34 T:2815833184   DEBUG: pcm->direction      : input
17:06:34 T:2815833184   DEBUG: pcm->nPortIndex     : 0
17:06:34 T:2815833184   DEBUG: pcm->eNumData       : 0
17:06:34 T:2815833184   DEBUG: pcm->eEndian        : 1
17:06:34 T:2815833184   DEBUG: pcm->bInterleaved   : 1
17:06:34 T:2815833184   DEBUG: pcm->nBitPerSample  : 16
17:06:34 T:2815833184   DEBUG: pcm->ePCMMode       : 0
17:06:34 T:2815833184   DEBUG: pcm->nChannels      : 6
17:06:34 T:2815833184   DEBUG: pcm->nSamplingRate  : 48000
17:06:34 T:2815833184   DEBUG: OMX_AUDIO_ChannelLF
17:06:34 T:2815833184   DEBUG: OMX_AUDIO_ChannelRF
17:06:34 T:2815833184   DEBUG: COMXAudio::Initialize device passthrough 1 hwdecode 0
17:06:34 T:2815833184    INFO: Audio codec  channels 6 samplerate 48000 bitspersample 16
17:06:34 T:2815833184   DEBUG: COMXAudio::Decode ADec : setStartTime 0.000000
17:06:34 T:2815833184   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_render input port 100 output port 100 m_handle 0x343e9d8
17:06:34 T:2815833184   DEBUG: COMXAudio::PortSettingsChanged - bits:0 mode:0 channels:0 srate:0 passthrough
17:06:34 T:2815833184    INFO: COMXPlayerAudio - Switching to normal playback
17:06:34 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started RESET
17:06:34 T:2722100320  NOTICE: OMXClock using audio as reference
17:06:34 T:2722100320   DEBUG: OMXClock::OMXReset audio / video : 1 / 1 wait mask 0->3 state : 2->1
17:06:34 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started 1 (tpa:0,a:1,v:1)
17:06:34 T:2722100320   DEBUG: COMXPlayer::SetCaching - caching state 0
17:06:34 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 1000
17:06:34 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 1000
17:06:34 T:2883245152    INFO: Output - renderer not started
17:06:34 T:3062005760    INFO: Previous line repeats 6 times.
17:06:34 T:3062005760   DEBUG: CGUIInfoManager::SetCurrentMovie(pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr)
17:06:34 T:2722100320   DEBUG: Resume 0.29,0.63 (A:01 V:01) EOF:0 FULL:0 T:0.20
17:06:34 T:2722100320   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
17:06:34 T:2883245152  NOTICE: not a 3D movie
17:06:34 T:2883245152   DEBUG: ResolutionUpdateCallBack - change configuration. video:1920x1080. framerate: 29.97. 1920x1080 format: BYPASS
17:06:34 T:2883245152  NOTICE: Display resolution DESKTOP : 1920x1080 @ 60.00 - Full Screen (16)
17:06:34 T:2883245152   DEBUG: CXBMCRenderManager::Configure - 3
17:06:34 T:3014653024   DEBUG: CecLogMessage - GetPhysicalAddress - physical address = 2000
17:06:34 T:3014653024   DEBUG: CecLogMessage - physical address changed to 2000
17:06:34 T:3014653024   DEBUG: CecLogMessage - physical address unchanged (2000)
17:06:34 T:2883245152   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_render input port 90 output port 90 m_handle 0x36de898
17:06:34 T:2883245152   DEBUG: COMXVideo::PortSettingsChanged - [email protected] interlace:3 deinterlace:0
17:06:34 T:2883245152   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_scheduler input port 10 output port 11 m_handle 0x358c040
17:06:35 T:3062005760   DEBUG: GetMovieId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idMovie from movie where idFile=2207
17:06:35 T:3062005760   DEBUG: GetEpisodeId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idEpisode from episode where idFile=2207
17:06:35 T:3062005760   DEBUG: GetMusicVideoId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idMVideo from musicvideo where idFile=2207
17:06:35 T:2926699616   DEBUG: Thread BackgroundLoader 2926699616 terminating
17:06:35 T:3062005760   DEBUG: GetMovieId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idMovie from movie where idFile=2207
17:06:35 T:3062005760   DEBUG: GetEpisodeId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idEpisode from episode where idFile=2207
17:06:35 T:3062005760   DEBUG: GetMusicVideoId (pvr://recordings/Default/Modern Family/Modern Family - Farm Strong, TV (57_1 CITYTV), 20131010_010000.pvr), query = select idMVideo from musicvideo where idFile=2207
17:06:35 T:3062005760   DEBUG: CAnnouncementManager - Announcement: OnPlay from xbmc
17:06:35 T:3062005760   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnPlay
17:06:35 T:3062005760    INFO: AddOnLog: MythTV cmyth PVR Client: Received announcement: Player, xbmc, OnPlay
17:06:35 T:3062005760   DEBUG: Activating window ID: 12005
17:06:35 T:3062005760   DEBUG: ------ Window Deinit (MyPVR.xml) ------
17:06:35 T:3062005760   DEBUG: ------ Window Init (VideoFullScreen.xml) ------
17:06:35 T:3062005760    INFO: Loading skin file: VideoFullScreen.xml, load type: KEEP_IN_MEMORY
17:06:35 T:3062005760  NOTICE: Using GL_TEXTURE_2D
17:06:35 T:3062005760   DEBUG: GL: Requested render method: 0
17:06:35 T:3062005760  NOTICE: GL: Using BYPASS render method
17:06:35 T:3062005760  NOTICE: GL: NPOT texture support detected
17:06:35 T:3062005760   DEBUG: CLinuxRendererGLES: Reorder drawpoints due to method change from 1 to 256
17:06:35 T:3062005760   DEBUG: dest_rect.x_offset 0 dest_rect.y_offset 0 dest_rect.width 1920 dest_rect.height 1080
17:06:36 T:3062005760   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
17:08:52 T:2909922400   DEBUG: CPVRTimers - Update - updating timers
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 327680 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 196608 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 262144 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 65536 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 458752 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 589824 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 393216 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 131072 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 327681 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 196609 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 655360 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 720896 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 262145 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 65537 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 458753 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 589825 on client 1
17:08:52 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 393217 on client 1
17:11:40 T:2909922400   DEBUG: CPVRTimers - Update - updating timers
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 327680 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 196608 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 262144 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 65536 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 458752 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 589824 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 393216 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 131072 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 327681 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 196609 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 655360 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 720896 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 262145 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 65537 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 458753 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 589825 on client 1
17:11:40 T:2909922400   DEBUG: PVRTimers - UpdateEntries - updated timer 393217 on client 1
17:13:13 T:2722100320   DEBUG: CheckAutoSceneSkip - Clock in commercial break [00:06:49.432 - 00:09:40.647]: 00:06:49.440. Automatically skipping to end of commercial break (only done once per break)
17:13:13 T:2722100320   DEBUG: COMXPlayer::SetCaching - caching state 3
17:13:13 T:2722100320   DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
17:13:13 T:2722100320   DEBUG: demuxer seek to: 580648
17:13:13 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 0
17:13:13 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_STARTED 1
17:13:13 T:2722100320    INFO: AddOnLog: MythTV cmyth PVR Client: ReadRecordedStream: Read 0 Bytes!
17:13:13 T:2722100320    INFO: Previous line repeats 1 times.
17:13:13 T:2722100320   DEBUG: SeekTime - seek ended up on time 580466
17:13:13 T:2722100320   DEBUG: demuxer seek to: 580648000, success
17:13:13 T:2722100320  NOTICE: FlushBuffers: q:0 pts:580648000 a:1
17:13:13 T:2722100320   DEBUG: OMXClock::OMXStop
17:13:13 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 0
17:13:13 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 1
17:13:13 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::GENERAL_FLUSH
17:13:13 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_FLUSH
17:13:13 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
17:13:13 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
17:13:13 T:2722100320   DEBUG: OMXClock::OMXMediaTime set config OMX_IndexConfigTimeCurrentAudioReference = 0.00
17:13:13 T:2883245152   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 581039433.333339, 1)
17:13:13 T:2883245152    INFO: COMXPlayerVideo - Stillframe left, switching to normal playback
17:13:13 T:2883245152   DEBUG: OMXVideo::Decode VDec : setStartTime 581.039433
17:13:13 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started 2 (tpa:0,a:0,v:1)
17:13:14 T:2815833184   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(-4503599627370496.000000, 0)
17:13:14 T:2815833184   DEBUG: COMXAudio::Decode ADec : setStartTime 580.640015
17:13:14 T:2815833184    INFO: COMXPlayerAudio - Switching to normal playback
17:13:14 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started RESET
17:13:14 T:2722100320   DEBUG: OMXClock::OMXReset audio / video : 1 / 1 wait mask 0->3 state : 2->1
17:13:14 T:2722100320   DEBUG: COMXPlayer::HandleMessages - player started 1 (tpa:0,a:1,v:1)
17:13:14 T:2722100320   DEBUG: COMXPlayer::SetCaching - caching state 0
17:13:14 T:2815833184   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_SETSPEED 1000
17:13:14 T:2883245152   DEBUG: COMXPlayerVideo - CDVDMsg::PLAYER_SETSPEED 1000
17:13:14 T:2722100320   DEBUG: Resume 580.77,581.27 (A:01 V:01) EOF:0 FULL:0 T:0.20
17:13:14 T:2722100320   DEBUG: OMXClock::OMXSetSpeed(1.00) pause_resume:1
Reply
#32
Further to the above log, here are the relevant lines from my advancedsettings.xml file:
Code:
<edl>
   <mergeshortcommbreaks>true</mergeshortcommbreaks>
   <maxcommbreaklength>150</maxcommbreaklength>
   <mincommbreaklength>90</mincommbreaklength>
   <maxcommbreakgap>120</maxcommbreakgap>
   <commbreakautowait>30</commbreakautowait>
   <commbreakautowind>0</commbreakautowind>
</edl>
Reply
#33
Any news?
Reply
#34
I'll check the EDL code tomorrow night. It doesn't look like the PVR loading of the MythTV breaks is going through the code pathway that merges or adjusts them based on the Advanced Settings.
Use MythTV for recording TV? Try the integrated MythTV support in XBMC Media Center. Now with commercial skip support built-in and integration with the Movie database!
Reply
#35
I should add that - on the rPi anyway - It cuts to commercial a second or two early. The show freezes for about a second (with someone in the middle of a sentence) and then skips the ad.

I was trying to use the commbreakautowait setting to work around this problem. Another (unavailable but desirable) workaround would be an option to turn off autoskip (i.e. don't skip automatically when you get to the ad, but skip the ad when you press 'big skip' during the ad). Such an option would be very useful.
Reply
#36
I am running mythtv .27 and xmbc 13.0-alpha10 git;20131113 on raspbmc.

Commercial skip works, but only to a point. It will make it all the way through a show. But some of the timing of the skips are off. And it seems to be due to the fact that xbmc writes the EDL file out using the time based markup instead of frames. Mythtv and it's xbmc pvr plugin can provide the skip information by frame, but this seems to always be converted to time. For shows that have a variable frame rate using what is returned by ffmpeg or assumed does not seem to work.

Digging through the code it looks like xbmc writes out the EDL from xbmc/cores/dvdplayer/dvdplayer/Edl.cpp .

Would it be possible to change this to write out an mplayer EDL that uses frames instead of time.

Thanks
Chris
Reply
#37
My experience with XBMC gotham alpha on the Raspberry Pi is the same as yours, but I find that commercial skipping is perfect with XBMC gotham alpha on a mac (OS X). That suggests that, if the issue you suggest is having an impact, there is probably another issue as well that is unique to the Pi build.
Reply
#38
It could be the way omxplayer is handling the timing in the EDL file on the pi. In previous builds before gotham I mounted my mythtv recordings directory to my pi and exported EDL files using frames and it worked great with the omxplayer. It was just kinda a stop gap solution until these features were in xbmc.
Reply
#39
Popcornmix was asking me to try exactly what you just described, so he could try to address the issue, but I could not figure out how. Would you mind trying again with a recent build?
Reply
#40
I just tried my old solution on the current gotham build. And it seems the xbmc converts the edl file to time based and uses that.

original cut file:
Code:
#20825 #31838 0
#56045 #69522 0
#103479 #115423 0
#133561 #148850 0
#170507 #186352 0
#217286 #227275 0

xbmc processed version of cutlist:
Code:
pi@raspbmc:~/.xbmc/temp$ cat xbmc.edl
347.000 531.000 0
935.000 1159.000        0
1726.000        1925.000        0
2228.000        2483.000        0
2844.000        3108.000        0
3625.000        3791.000        0

debug logging:
Code:
19:56:11 T:2779771968   DEBUG: ReadEditDecisionLists - Checking for edit decision lists (EDL) on local drive or remote share for: /media/xbmc/tvshows/Greys Anatomy/Greys Anatomy.s10.e4.mpg
19:56:11 T:2771383360   DEBUG: COMXPlayerAudio - CDVDMsg::PLAYER_STARTED 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [00:05:47.430 - 00:08:51.163], 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [00:15:35.017 - 00:19:19.858], 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [00:28:46.374 - 00:32:05.640], 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [00:37:08.242 - 00:41:23.314], 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [00:47:24.625 - 00:51:48.972], 0
19:56:11 T:2779771968   DEBUG: AddCut - Pushing new cut to back [01:00:25.054 - 01:03:11.704], 0
19:56:11 T:2779771968   DEBUG: ReadEdl - Read 6 cuts and 0 scene markers in EDL file: /media/xbmc/tvshows/Greys Anatomy/Greys Anatomy.s10.e4.edl
Reply
#41
Does it work correctly?
Reply
#42
After watching that and some other shows it still seems to be coming out wrong. Skips start to early still. And these are all variable frame rate videos. Typically commercials are 29.97 and the show is 59.94.
Reply
#43
Another possibility is using the mythtv recordedseek table. type 33 is an offset of Milliseconds from the start of the show and the mark is a keyframe. Just have to find the keyframe after the frame (for break start, keyframe before for break stop) from the recordedmarkup table and then you can get the exact time position in milliseconds of the commercial.
Reply
#44
Example from the database (mythtv .27 not sure if this works in previous versions)

Code:
breaks
select * from recordedmarkup where chanid=5772 and starttime="2013-11-05 04:00:00";
+--------+---------------------+-------+------+---------+
| chanid | starttime           | mark  | type | data    |
+--------+---------------------+-------+------+---------+
|   5772 | 2013-11-05 04:00:00 |     0 |   -3 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 17213 |    4 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 29964 |    4 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 47255 |    4 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 21166 |    5 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 35944 |    5 |    NULL |
|   5772 | 2013-11-05 04:00:00 | 53943 |    5 |    NULL |
|   5772 | 2013-11-05 04:00:00 |     1 |   12 |    NULL |
|   5772 | 2013-11-05 04:00:00 |     1 |   30 |    1920 |
|   5772 | 2013-11-05 04:00:00 |     1 |   31 |    1080 |
|   5772 | 2013-11-05 04:00:00 |     1 |   32 |   29970 |
|   5772 | 2013-11-05 04:00:00 |     0 |   33 | 1863000 |
|   5772 | 2013-11-05 04:00:00 |     0 |   34 |   53649 |
+--------+---------------------+-------+------+---------+




beginning of break
select * from recordedseek where chanid=5772 and starttime="2013-11-05 04:00:00" and mark > 17213 and type=33 limit 1;
+--------+---------------------+-------+--------+------+
| chanid | starttime           | mark  | offset | type |
+--------+---------------------+-------+--------+------+
|   5772 | 2013-11-05 04:00:00 | 17220 | 574641 |   33 |
+--------+---------------------+-------+--------+------+


end of break
select * from recordedseek where chanid=5772 and starttime="2013-11-05 04:00:00" and type=33 and mark in (select max(mark) as maxmark from recordedseek where chanid=5772 and starttime="2013-11-05 04:00:00" and mark < 21166 and type=33) ;
+--------+---------------------+-------+--------+------+
| chanid | starttime           | mark  | offset | type |
+--------+---------------------+-------+--------+------+
|   5772 | 2013-11-05 04:00:00 | 21164 | 729862 |   33 |
+--------+---------------------+-------+--------+------+

Gives 1st break at 574.641 (9:57) - 729.862 (12:16)


calculated using seek table
574.641 729.862 0
1023.689 1249.181 0
1627.793 1861.393 0

xbmc calculated
574.000 729.000 0
1023.000 1249.000 0
1627.000 1861.000 0
Reply
#45
I don't understand how your calculation is done, but it appears from your conclusion that XBMC truncates the times to whole seconds. This would cause a maximum error of just under one second, and an average error of half a second. I do sometimes notice that the skip reenters a fraction of a second too early after an ad, but this truncating error does not account for the beginning of the skip. The skip starts several seconds too early.
Reply

Logout Mark Read Team Forum Stats Members Help
Improving commercial break skip support for MythTV0