search

nova-video-player / aos-AVP

NOVA opeN sOurce Video plAyer: main repository to build them all
Apache License 2.0
3.54k stars 202 forks source link

[Bug]: Audio Drops out when seeking on DDP content #624

Open KyleSanderson opened 2 years ago

KyleSanderson commented 2 years ago

Problem description

Audio drops out completely when seeking a couple minutes on a DDP video.

Steps to reproduce the issue

Seek.

Expected behavior

Seeking works.

Your phone/tablet/androidTV model

Firestick Max

Operating system version

AMZN

Application version and app store

6.0.62

Additional system information

No response

Debug logs

No response

KyleSanderson commented 2 years ago 
04-21 21:53:50.103  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:50.108   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:50.108   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:50.109   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:50.110   307   331 I libPowerHal: 2: cpu_ctrl set freq: 1794000 -1
04-21 21:53:50.110   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:50.111   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:50.112   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:50.112   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:50.212   545   561 I UsageStatsService: User[0] Flushing usage stats to disk
04-21 21:53:50.223  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:50.224   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:50.224   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:50.225   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:50.225   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:50.226   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:50.227 31948 32072 D avos_player: ###  <NSR 2384090>0x8226b200|avos_mp_pause:
04-21 21:53:50.229  3466  3466 V NewAvrcpMediaPlayerWrapper: onPlaybackStateChanged(): com.amazon.vizzini : PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=12413543, actions=4, custom actions=[], active item id=-1, error=null}
04-21 21:53:50.238   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:50.238   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:50.239  3466  3466 V NewAvrcpMediaPlayerWrapper: trySendMediaUpdate(): Metadata has been updated for com.amazon.vizzini
04-21 21:53:50.239  3466  3466 D NewAvrcpMediaPlayerList: sendMediaUpdate
04-21 21:53:50.239  3466  3466 I NewAvrcpMediaPlayerList: sendMediaUpdate: Creating a one item queue for a player with no queue
04-21 21:53:50.239  3466  3466 D NewAvrcpTargetService: onMediaUpdated: track_changed=false state=true queue=false
04-21 21:53:50.239  3466  3466 D NewAvrcpNativeInterface: sendMediaUpdate: metadata=false playStatus=true queue=false
04-21 21:53:50.239  3466  3466 D NewAvrcpTargetJni: sendMediaUpdateNative
04-21 21:53:50.240  3466  3466 I bt_stack: [INFO:avrcp_service.cc(342)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 :  play_state=1 :  queue=0
04-21 21:53:50.279   545  3942 I AmazonPowerManagerVendorCallback: Wakelock released UID:1000 PID:545 Tag:WindowManager
04-21 21:53:50.280   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:50.430   307   331 I libPowerHal: 2: cpu_ctrl set freq: -1 -1
04-21 21:53:51.444  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:51.445   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:51.446   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:51.447   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:51.448   307   331 I libPowerHal: 2: cpu_ctrl set freq: 1794000 -1
04-21 21:53:51.448   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:51.448   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:51.449   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:51.449   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:51.523  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:51.524   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:51.525   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:51.527   545  3749 I MediaFocusControl: requestAudioFocus() from uid/pid 10187/31948 clientId=com.amazon.media.AmazonAudioManager@5422c91com.archos.mediacenter.video.player.Player$3@e6d37f9 callingPack=org.courville.nova req=1 flags=0x0 sdk=31
04-21 21:53:51.527 31948 32072 D avos_player: 0x8226b200|avos_mp_start:
04-21 21:53:51.529  1014  1044 I DolbyAudioStreamOut: pause()
04-21 21:53:51.530  3466  3466 V NewAvrcpMediaPlayerWrapper: onPlaybackStateChanged(): com.amazon.vizzini : PlaybackState {state=3, position=-1, buffered position=0, speed=1.0, updated=12414844, actions=3, custom actions=[], active item id=-1, error=null}
04-21 21:53:51.532   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:51.532   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:51.533  1015  1026 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0xa65fe000
04-21 21:53:51.533  1015  1064 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0xa6a83300
04-21 21:53:51.536  3466  3466 V NewAvrcpMediaPlayerWrapper: trySendMediaUpdate(): Metadata has been updated for com.amazon.vizzini
04-21 21:53:51.536  3466  3466 D NewAvrcpMediaPlayerList: sendMediaUpdate
04-21 21:53:51.536  3466  3466 I NewAvrcpMediaPlayerList: sendMediaUpdate: Creating a one item queue for a player with no queue
04-21 21:53:51.536  3466  3466 D NewAvrcpTargetService: onMediaUpdated: track_changed=false state=true queue=false
04-21 21:53:51.536  3466  3466 D NewAvrcpNativeInterface: sendMediaUpdate: metadata=false playStatus=true queue=false
04-21 21:53:51.536  3466  3466 D NewAvrcpTargetJni: sendMediaUpdateNative
04-21 21:53:51.536  3466  3466 I bt_stack: [INFO:avrcp_service.cc(342)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 :  play_state=1 :  queue=0
04-21 21:53:51.537  3466  3961 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
04-21 21:53:51.539  3466  3961 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 10 lines
04-21 21:53:51.539  3466  3961 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
04-21 21:53:51.549  1014  8990 I Connector: setVolume(): connector (null), in-volume 0.000000, volume -96 dB, fade 20 ms, type 2
04-21 21:53:51.524   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:51.562   545  3749 I AmazonPowerManagerVendorCallback: Wakelock acquired UID:1000 PID:545 Tag:WindowManager
04-21 21:53:51.599   307   331 I libPowerHal: 2: cpu_ctrl set freq: -1 -1
04-21 21:53:51.669 31948  8935 I MediaCodecLogger: the latest buffer is 1405 old with packageName org.courville.nova. Possible resume detected
04-21 21:53:51.811 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:51.820 31948  8935 I chatty  : uid=10187(org.courville.nova) NDK MediaCodec_ identical 1 line
04-21 21:53:51.825 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:51.828 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision.bitrateInKbps = 20012
04-21 21:53:51.831 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:55.265  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:55.266   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:55.266   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:55.268   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:55.271   307   331 I libPowerHal: 2: cpu_ctrl set freq: 1794000 -1
04-21 21:53:55.272   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:55.272   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:55.273   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:55.273   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:55.403  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
04-21 21:53:55.404   545   627 E SELinux : avc:  denied  { see_home_task } for  scontext=u:r:platform_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
04-21 21:53:55.406   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:55.407   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:55.407   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:55.408 31948 32072 D avos_player:   <NSR 2468341>0x8226b200|avos_mp_pause:
04-21 21:53:55.410  3466  3466 V NewAvrcpMediaPlayerWrapper: onPlaybackStateChanged(): com.amazon.vizzini : PlaybackState {state=1, position=-1, buffered position=0, speed=1.0, updated=12418725, actions=4, custom actions=[], active item id=-1, error=null}
04-21 21:53:55.413   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:55.413   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:55.419  3466  3466 V NewAvrcpMediaPlayerWrapper: trySendMediaUpdate(): Metadata has been updated for com.amazon.vizzini
04-21 21:53:55.419  3466  3466 D NewAvrcpMediaPlayerList: sendMediaUpdate
04-21 21:53:55.419  3466  3466 I NewAvrcpMediaPlayerList: sendMediaUpdate: Creating a one item queue for a player with no queue
04-21 21:53:55.419  3466  3466 D NewAvrcpTargetService: onMediaUpdated: track_changed=false state=true queue=false
04-21 21:53:55.419  3466  3466 D NewAvrcpNativeInterface: sendMediaUpdate: metadata=false playStatus=true queue=false
04-21 21:53:55.419  3466  3466 D NewAvrcpTargetJni: sendMediaUpdateNative
04-21 21:53:55.419  3466  3466 I bt_stack: [INFO:avrcp_service.cc(342)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 :  play_state=1 :  queue=0
04-21 21:53:55.405   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:55.449   545  3942 I AmazonPowerManagerVendorCallback: Wakelock released UID:1000 PID:545 Tag:WindowManager
04-21 21:53:55.450   307   332 I vendor.mediatek.hardware.power@2.0-impl: powerHintAsync hint:2, data:0
04-21 21:53:55.600   307   331 I libPowerHal: 2: cpu_ctrl set freq: -1 -1
04-21 21:53:55.895   264   343 W Netd    : No subsystem found in netlink event
04-21 21:53:56.546  1014  8990 I Node    : dolby-audio-meter, AdapterPcmOut adapter audio meter: channel 0; audio level: 0.266
04-21 21:53:56.546  1014  8990 I Node    : dolby-audio-meter, AdapterPcmOut adapter audio meter: channel 1; audio level: 0.313
04-21 21:53:56.876  4060  9071 I Vizzini_2.0.14628.0:HealthLogger: Current State = {"Account":"valid","AlexaCaptionsEnabled":"false","ProfileValidated":"true","AlexaCaptionsSupported":"true","memoryTotalPss":"44831","DeviceFamily":"SMP","memoryTotalSharedDirty":"2876","InstaHintsSyncTime":"2022-04-21 18:33:16","ReleaseVersion":"637.0.0","AlexaLegalTermsAccepted":"true","AppVersion":"2.0.14628.0","AlexaExperience":"FULL","SupportsFarField":"false","memoryAvailable":"480579584","Gateway":"avs-alexa-18-na.amazon.com:443","memoryLow":"false","ConnectionState":"CONNECTED","OOBECompleted":"true","memoryTotalPrivateDirty":"31097"}
04-21 21:53:56.876  4060  9071 I DeviceEvent: CSMSIM#device_event_contract#0#1.0
04-21 21:53:57.079  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 0; audio level: 0.035
04-21 21:53:57.079  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 1; audio level: 0.031
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 2; audio level: 0.015
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 3; audio level: 0.000
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 4; audio level: 0.012
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmMain adapter audio meter: channel 5; audio level: 0.014
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmSystem adapter audio meter: channel 0; audio level: 0.000
04-21 21:53:57.080  1014  8990 I Node    : dolby-audio-meter, AdapterPcmSystem adapter audio meter: channel 1; audio level: 0.000
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 0; audio level: 0.024
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 1; audio level: 0.020
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 2; audio level: 0.004
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 3; audio level: 0.000
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 4; audio level: 0.012
04-21 21:53:57.080  1014  8990 I RendererNode: dolby-audio-meter, Renderer renderer audio meter: channel 5; audio level: 0.014
KyleSanderson commented 2 years ago

Specifically these lines look suspicious that the audio device is never resumed. The additional invalid frame information also is likely related to the other issue I opened. https://github.com/nova-video-player/aos-AVP/issues/623

04-21 21:53:51.527 31948 32072 D avos_player: 0x8226b200|avos_mp_start:
04-21 21:53:51.529  1014  1044 I DolbyAudioStreamOut: pause()
04-21 21:53:51.530  3466  3466 V NewAvrcpMediaPlayerWrapper: onPlaybackStateChanged(): com.amazon.vizzini : PlaybackState {state=3, position=-1, buffered position=0, speed=1.0, updated=12414844, actions=3, custom actions=[], active item id=-1, error=null}
04-21 21:53:51.532   545   626 D AmzPhoneWindowManager: interceptUnhandledKey: 23
04-21 21:53:51.532   545   626 D AmzPhoneWindowManager: is 23 in key list = false
04-21 21:53:51.533  1015  1026 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0xa65fe000
04-21 21:53:51.533  1015  1064 W AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0xa6a83300
04-21 21:53:51.536  3466  3466 V NewAvrcpMediaPlayerWrapper: trySendMediaUpdate(): Metadata has been updated for com.amazon.vizzini
04-21 21:53:51.536  3466  3466 D NewAvrcpMediaPlayerList: sendMediaUpdate
04-21 21:53:51.536  3466  3466 I NewAvrcpMediaPlayerList: sendMediaUpdate: Creating a one item queue for a player with no queue
04-21 21:53:51.536  3466  3466 D NewAvrcpTargetService: onMediaUpdated: track_changed=false state=true queue=false
04-21 21:53:51.536  3466  3466 D NewAvrcpNativeInterface: sendMediaUpdate: metadata=false playStatus=true queue=false
04-21 21:53:51.536  3466  3466 D NewAvrcpTargetJni: sendMediaUpdateNative
04-21 21:53:51.536  3466  3466 I bt_stack: [INFO:avrcp_service.cc(342)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 :  play_state=1 :  queue=0
04-21 21:53:51.537  3466  3961 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
04-21 21:53:51.539  3466  3961 I chatty  : uid=1002(bluetooth) BluetoothAvrcpH identical 10 lines
04-21 21:53:51.539  3466  3961 E bt_btif : register_notification_rsp: Avrcp device is not connected, handle: 0x0
04-21 21:53:51.549  1014  8990 I Connector: setVolume(): connector (null), in-volume 0.000000, volume -96 dB, fade 20 ms, type 2
04-21 21:53:51.524   545   627 I AmazonProfileService: Event is not filtered because it is not in filter key list.
04-21 21:53:51.562   545  3749 I AmazonPowerManagerVendorCallback: Wakelock acquired UID:1000 PID:545 Tag:WindowManager
04-21 21:53:51.599   307   331 I libPowerHal: 2: cpu_ctrl set freq: -1 -1
04-21 21:53:51.669 31948  8935 I MediaCodecLogger: the latest buffer is 1405 old with packageName org.courville.nova. Possible resume detected
04-21 21:53:51.811 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:51.820 31948  8935 I chatty  : uid=10187(org.courville.nova) NDK MediaCodec_ identical 1 line
04-21 21:53:51.825 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:51.828 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision.bitrateInKbps = 20012
04-21 21:53:51.831 31948  8935 I MediaCodecLogger: 31948.4K.HW.video.dolby-vision Dropping frame
04-21 21:53:55.265  3466  3918 W bt_btif : bta_hh_le_input_rpt_notify uuid=0x2a4d srv_handle=37 is_bl_svc_primary=1 rpt_id=1 len=3
KyleSanderson commented 2 years ago

The issue is with the AudioTrack backend it seems like - OpenSL ES does not suffer from the same defect.

Is there any more information I can provide?

courville commented 2 years ago

Thanks for reporting and sharing the logs. I can reproduce the frame drops on the firestick max:

9833.HW.video.hevc Dropping frame

@nnoury any idea? No error on avos side:

D/avos_player( 9833): audio_interface_init: audiotrack_java success
D/avos_player( 9833): device_config.mp_decoder  0
D/avos_player( 9833): device_config.mp_audio_interface  1
D/avos_player( 9833): device_config.output_sample_rate  48000
D/avos_player( 9833): 0x8c684900|avos_mp_create:
V/avos_media_player( 9833): event_thread: start
D/avos_player( 9833): 0x8c684900|avos_mp_setdatasource: http://localhost:44579/blah..2160p.WEB-DL.DDP5.1.Atmos.HDR.H.265-NOSiViD[eztv.re].mkv
D/avos_media_player( 9833): setVideoSurface
V/avos_media_player( 9833): free_native_window
D/avos_player( 9833): 0x8c684900|avos_mp_open_async:
D/avos_player( 9833):
D/avos_player( 9833): stream_open http://localhost:44579/blah..2160p.WEB-DL.DDP5.1.Atmos.HDR.H.265-NOSiViD[eztv.re].mkv  etype 48->ETYPE_MKV  flags 2001
D/avos_player( 9833): flags:  PAUSED  LATE_INDEX  FILE_NONLOCAL
D/avos_player( 9833): HELLO, Found 0 side data!
D/avos_player( 9833): PARSER: [FFMPEG]  buffersize -1
D/avos_player( 9833): VIDEO:  [HEVC] [HEVC/H.265] 3840x2160   0fps  0kbit/s  dec [(none)]
D/avos_player( 9833): AUDIO:  [4747] [EAC3] 48000Hz  6-ch 0bit  768kbit/s  dec [(none)]
D/avos_player( 9833): SUB:    [0004] [TEXT] s_english gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_english gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_chinese gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_chinese gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_danish gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_german gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_spanish gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_spanish gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_french gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_french gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_italian gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_japanese gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_korean gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_dutch gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_norwegian gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_portuguese gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_portuguese gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_finnish gfx 0  ext 0  1/1000
D/avos_player( 9833): SUB:    [0004] [TEXT] s_swedish gfx 0  ext 0  1/1000
D/avos_player( 9833): audio[0] playable!
D/avos_player( 9833): VID_SNK: [sfdec2]
D/avos_player( 9833): videosink_open: opened
D/avos_player( 9833): VID_DEC: [sfdec2]
D/avos_player( 9833): AUD_DEC: [ffmpeg]
D/avos_player( 9833): facomp: open
D/avos_player( 9833): lvl 0  tgt 0  maxg 0  sm 8  hist 65536
D/avos_player( 9833): facomp: level 0
D/avos_player( 9833):
D/avos_player( 9833): stream_start http://localhost:44579/blah.2160p.WEB-DL.DDP5.1.Atmos.HDR.H.265-NOSiViD[eztv.re].mkv
D/avos_player( 9833): AUD_SNK: [audio]
D/avos_player( 9833): stream_sink_audio_open
D/avos_player( 9833): start video at start
D/avos_player( 9833): 0x8c684900|avos_mp_setsubtitletrack: 9
D/avos_player( 9833): stream_set_subtitle_stream( 9 )
D/avos_player( 9833): 0x8c684900|avos_mp_setsubtitledelay: 0
D/avos_player( 9833): 0x8c684900|avos_mp_setsubtitleratio: 24000/24000
D/avos_player( 9833): 0x8c684900|avos_mp_setaudiofilter: 0 0
D/avos_player( 9833): facomp: level 0
D/avos_player( 9833): 0x8c684900|avos_mp_setavdelay: 0
D/avos_player( 9833): stream_play_n_frames( 10, 230000, -1 )
D/avos_player( 9833): init_renderer: width NOT changed: 3840 -> 4096
D/avos_player( 9833): init_renderer: height NOT changed: 2160 -> 2176
D/avos_player( 9833): sfdec_read: INFO_FORMAT_CHANGED: 3840x2160
D/avos_player( 9833):   <NSR 230000>0x8c684900|avos_mp_start:
D/avos_player( 9833): 0x8c684900|avos_mp_setlooping: 0
D/avos_player( 9833): 0x8c684900|avos_mp_setaudiofilter: 0 0
D/avos_player( 9833): facomp: level 0
D/avos_player( 9833):   <NSR 230042>realloc 0 -> 62

MediaCodec logs:

I/MediaCodecLogger( 9833): 9833.HW.video.hevc.bitrateInKbps = 16593
I/MediaCodecLogger( 9833): 9833.HW.video.hevc Dropping frame
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.bitrateInKbps = 14947
I/MediaCodecLogger( 9833): 9833.HW.video.hevc Dropping frame
I/MediaCodecLogger( 9833): 9833.HW.video.hevc Dropping frame
I/MediaCodecLogger( 9833): Flushing: 9833.HW.video.hevc.framerate = 24.000 fps
E/NdkMediaCodec( 9833): sf error code: -13
I/MediaCodecLogger( 9833): MC Stop Time(start: 2639834, stop:2639862 :28 <profileMCStopEnd 1212>
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.TotalVideoPlaybackTimeMs = 68333
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.videoResolution.UHD = 68333
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.StreamAvgFramerate = 24.000
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.StreamFramerate = 23.802
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.OneConsecutiveFramesDropped = 10
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.TwoConsecutiveFramesDropped = 2
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.TotalFramesDropped = 14
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.MaxConsecutiveFramesDropped = 3
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.ASAP-P5Ms = 231
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.ASAP-P2Ms = 6
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.ASAP-P3Ms = 11
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.FirstFrameReadyMs = 229
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.StreamAvgBitrateInKbps = 16654
I/MediaCodec( 9833): [OMX.MTK.VIDEO.DECODER.HEVC] setting surface generation to 10068995
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc P2 + 2692028
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc P2 - 2692032
D/MediaCodecLogger( 9833): Got amazon_media_codec_logger Service. Calling PID = 9833
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc P3 + 2692034
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc P3 - 2692046
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc Got First Input Frame 2692954 pts:0
I/MediaCodecLogger( 9833): updateFormatChanged width = 3840 height = 2160
I/MediaCodecLogger( 9833): updatePTSTime [HW.video.hevc] First PTS after Flush or reset = 294000000
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc Got First Frame Ready 2693303(349)
I/MediaCodecLogger( 9833): [ASAP] HW.video.hevc Got First Frame Render 2693306(352)
I/MediaCodecLogger( 9833): App sets Timestamps for render in SurfaceFlinger
I/MediaCodecLogger( 9833): 9833.HW.video.hevc.bitrateInKbps = 18235
I/MediaCodecLogger( 9833): 9833.HW.video.hevc Resolution change from 0x0 to 3840x2160 took = 38
I/MediaCodecLogger( 9833): 9833.HW.video.hevc Dropping frame