Stream/App freeze in DASH Multi-Period Live-Stream #1698
Description
Version
Media3 1.4.1
More version details
Issue reproduced in 1.4.1 and 1.4.0 - 1.3.1 is working fine.
After doing some git bisect we were able to pin down the issue to commit d292f809. If we revert this particular commit on version 1.4.1 we cannot reproduce the issue anymore.
We observe the following Logcat messages when the issue occurs. In this particular case the "freeze" started at around 13:20:47 and application resumed at around 12:20:53.
13:20:45.705 AvrcpMediaPlayerList D sendMediaUpdate
13:20:45.705 AvrcpMediaPlayerList I sendMediaUpdate: Creating a one item queue for a player with no queue
13:20:45.705 AvrcpMediaPlayerList D sendMediaUpdate state=PlaybackState {state=3, position=1725535199867, buffered position=0, speed=1.0, updated=15856860, actions=895, custom actions=[], active item id=-1, error=null}
13:20:45.705 AvrcpTargetService D onMediaUpdated: track_changed=false state=true queue=false
13:20:45.705 AvrcpNativeInterface D sendMediaUpdate: metadata=false playStatus=true queue=false
13:20:45.705 AvrcpTargetJni D sendMediaUpdateNative
13:20:45.705 bt_stack I [INFO:avrcp_service.cc(346)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 : play_state=1 : queue=0
13:20:45.767 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90773,90773], OUT[90753,90751,90751] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:46.292 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90786,90786], OUT[90766,90764,90764] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:46.613 ThermalService I CPU temperatures: [73.3]
13:20:46.811 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90796,90796], OUT[90773,90771,90771] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:47.559 WifiVendorHal E getWifiLinkLayerStats_1_3_Internal(l.978) failed {.code = ERROR_UNKNOWN, .description = unknown error}
13:20:47.763 g.xxxxx.previe I Background young concurrent copying GC freed 442206(17MB) AllocSpace objects, 6(1128KB) LOS objects, 20% free, 58MB/73MB, paused 191us total 284.960ms
13:20:47.889 Choreographer I Skipped 47 frames! The application may be doing too much work on its main thread.
13:20:47.902 OpenGLRenderer I Davey! duration=960ms; Flags=0, IntendedVsync=15858100892199, Vsync=15859040892199, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=15859048906269, AnimationStart=15859048909061, PerformTraversalsStart=15859048910769, DrawStart=15859052521144, SyncQueued=15859054356852, SyncStart=15859054752061, IssueDrawCommandsStart=15859054982144, SwapBuffers=15859060168394, FrameCompleted=15859061705727, DequeueBufferDuration=474208, QueueBufferDuration=522000, GpuCompleted=15798429353532,
13:20:47.995 AudioFlinger I BUFFER TIMEOUT: remove(69) from active list on thread 0xf4669030
13:20:47.998 system_server I oneway function results will be dropped but finished with status OK and parcel size 4
13:20:47.999 APM::AudioPolicyEngine W getDevicesForStrategy() unknown strategy: -1
13:20:47.999 APM::AudioPolicyEngine W getDevicesForStrategy() unknown strategy: -1
13:20:48.076 BasicMediaStatusFactory D Supported media session actions: 895
13:20:48.077 WargReceiverApp E LogEventSink not set.
13:20:48.085 AvrcpMediaPlayerWrapper V onPlaybackStateChanged(): our.package.name : PlaybackState {state=3, position=1725535200735, buffered position=0, speed=1.0, updated=15859240, actions=895, custom actions=[], active item id=-1, error=null}
13:20:48.093 AvrcpMediaPlayerWrapper V trySendMediaUpdate(): Metadata has been updated for our.package.name
13:20:48.093 AvrcpMediaPlayerList D sendMediaUpdate
13:20:48.093 AvrcpMediaPlayerList I sendMediaUpdate: Creating a one item queue for a player with no queue
13:20:48.093 AvrcpMediaPlayerList D sendMediaUpdate state=PlaybackState {state=3, position=1725535200746, buffered position=0, speed=1.0, updated=15859251, actions=895, custom actions=[], active item id=-1, error=null}
13:20:48.093 AvrcpTargetService D onMediaUpdated: track_changed=false state=true queue=false
13:20:48.093 AvrcpNativeInterface D sendMediaUpdate: metadata=false playStatus=true queue=false
13:20:48.093 AvrcpTargetJni D sendMediaUpdateNative
13:20:48.093 bt_stack I [INFO:avrcp_service.cc(346)] virtual void bluetooth::avrcp::AvrcpService::SendMediaUpdate(bool, bool, bool) track_changed=0 : play_state=1 : queue=0
13:20:48.094 BasicMediaStatusFactory D Supported media session actions: 895
13:20:48.288 audio_hw_primary I alsa format =0x1 delay frames =1664 total frames=760576000
13:20:48.629 thermal2 I Sending notification: Type: CPU Name: soc_thermal CurrentValue: 75.4 ThrottlingStatus: MODERATE
13:20:48.630 ThermalService I CPU temperatures: [75.4]
13:20:48.817 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90798,90798], OUT[90773,90771,90771] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:49.264 g.xxxxx.previe I Background concurrent copying GC freed 701039(27MB) AllocSpace objects, 7(284KB) LOS objects, 30% free, 54MB/78MB, paused 190us total 686.217ms
13:20:49.478 e D topActivityPackage: our.package.name, appCollectType: 1 ， launcherPackage: our.package.name, video: true
13:20:49.516 e D showNotification: It is not in the launcher interface, so it will not be displayed for the time being!
13:20:49.582 AudioTrack D getTimestamp_l(45): device stall time corrected using current time 15860741260770
13:20:49.594 AudioTrack W restartIfDisabled(45): releaseBuffer() track 0xac5a0a10 disabled due to previous underrun, restarting
13:20:49.595 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90798,90798], OUT[90776,90772,90772] DEC[0->0] => DEVICE[3+0/3->0+4/14] => CLIENT[10]\n"
13:20:49.595 APM::AudioPolicyEngine W getDevicesForStrategy() unknown strategy: -1
13:20:49.595 APM::AudioPolicyEngine W getDevicesForStrategy() unknown strategy: -1
13:20:49.596 BufferPoolAccessor2.0 D bufferpool2 0xaf57d888 : 8(65536 size) total buffers - 1(8192 size) used buffers - 2319/2327 (recycle/alloc) - 23/2320 (fetch/transfer)
13:20:49.602 BufferPoolAccessor2.0 D bufferpool2 0xf3cc33e8 : 6(24576 size) total buffers - 1(4096 size) used buffers - 2311/2317 (recycle/alloc) - 8/2316 (fetch/transfer)
13:20:49.613 system_server I oneway function results will be dropped but finished with status OK and parcel size 4
13:20:50.096 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90819,90819], OUT[90799,90797,90797] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:50.578 WifiVendorHal E getWifiLinkLayerStats_1_3_Internal(l.978) failed {.code = ERROR_UNKNOWN, .description = unknown error}
13:20:50.617 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90831,90831], OUT[90812,90810,90810] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:50.645 ThermalService I CPU temperatures: [75.200005]
13:20:51.133 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90842,90842], OUT[90825,90823,90823] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:51.356 NotificationUtil I (NotificationUtil.java:1)#d
13:20:51.691 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90856,90856], OUT[90839,90836,90836] DEC[0->0] => DEVICE[3+0/3->0+3/14] => CLIENT[11]\n"
13:20:52.218 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90870,90870], OUT[90852,90849,90849] DEC[0->0] => DEVICE[3+0/3->0+3/14] => CLIENT[11]\n"
13:20:52.310 b1 I isNetWorkConnected, net: true
13:20:52.310 MQM W testConnect already connected!
13:20:52.661 ThermalService I CPU temperatures: [75.8]
13:20:52.724 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90885,90885], OUT[90865,90861,90861] DEC[0->0] => DEVICE[3+0/3->0+4/14] => CLIENT[10]\n"
13:20:52.936 g.xxxxx.previe I Background young concurrent copying GC freed 520245(22MB) AllocSpace objects, 13(2524KB) LOS objects, 30% free, 54MB/78MB, paused 274us total 401.408ms
13:20:53.057 Choreographer I Skipped 248 frames! The application may be doing too much work on its main thread.
13:20:53.076 OpenGLRenderer I Davey! duration=4994ms; Flags=0, IntendedVsync=15859240890616, Vsync=15864200890616, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=15864216970855, AnimationStart=15864216973188, PerformTraversalsStart=15864226487355, DrawStart=15864227799980, SyncQueued=15864229443771, SyncStart=15864229947355, IssueDrawCommandsStart=15864230172438, SwapBuffers=15864234054021, FrameCompleted=15864235700021, DequeueBufferDuration=763417, QueueBufferDuration=469792, GpuCompleted=15799171707324,
13:20:53.087 BasicMediaStatusFactory D Supported media session actions: 895
13:20:53.090 WargReceiverApp E LogEventSink not set.
13:20:53.228 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90897,90897], OUT[90877,90875,90875] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:53.587 WifiVendorHal E getWifiLinkLayerStats_1_3_Internal(l.978) failed {.code = ERROR_UNKNOWN, .description = unknown error}
13:20:53.622 audio_hw_primary I alsa format =0x1 delay frames =1664 total frames=760832000
13:20:53.730 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90910,90910], OUT[90890,90887,90887] DEC[0->0] => DEVICE[3+0/3->0+3/14] => CLIENT[11]\n"
13:20:54.247 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90923,90923], OUT[90903,90901,90901] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:54.677 ThermalService I CPU temperatures: [75.3]
13:20:54.757 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90936,90936], OUT[90915,90913,90913] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:55.027 BufferPoolAccessor2.0 D bufferpool2 0xaf57d888 : 8(65536 size) total buffers - 1(8192 size) used buffers - 2586/2594 (recycle/alloc) - 31/2587 (fetch/transfer)
13:20:55.039 BufferPoolAccessor2.0 D bufferpool2 0xf3cc33e8 : 6(24576 size) total buffers - 1(4096 size) used buffers - 2578/2584 (recycle/alloc) - 9/2583 (fetch/transfer)
13:20:55.295 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90948,90948], OUT[90929,90927,90927] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:55.813 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90962,90962], OUT[90942,90940,90940] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:56.324 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90976,90976], OUT[90954,90952,90952] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:56.594 WifiVendorHal E getWifiLinkLayerStats_1_3_Internal(l.978) failed {.code = ERROR_UNKNOWN, .description = unknown error}
13:20:56.693 ThermalService I CPU temperatures: [75.4]
13:20:56.844 VDA I [0]"ServiceDeviceTask: buffer counts: IN[90988,90988], OUT[90967,90965,90965] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
13:20:57.373 VDA I [0]"ServiceDeviceTask: buffer counts: IN[91001,91001], OUT[90981,90979,90979] DEC[0->0] => DEVICE[3+0/3->0+2/14] => CLIENT[12]\n"
I've sent a video of the issue, the adb bugreport as well as the logs via Mail.
Devices that reproduce the issue
Any device. We tested it specifically on AFTMM Fire TV (Android 7) stick and our own Android TV Stick (Android 11)
Devices that do not reproduce the issue
No response
Reproducible in the demo app?
Not tested
Reproduction steps
Play a DASH Multi-Period Live Stream
Expected result
Stream plays smoothly without interruption
Actual result
Application freezes (including Audio & Video) for a brief moment
Media
Not applicable
Bug Report
- You will email the zip file produced by
adb bugreportto android-media-github@google.com after filing this issue.