Open TomaszKowalik opened 1 year ago
Hi @TomaszKowalik,
It weirdly looks like there's it does not succeed to buffer segments, because new video segments are loaded and pushed, but are then not found in the buffer. By looking in your logs at what is present in the buffer, I see that it seems to not be properly garbage collecting old segments (~80 seconds of ~3Mbps video behind the current position seems high to me) :/
Can you test by calling player.setMaxBufferBehind(7)
and player.setMaxBufferAhead(40)
? We'll set some bounds on what can be kept in the buffer and see if it improves the situation.
Theoretically if this is the problem, player.setMaxVideoBufferSize
is the more adapted API, but it's more complicated to use as we we have know how much data in kB we want to keep in the video buffer.
MEDIA_TIME_BEFORE_MANIFEST
is a warning sent when the position falls behind the first position described by the MPD, but here it seems to be sent as a side-effect of the original issue, because we were rebuffering for too long (this is only a theory though).
Hi @peaBerberian , thank you for your answer I was testing it with these buffer boundaries, but unfortunately streams are still crashing in the same manner. :( We were also wondering if maybe this might be related to the manifest parsing time (manifest files from this provider are around 13 KB size) ? According to the Samsung Docs, WebAssembly is not suppoerted on devices lower than Tizen 2020, so we have to rely on JS parser on the affected devices... https://developer.samsung.com/smarttv/develop/extension-libraries/webassembly/webassembly.html
Ah, perhaps! It's true that MPD parsing seems to take a lot of time here... (I can see 500ms and 700ms in here) Though 13 kb doesn't look like too much (we tested multi-megabytes ones which was the reason behind the webassembly implementation).
Perhaps the issue is somewhat linked to garbage collection pressure, iself due to frequent heavy manifest updates ?
Can you try playing with a minimumManifestUpdateInterval
set to a larger value, like 10000 (10 seconds). It will force manifest updates to happen less often which may improve the situation here. You may also want to start further from the live edge for your tests to prevent rebuffering (as the update throttling will impact the delay after which the RxPlayer is aware of new segments), through the startAt
option.
Doc for minimumManifestUpdateInterval
: https://developers.canal-plus.com/rx-player/doc/api/Loading_a_Content.html#transportoptions
Doc for the startAt
: https://developers.canal-plus.com/rx-player/doc/api/Loading_a_Content.html#startat
For example, you can try:
player.loadVideo({
// ...
transportOptions: {
minimumManifestUpdateInterval: 10000,
},
startAt: {
fromLastPosition: -20,
},
});
Thanks
So I've tried with and without startAt
parameter (I had to use lower value, because with -20 I was getting time before manifest errors right away). Manifest requests were less frequent, but unfortuantely issue is still present, and it still occurs after around 15 min of playback. I've tracked parsing times and their values seem to be in normal ranges, like 18ms, then suddenly they are peaking and the error occurs:
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349892.71|A|349974.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349292.20|A|349974.71
[A] P: 1673512544 || R: tracks-a1(98000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 43.88000000012107ms
API: current media element state tick event timeupdate position 349968.711 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349892.71|==82.00==|349974.71
^349968.711
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349892.71|A|349974.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
SI: current audio inventory timeline:
349292.20|A|349974.71
[A] P: 1673512544 || R: tracks-a1(98000)
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 349296.718 349298.105
SI: current audio inventory timeline:
349298.10|A|349974.71
[A] P: 1673512544 || R: tracks-a1(98000)
SI: Pushing segment strictly after previous one. audio 349974.7133125 349974.713
AVSB: Acknowledging complete segment audio P: 1673512544 A: 1 R: tracks-a1 S: 349974.711-6
SI: found true buffered end audio 349980.729 349980.7293125
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
AVSB: receiving order to push data to the SourceBuffer video video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
AVSB: updating codec video/mp4;codecs="avc1.4d001f"
AVSB: could not update codec video/mp4;codecs="avc1.4d001f" video/mp4;codecs="avc1.4d0015"
AVSB: pushing segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
SF: Segment request ended with success video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
AVSB: receiving order for validating end of segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
SI: 1 segments GCed. video
SI: Segment partially GCed at the start video 349896.711 349898.711
SI: current video inventory timeline:
349898.71|A|349974.71
[A] P: 1673512544 || R: tracks-v1(4006000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
SI: Pushing segment strictly after previous one. video 349974.711 349974.711
AVSB: Acknowledging complete segment video P: 1673512544 A: 3 R: tracks-v1 S: 349974.711-6
SI: found true buffered end video 349980.711 349980.711
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
Stream: new video bitrate estimate 36185450.90170627
API: current media element state tick event timeupdate position 349969.72 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349969.72
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349970.623 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349970.623
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349971.634 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349971.634
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349972.645 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349972.645
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349973.651 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349973.651
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349974.656 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349974.656
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349975.666 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349898.71|==82.00==|349980.71
^349975.666
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349976.678 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349898.71|==82.00==|349980.71
^349976.678
timeupdate
ABR: enter starvation mode.
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349977.695 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349898.71|==82.00==|349980.71
^349977.695
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349978.907 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349898.71|==82.00==|349980.71
^349978.907
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 302.46999999997206ms
API: current media element state tick event timeupdate position 349979.973 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349898.71|==82.00==|349980.71
^349979.973
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
API: current media element state tick event timeupdate position 349980.668 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
349898.71|==82.00==|349980.71
^349980.668
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Pause playback to build buffer
API: playerStateChange event BUFFERING
API: current media element state tick event ratechange position 349980.668 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 2
API: current playback timeline:
349898.71|==82.00==|349980.71
^349980.668
ratechange
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349898.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349298.10|A|349980.73
[A] P: 1673512544 || R: tracks-a1(98000)
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
SI: Pushing segment strictly after previous one. audio 349980.7293125 349980.729
AVSB: Acknowledging complete segment audio P: 1673512544 A: 1 R: tracks-a1 S: 349980.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 349302.713 349304.163
SI: found true buffered end audio 349986.723 349986.72397916665
SI: current audio inventory timeline:
349304.16|A|349986.72
[A] P: 1673512544 || R: tracks-a1(98000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
AVSB: receiving order to push data to the SourceBuffer video video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
AVSB: updating codec video/mp4;codecs="avc1.4d001f"
AVSB: could not update codec video/mp4;codecs="avc1.4d001f" video/mp4;codecs="avc1.4d0015"
AVSB: pushing segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
SF: Segment request ended with success video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
AVSB: receiving order for validating end of segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
API: current media element state tick event canplay position 349980.668 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349904.71|==76.88==|349981.59
^349980.668
canplay
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
Stream: new video bitrate estimate 28948792.915776983
SI: 1 segments GCed. video
SI: Segment partially GCed at the start video 349902.711 349904.711
SI: current video inventory timeline:
349904.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349304.16|A|349986.72
[A] P: 1673512544 || R: tracks-a1(98000)
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 349308.729 349310.158
SI: current audio inventory timeline:
349310.16|A|349986.72
[A] P: 1673512544 || R: tracks-a1(98000)
SI: Pushing segment strictly after previous one. audio 349986.72397916665 349986.723
AVSB: Acknowledging complete segment audio P: 1673512544 A: 1 R: tracks-a1 S: 349986.711-6
SI: found true buffered end audio 349992.718 349992.7186458333
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
AVSB: receiving order to push data to the SourceBuffer video video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
SF: Segment request ended with success video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
AVSB: receiving order for validating end of segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
SI: current video inventory timeline:
349904.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
API: current media element state tick event timeupdate position 349980.811 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349904.71|==79.00==|349983.71
^349980.811
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
Stream: new video bitrate estimate 27292275.004677135
SI: current video inventory timeline:
349904.71|A|349980.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
SI: Pushing segment strictly after previous one. video 349980.711 349980.711
AVSB: Acknowledging complete segment video P: 1673512544 A: 3 R: tracks-v1 S: 349980.711-6
SI: found true buffered end video 349986.711 349986.711
SI: current video inventory timeline:
349904.71|A|349986.71
[A] P: 1673512544 || R: tracks-v1(4006000)
AVSB: updating codec video/mp4;codecs="avc1.4d001f"
AVSB: could not update codec video/mp4;codecs="avc1.4d001f" video/mp4;codecs="avc1.4d0015"
AVSB: pushing segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
SI: Pushing segment strictly after previous one. video 349986.711 349986.711
AVSB: Acknowledging complete segment video P: 1673512544 A: 3 R: tracks-v1 S: 349986.711-6
SI: 1 segments GCed. video
SI: Segment partially GCed at the start video 349908.711 349910.711
SI: found true buffered end video 349992.711 349992.711
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
API: current media element state tick event timeupdate position 349980.811 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 0 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349980.811
timeupdate
ABR: exit starvation mode.
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Resume playback speed 1
API: playerStateChange event PLAYING
API: current media element state tick event ratechange position 349980.811 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349980.811
ratechange
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349981.669 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349981.669
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349982.619 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349982.619
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349983.642 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349983.642
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349984.613 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349984.613
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Refreshing the Manifest in "unsafeMode" for the 1 consecutive time.
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 240.17499999993015ms
API: current media element state tick event timeupdate position 349985.634 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349910.71|==82.00==|349992.71
^349985.634
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349910.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 349992.711-6
SI: current audio inventory timeline:
349310.16|A|349992.72
[A] P: 1673512544 || R: tracks-a1(98000)
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
AVSB: receiving order to push data to the SourceBuffer video video P: 1673512544 A: 3 R: tracks-v1 S: 349992.711-6
AVSB: updating codec video/mp4;codecs="avc1.4d001f"
AVSB: could not update codec video/mp4;codecs="avc1.4d001f" video/mp4;codecs="avc1.4d0015"
AVSB: pushing segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349992.711-6
SF: Segment request ended with success video P: 1673512544 A: 3 R: tracks-v1 S: 349992.711-6
AVSB: receiving order for validating end of segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349992.711-6
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 349998.711-6
SI: Pushing segment strictly after previous one. audio 349992.7186458333 349992.718
AVSB: Acknowledging complete segment audio P: 1673512544 A: 1 R: tracks-a1 S: 349992.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 349314.723 349316.302
SI: found true buffered end audio 349998.713 349998.7133125
SI: current audio inventory timeline:
349316.30|A|349998.71
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349986.656 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
349914.71|==78.00==|349992.71
^349986.656
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
Stream: new video bitrate estimate 28131138.058795404
SI: 1 segments GCed. video
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349316.30|A|349998.71
[A] P: 1673512544 || R: tracks-a1(98000)
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 349320.718 349322.339
SI: current audio inventory timeline:
349322.34|A|349998.71
[A] P: 1673512544 || R: tracks-a1(98000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
API: current media element state tick event timeupdate position 349987.711 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349914.71|==78.28==|349992.99
^349987.711
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|349998.71
[A] P: 1673512544 || R: tracks-a1(98000)
SI: Pushing segment strictly after previous one. audio 349998.7133125 349998.713
AVSB: Acknowledging complete segment audio P: 1673512544 A: 1 R: tracks-a1 S: 349998.711-6
SI: found true buffered end audio 350004.729 350004.7293125
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 349990.633 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349914.71|==78.80==|349993.51
^349990.633
timeupdate
ABR: enter starvation mode.
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
API: current media element state tick event timeupdate position 349992.628 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
349914.71|==79.44==|349994.15
^349992.628
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
AVSB: receiving order to push data to the SourceBuffer video video P: 1673512544 A: 3 R: tracks-v1 S: 349998.711-6
SF: Segment request ended with success video P: 1673512544 A: 3 R: tracks-v1 S: 349998.711-6
AVSB: receiving order for validating end of segment video video P: 1673512544 A: 3 R: tracks-v1 S: 349998.711-6
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
API: current media element state tick event timeupdate position 349994.3 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
349914.71|==79.84==|349994.55
^349994.3
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
Stream: new video bitrate estimate 6061955.65216667
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Pause playback to build buffer
API: playerStateChange event BUFFERING
API: current media element state tick event ratechange position 349994.3 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==80.00==|349994.71
^349994.3
ratechange
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event canplay position 349994.3 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==80.00==|349994.71
^349994.3
canplay
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Refreshing the Manifest in "unsafeMode" for the 2 consecutive time.
API: current media element state tick event timeupdate position 349994.3 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==80.16==|349994.87
^349994.3
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 847.0600000000559ms
MUS: Manifest took too long to parse. Postponing next request 1801.6100000001024 1801.6100000001024
API: current media element state tick event timeupdate position 349994.635 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==80.64==|349995.35
^349994.635
timeupdate
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SF: Beginning request video P: 1673512544 A: 3 R: tracks-v1 S: 350004.711-6
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
SF: Beginning request audio P: 1673512544 A: 1 R: tracks-a1 S: 350004.711-6
API: current media element state tick event timeupdate position 349994.635 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==81.12==|349995.83
^349994.635
timeupdate
API: Sending warning: t: MediaError (MEDIA_TIME_BEFORE_MANIFEST) The current position is behind the earliest time announced in the Manifest.
ABR: Choosing representation with bandwidth estimation. 4006000 tracks-v1
SI: current video inventory timeline:
349914.71|A|349992.71
[A] P: 1673512544 || R: tracks-v1(4006000)
SI: current audio inventory timeline:
349322.34|A|350004.73
[A] P: 1673512544 || R: tracks-a1(98000)
Init: Refreshing the Manifest in "unsafeMode" for the 3 consecutive time.
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1673512544 A: 1 R: tracks-a1 S: 350004.711-6
AVSB: pushing segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 350004.711-6
SF: Segment request ended with success audio P: 1673512544 A: 1 R: tracks-a1 S: 350004.711-6
AVSB: receiving order for validating end of segment audio audio P: 1673512544 A: 1 R: tracks-a1 S: 350004.711-6
API: current media element state tick event timeupdate position 349994.635 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
349914.71|==81.40==|349996.11
^349994.635
timeupdate
API: Sending warning: t: MediaError (MEDIA_TIME_BEFORE_MANIFEST) The current position is behind the earliest time announced in the Manifest.
:/
It still looks like there's a lot in the buffer at this point. To check quickly if this seems memory-related, could you check if the error arises after the same delay when you're playing the lowest video quality (player.setMaxVideoBitrate(0)
)?
Indeed, with this setting, stream was playing nicely and after around 30 minutes it started to throw a lot of MEDIA_TIME_BEFORE_MANIFEST
errors in the logs. Stream freezed for a few seconds, but then it kept playing (in earlier tests it was crashing with a black screen). Stream was playing forward but in the logs it was still throwing MEDIA_TIME_BEFORE_MANIFEST
errors from that moment.
Parsing times were between 10 - 25 ms.
This is what I found in the logs before the error:
MF: Manifest parsed in 12.959999999962747ms
API: current media element state tick event timeupdate position 452260.678 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
451584.38|==678.34==|452262.71
^452260.678
timeupdate
ABR: Choosing representation with buffer-based estimation. 200000 tracks-v6
SI: current video inventory timeline:
450576.71|A|452268.71
[A] P: 1673512544 || R: tracks-v6(200000)
SI: current audio inventory timeline:
451584.38|A|452262.71
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 452261.681 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 3
API: current playback timeline:
451584.38|==678.34==|452262.71
^452261.681
timeupdate
ABR: Choosing representation with buffer-based estimation. 200000 tracks-v6
SI: current video inventory timeline:
450576.71|A|452268.71
[A] P: 1673512544 || R: tracks-v6(200000)
SI: current audio inventory timeline:
451584.38|A|452262.71
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 452262.583 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
451584.38|==678.34==|452262.71
^452262.583
timeupdate
ABR: Choosing representation with buffer-based estimation. 200000 tracks-v6
SI: current video inventory timeline:
450576.71|A|452268.71
[A] P: 1673512544 || R: tracks-v6(200000)
SI: current audio inventory timeline:
451584.38|A|452262.71
[A] P: 1673512544 || R: tracks-a1(98000)
Init: ignored stall for too long, checking discontinuity 1742023.5200000003
Init: Pause playback to build buffer
API: playerStateChange event BUFFERING
API: current media element state tick event ratechange position 452262.583 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 2
API: current playback timeline:
451584.38|==678.34==|452262.71
^452262.583
ratechange
ABR: Choosing representation with buffer-based estimation. 200000 tracks-v6
SI: current video inventory timeline:
450576.71|A|452268.71
[A] P: 1673512544 || R: tracks-v6(200000)
SI: current audio inventory timeline:
451584.38|A|452262.71
[A] P: 1673512544 || R: tracks-a1(98000)
API: current media element state tick event timeupdate position 452262.583 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 2
API: current playback timeline:
451584.38|==678.34==|452262.71
^452262.583
timeupdate
ABR: Choosing representation with buffer-based estimation. 200000 tracks-v6
SI: current video inventory timeline:
450576.71|A|452268.71
[A] P: 1673512544 || R: tracks-v6(200000)
SI: current audio inventory timeline:
451584.38|A|452262.71
[A] P: 1673512544 || R: tracks-a1(98000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 11.804999999934807ms
API: current media element state tick event timeupdate position 452262.583 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 2
API: current playback timeline:
451584.38|==678.34==|452262.71
^452262.583
timeupdate
API: Sending warning: t: MediaError (MEDIA_TIME_BEFORE_MANIFEST) The current position is behind the earliest time announced in the Manifest.
This log looks quite unusual:
Init: ignored stall for too long, checking discontinuity 1742023.5200000003
Init: Pause playback to build buffer
API: playerStateChange event BUFFERING
Looks like it led to ratechange event
What could we do to enchance this buffer handling, also for higher quality?
This log looks quite unusual:
Init: ignored stall for too long, checking discontinuity 1742023.5200000003
Ah yes, this is Tizen! Tizen devices are particularly hard to handle because they sometimes have their own behaviors in conflict with the RxPlayer.
So the RxPlayer just let the device do its thing, but if it finds out that after some delay, Tizen still didn't handle properly some problematic situations (such as not skipping over some discontinuities), the RxPlayer does it itself. That's what we're seeing here.
Strange situation but it may happen. The "ratechange" event should just be linked to the fact that we're then rebuffering, in which case we temporarily set the video element's playback rate to 0
.
If updating the played bitrate changes the delay at which the issue is encountered, it has high chances of being linked to memory usage. Can you now re call at least the player.setMaxBufferBehind(10)
API before playback? It will automatically remove buffer behind the current position (10 seconds before it). Here, at 678 seconds, it looks like Tizen is optimist.
After using player.setMaxBufferBehind(10)
combined with player.setMaxVideoBitrate(0)
it was streaming fine. Parsing times were correct, and it was not throwing so many (MEDIA_TIME_BEFORE_MANIFEST) errors, for 40 minutes of playback there was about 40 of such errors in the logs.
Unfortunately when I'm removing player.setMaxVideoBitrate(0)
and only leaving player.setMaxBufferBehind(10)
it results in crash with parsing time peak, and (MEDIA_TIME_BEFORE_MANIFEST) are showing almost immediately :(
But I've noticed another strange thing today: stream is crashing after ~15 minutes, but if I'll play the stream for about 8 minutes, then stop it with eg back button, and then start the stream again -> it will crash after ~7 minutes then. So looks like that no matter if stream is playing continuously or not, it will crash after this particular period of playback time...
For the MEDIA_TIME_BEFORE_MANIFEST
error, it happens when the current position go behind the minimum position reachable through the Manifest, so I think you just have a Manifest with a very small buffer depth and if enough buffering is experienced, we'll be behind that minimum position.
In that situation you should seek back at a position superior to rxPlayer.getMinimumPosition()
to be able to play back (like 5 seconds after it?).
As for the more important bitrate-related error, it's strange that it triggers after 15 minutes of playback, regardless of if we're ourselves cleaning the buffer regularly and even more strange that it is still happening if we quit and restart the content in between. It looks like a leak, but that something we monitor closely and we didn't detect one for now on the JavaScript side... Is there a Representation where that problem seems to be appearing? The fact that it only appears for the stream of a given provider could indicate a Tizen issue with some video codec/profile for example...
Does Tizen provide some tools to monitor memory usage and CPU usage to see if there's a correlation? We could also try playing the same content with the same options on a PC and see if some kind of leak seems to be present? Or just if memory goes a little up just enough to provoke problems on some devices?
I handled this MEDIA_TIME_BEFORE_MANIFEST
error, by making player seek back to 5 secs after minimum position, and indeed I didnt seen this errors anymore.
Samsung offers some tools for memory usage monitoring, but not for Smart TV "for safety reasons" :/ The only thing I can do is to make calls to Tizen's API for total and available memory and for CPU load, and print it in the logs. After doing so, indeed available memory was dropping down.
After starting the stream:
The total memory size is 1443385344 bytes.
The available memory size is 648912896 bytes.
After 10 minutes:
The total memory size is 1443385344 bytes.
The available memory size is 224264192 bytes.
Before the crash:
The total memory size is 1443385344 bytes.
The available memory size is 147206144 bytes.
And after closing the stream, available memory stays at the same level.
As for CPU load, during streaming its value ranges between 0.08 - 0.5
, but right before the crash it spikes to almost 1
. If I stop the stream on time, then its load also stays at nearly 100%
and app is very laggy
As for Representation I can see few in the manifest:
<Representation id="tracks-v1" width="1280" height="720" sar="1:1" frameRate="25" bandwidth="3905000" codecs="avc1.4d001f">
<Representation id="tracks-v2" width="1024" height="576" sar="1:1" frameRate="25" bandwidth="2337000" codecs="avc1.4d001f">
<Representation id="tracks-v3" width="850" height="480" sar="1:1" frameRate="25" bandwidth="1175000" codecs="avc1.4d001e">
<Representation id="tracks-v4" width="682" height="384" sar="1:1" frameRate="25" bandwidth="776000" codecs="avc1.4d001e">
<Representation id="tracks-v5" width="512" height="288" sar="1:1" frameRate="25" bandwidth="378000" codecs="avc1.4d0015">
<Representation id="tracks-v6" width="426" height="240" sar="1:1" frameRate="25" bandwidth="190000" codecs="avc1.4d0015">
When I played the stream with the locked bitrate to use the parameters from the representation with bandwidth="2337000", then after 30 minutes of streaming available memory was around 240000000 bytes
(with 700837888
at the start), so it was also dropping down but not as dramatically as with the highest quality.
Crash happend after ~45 minutes on that quality:
The total memory size is 1443385344 bytes.
The available memory size is 145567744 bytes.
With the lowest quality it looks like that available memory is also dropping down, but very slowly, so crash probably would also happen after longer period of time.
Additional manifest settings:
minBufferTime="PT13S"
minimumUpdatePeriod="PT4.2S"
maxSegmentDuration="PT7S"
timeShiftBufferDepth="PT24S"
<AdaptationSet id="3" mimeType="video/mp4" contentType="video" maxWidth="1280" maxHeight="720" par="1280:720" maxFrameRate="4167/100" segmentAlignment="true" startWithSAP="1" subsegmentAlignment="true" subsegmentStartsWithSAP="1">
But Today I played 1080p
VOD stream, to see how memory is managed there, and to my suprise it also was dropping down, and caused the crash (didnt paid much attention to VOD before as I focused on livestreams). This stream was from other provider with:
<AdaptationSet id="2" group="2" contentType="video" par="16:9" minBandwidth="577000" maxBandwidth="6785000" segmentAlignment="true" width="1920" height="1080" sar="1:1" frameRate="25" mimeType="video/mp4" codecs="avc1.640028" startWithSAP="1">
<Representation id="video=577000" bandwidth="577000" scanType="progressive">
<Representation id="video=783000" bandwidth="783000" scanType="progressive">
<Representation id="video=1379000" bandwidth="1379000" scanType="progressive">
<Representation id="video=2169000" bandwidth="2169000" scanType="progressive">
<Representation id="video=2760000" bandwidth="2760000" scanType="progressive">
<Representation id="video=4525000" bandwidth="4525000" scanType="progressive">
<Representation id="video=6785000" bandwidth="6785000" scanType="progressive">
This crashes seem rather to be related to stream quality. I checked the livestreams from provider where I didnt noticed the crash before, and their quality were eg 480p
, probably thats why I assumed its provider-related...
On the Samsung 2020 however, when playing same streams, with same paramaters in the manifests I was also seeing memory drops to eg:
The total memory size is 1546376192 bytes.
The available memory size is 26000384 bytes (much lower than values where 2018 crashes).
But streams were playing fine and I saw it was freeing the memory as its value was also raising.
We prepared the app that can be run on a PC, I'll send you link and credentials via email
Hi and thanks!
Ok, so the crash does seem to happen when there's around ~145MB of memory left and memory doesn't seem to be collected once stopped... There's many questions left here but it's a very good start. The fact that it seems to happen only on older Tizen versions scares me a little - as it might not be reproducible elsewhere, I'll check if other players have specific work-arounds linked to memory.
@peaBerberian I did another discovery. I wrote some simple html player, attached RXplayer to it and played one of our linear HD content. Memory was dropping during the stream from 325MB to 15MB, and then stream started to stutter and TV was barely responding on the remote, but it didnt crashed (in our app such stalls are stopping the player). Then I turned off Tizen Studio's debugger, and memory raised up to around 320 MB... and from that point it was being managed correctly. I repeat this test with our app - played stream again on Tizen 2018, and turned off debugger. Stream was not crashing anymore, and memory values were stable (without debugger I had to display its vaules on the screen). Looks like this leak is happening only with debugger turned on, but with use of eg native Tizen AvPlay I didnt observed any memory drops while debugging. What might be causing this behavior ?
I've observed this on LG 2019 (webOS 4) and Hisense U6. Some of my colleagues have also observed this on Hisense U4 and Samsung 2017. It happens with and without a debugger attached.
We found an issue that occurs on some Tizen models when using rxPlayer 3.29.0. I was able to reproduce it on Tizen 2018, 2019 but not on Tizen 2020 and 2021. DASH live streams from one of our providers are affected. After starting the stream it's playing fine for about 15 - 20 minutes, then it freezes, and leads to session being aborted.
We are starting the stream with these parameters:
I've collected some logs during debugging session with
RxPlayer.LogLevel
set to"DEBUG"
Just before the freeze I think its the first unusual message from the player:
and it leads to:
Then these logs seem to be repeating like that with
MEDIA_TIME_BEFORE_MANIFEST
errors, and ultimately it leads to session being aborted.I was also looking in the network tab of the devTools, and the unusual thing that I can see is that when the freeze occured, this
init.m4v
request was made:What might be the possible cause of such behavior? Please let me know if there is any other information I could provide.