[Helix-client-dev] CN-Client: Core start performance
Milko Boic milko at real.comModified by: milko at real.com Date: 8:28:06 Project: Atlas Synopsis: Player core start optimizations Overview: The change provides logistical optimizations for management of time and data flow processing during start-up period. Prior logic was inefficient due to insufficient granularity among data retrieval, data transfer to renderers/devices and buffering fulfillment determination. Previously small time-gaps also occurred when transitioning between start-up states due to necessary deferral to next player processing slice (a.k.a process idle). A test of an A/V clip on windows platform shows more than 50% reduction in start-up time (631ms -> 307ms). See detailed trace below. The new logic during buffering phase, moves data from data source into renderers one packet at the time and at the moment the initial buffering needs are satisfied, the resumption of audio is attempted and then any remaining buffering needs addressed. The start-up from local files takes advantage of fast-start behavior by resuming the playback as soon as first frame of video and minimal audio pushdown of audio have been supplied to the output devices. New set of logging statements has been added based on which this work was done: "CORP" - Core Performance A few issues have been fixed as well: - core lock accounting was flawed since it used a boolean and was invalidate in some cases by recursive calls - Accounting of buffering in file source as part of FillBuffers was conceptually incorrect and resulted in premature start of play. The buffering must be accounted at the time event is supplied. FillBuffers only provides async to sync data retrieval conversion and any buffering at that level cannot be counted toward completion of buffering since this data is not yet checked for transfer to renderers. That is, data buffered by FillBuffers is the equivalent of transport buffer in network source. - base video renderer smoothing filter is now reset on occurrence of buffering resulting in faster re-sync to the new time-line. Previously, sluggishness could be observed until the filter received sufficient number of new samples to re-lock onto new time-line trend. Timing Results: =============== New improved core: ------------------ CORE 43490241 2212 HXPlayer[00B5ACD8]::OpenURL(): file://br-av-ss-hi.rm CORE 43490252 2212 ClientPrerollHelper::GetPreroll() header [00BABF68]: Preroll 1864 PostDecodeDelay 0 Total 1864 CORE 43490252 2212 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::OnStreamHeader() StreamNum=0 PreRoll=1864 PreData=0 PDStart=0 PDSeek=0 PRStart=0 PRSeek=0 AvgBitRate=603532 MaxBitRate=603532 mimeType=video/x-pn-realvideo CORE 43490253 2212 ClientPrerollHelper::GetPreroll() header [00BAD680]: Preroll 3714 PostDecodeDelay 0 Total 3714 CORE 43490253 2212 HXBufferingState[audio/x-pn-realaudio-00BB486D]::OnStreamHeader() StreamNum=1 PreRoll=3714 PreData=0 PDStart=0 PDSeek=0 PRStart=0 PRSeek=0 AvgBitRate=96468 MaxBitRate=96468 mimeType=audio/x-pn-realaudio CORE 43490254 2212 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::Init(ulPerfectPlayTime=0) CORE 43490254 2212 HXBufferingState[audio/x-pn-realaudio-00BB486D]::Init(ulPerfectPlayTime=0) CORE 43490254 2212 HXPlayer[00B5ACD8]::Begin() CORE 43490254 2212 HXPlayer[00B5ACD8]::BeginPlayer() CORE 43490256 2212 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::OnStream(pStream=0x00bab860) CORE 43490257 2212 HXBufferingState[audio/x-pn-realaudio-00BB486D]::OnStream(pStream=0x00bb97d0) CORE 43490265 2212 ClientPrerollHelper::GetPreroll() header [00BABF68]: Preroll 1864 PostDecodeDelay 500 Total 2364 CORE 43490265 2212 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::UpdatePreroll(ulPreroll=2364) CORE 43490271 2212 ClientPrerollHelper::GetPreroll() header [00BAD680]: Preroll 1857 PostDecodeDelay 1000 Total 2857 CORE 43490271 2212 HXBufferingState[audio/x-pn-realaudio-00BB486D]::UpdatePreroll(ulPreroll=2857) CORE 43490341 3724 ClientPrerollHelper::GetPreroll() header [00BABF68]: Preroll 1864 PostDecodeDelay 500 Total 2364 CORE 43490341 3724 ClientPrerollHelper::GetPreroll() header [00BAD680]: Preroll 1857 PostDecodeDelay 1000 Total 2857 CORE 43490341 3724 HXSource[00BA3088]::SetMinimumPreroll(): Preroll 2857 MinPreroll 0 MaxLatencyThreshold 3857 CORE 43490341 3724 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 43490341 3724 HXBufferingState[audio/x-pn-realaudio-00BB486D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 43490341 3724 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 43490341 3724 HXBufferingState[audio/x-pn-realaudio-00BB486D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 43490346 3724 CBufferManager[00BA3378] Wallclock delay for stream 0 set to 0 CORE 43490346 3724 CBufferManager[00BA3378] Wallclock delay for stream 1 set to 0 CORE 43490346 3724 CBufferManager[00BA3378] Wallclock delay for stream 1 set to 0 TRAN 43490380 2212 (00BA3088) AudioPushDown Satisfied 278 100 TRAN 43490547 3724 (00BA3088) VideoPushDown Satisfied 1 1 TRAN 43490547 3724 (00BA3088) TURBO Started CORE 43490548 3724 HXPlayer[00B5ACD8]::CheckForAudioResume(): resuming audio player CORE 43490548 3724 HXBufferingState[video/x-pn-realvideo-00BAEE9D]::OnResumed 0 54776 CORE 43490548 3724 HXBufferingState[audio/x-pn-realaudio-00BB486D]::OnResumed 1 60200 Previous core: -------------- CORE 861730519 0596 HXPlayer[00B5ACD8]::OpenURL(): file://br-av-ss-hi.rm CORE 861730586 0596 ClientPrerollHelper::GetPreroll() header [00BAC018]: Preroll 1864 PostDecodeDelay 0 Total 1864 CORE 861730586 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::OnStreamHeader() StreamNum=0 PreRoll=1864 PreData=0 PDStart=0 PDSeek=0 PRStart=0 PRSeek=0 AvgBitRate=603532 MaxBitRate=603532 mimeType=video/x-pn-realvideo CORE 861730587 0596 ClientPrerollHelper::GetPreroll() header [00BAD730]: Preroll 3714 PostDecodeDelay 0 Total 3714 CORE 861730587 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::OnStreamHeader() StreamNum=1 PreRoll=3714 PreData=0 PDStart=0 PDSeek=0 PRStart=0 PRSeek=0 AvgBitRate=96468 MaxBitRate=96468 mimeType=audio/x-pn-realaudio CORE 861730588 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::Init(ulPerfectPlayTime=0) CORE 861730588 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::Init(ulPerfectPlayTime=0) CORE 861730589 0596 HXPlayer[00B5ACD8]::Begin() CORE 861730589 0596 HXPlayer[00B5ACD8]::BeginPlayer() CORE 861730594 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::OnStream(pStream=0x00bab910) CORE 861730606 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::OnStream(pStream=0x00bba8d8) CORE 861730614 0596 ClientPrerollHelper::GetPreroll() header [00BAC018]: Preroll 1864 PostDecodeDelay 500 Total 2364 CORE 861730614 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::UpdatePreroll(ulPreroll=2364) CORE 861730622 0596 ClientPrerollHelper::GetPreroll() header [00BAD730]: Preroll 1857 PostDecodeDelay 1000 Total 2857 CORE 861730622 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::UpdatePreroll(ulPreroll=2857) CORE 861730730 0596 ClientPrerollHelper::GetPreroll() header [00BAC018]: Preroll 1864 PostDecodeDelay 500 Total 2364 CORE 861730730 0596 ClientPrerollHelper::GetPreroll() header [00BAD730]: Preroll 1857 PostDecodeDelay 1000 Total 2857 CORE 861730730 0596 HXSource[00BA3198]::SetMinimumPreroll(): Preroll 2857 MinPreroll 0 MaxLatencyThreshold 3857 CORE 861730730 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 861730730 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 861730730 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 861730730 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::SetMinimumPreroll(ulSourcePreroll=0,ulPerfectPlayTime=0,bIsRebuffering=0) CORE 861730754 0596 CBufferManager[00BA3488] Wallclock delay for stream 0 set to 0 CORE 861730755 0596 CBufferManager[00BA3488] Wallclock delay for stream 1 set to 0 CORE 861730768 0596 CBufferManager[00BA3488] Wallclock delay for stream 1 set to 14 TRAN 861730834 0596 (00BA3198) AudioPushDown Satisfied 278 100 TRAN 861731057 0596 (00BA3198) VideoPushDown Satisfied 1 1 TRAN 861731057 0596 (00BA3198) TURBO Started CORE 861731150 0596 HXPlayer[00B5ACD8]::CheckForAudioResume(): resuming audio player CORE 861731150 0596 HXBufferingState[video/x-pn-realvideo-00BAEF4D]::OnResumed 0 265635 CORE 861731150 0596 HXBufferingState[audio/x-pn-realaudio-00BB4D3D]::OnResumed 1 37800 Files Modified: /client/core/hxbufstate.cpp,v /client/core/hxflsrc.cpp,v /client/core/hxflsrc.h,v /client/core/hxplay.cpp,v /client/core/pub/hxplay.h,v /common/include/ihxtlogsystem.h,v /datatype/common/vidrend/vidrend.cpp,v Image Size and Heap Use impact (Client -Only): next to none Platforms and Profiles Affected: all Distribution Libraries Affected: none Distribution library impact and planned action: n/a Platforms and Profiles Build Verified: win32-i386-vc7, helix-client-all-defines Platforms and Profiles Functionality verified: win32-i386-vc7, helix-client-all-defines Branch: HEAD