Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tizen: DASH live streams are freezing after 15 - 20 minutes of playback #1195

Open
TomaszKowalik opened this issue Jan 5, 2023 · 12 comments

Comments

@TomaszKowalik
Copy link

TomaszKowalik commented Jan 5, 2023

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:

{
autoPlay: true
enableFastSwitching: false,
keySystems: [{type: "widevine", ... }],
onCodecSwitch: "reload",
textTrackElement: div.rxp-texttrack-cont,
textTrackMode: "html",
transport: "dash",
url: "https://{redacted}/Manifest.mpd",
}

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:

Stream: Urgent switch, terminate now. video
SF: Segment request cancelled video P: 1662237984 A: 3 R: tracks-v1 S: 10605446.711-6
Stream: changing representation video tracks-v2 2281000
SI: current video inventory timeline:
10605358.71|A|10605434.71
[A] P: 1662237984 || R: tracks-v1(3709000)
SF: Beginning request video P: 1662237984 A: 3 R: tracks-v2 S: init
SF: Beginning request video P: 1662237984 A: 3 R: tracks-v2 S: 10605446.711-6
DRM: Init data already processed. Skipping it.
Stream: new video bitrate estimate 4975062.103026741
SI: current audio inventory timeline:
10604768.19|A|10605446.71
[A] P: 1662237984 || R: tracks-a1(96000)
SF: Segment request aborted video P: 1662237984 A: 3 R: tracks-v1 S: 10605446.711-6
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605446.711-6
AVSB: pushing segment audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605446.711-6
SF: Segment request ended with success audio P: 1662237984 A: 1 R: tracks-a1 S: 10605446.711-6
AVSB: receiving order for validating end of segment audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605446.711-6
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 10604768.718 10604774.563

and it leads to:

Init: ignored stall for too long, checking discontinuity 813124.6699999999
Init: Pause playback to build buffer
API: playerStateChange event BUFFERING
Init: Refreshing the Manifest in "unsafeMode" for the 6 consecutive time.
API: current media element state tick event ratechange position 10605458.595 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==80.56==|10605459.27
                 ^10605458.595 
ratechange
ABR: Choosing representation with bandwidth estimation. 2281000 tracks-v2
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: current audio inventory timeline:
10604791.87|A|10605464.72
[A] P: 1662237984 || R: tracks-a1(96000)
API: current media element state tick event canplay position 10605458.595 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==80.56==|10605459.27
                 ^10605458.595 
canplay
ABR: Choosing representation with bandwidth estimation. 2281000 tracks-v2
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: current audio inventory timeline:
10604791.87|A|10605464.72
[A] P: 1662237984 || R: tracks-a1(96000)
SI: Pushing segment strictly after previous one. audio 10605464.718645833 10605464.718
AVSB: Acknowledging complete segment audio P: 1662237984 A: 1 R: tracks-a1 S: 10605464.711-6
SI: found true buffered end audio 10605470.713 10605470.7133125
SI: current audio inventory timeline:
10604791.87|A|10605470.71
[A] P: 1662237984 || R: tracks-a1(96000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 515.3600000001024ms
MUS: Manifest took too long to parse. Postponing next request 2002.445000000298 2002.445000000298
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
API: current media element state tick event timeupdate position 10605458.808 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==81.12==|10605459.83
                 ^10605458.808 
timeupdate
ABR: Choosing representation with bandwidth estimation. 2281000 tracks-v2
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: current audio inventory timeline:
10604791.87|A|10605470.71
[A] P: 1662237984 || R: tracks-a1(96000)
AVSB: receiving order to push data to the SourceBuffer video video P: 1662237984 A: 3 R: tracks-v2 S: 10605464.711-6
SF: Segment request ended with success video P: 1662237984 A: 3 R: tracks-v2 S: 10605464.711-6
AVSB: receiving order for validating end of segment video video P: 1662237984 A: 3 R: tracks-v2 S: 10605464.711-6
SF: Beginning request audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
SF: Beginning request video P: 1662237984 A: 3 R: tracks-v2 S: 10605470.711-6
API: current media element state tick event timeupdate position 10605458.808 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==81.44==|10605460.15
                 ^10605458.808 
timeupdate
ABR: Choosing representation with bandwidth estimation. 797000 tracks-v4
Stream: urgent Representation switch video
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
Stream: Urgent switch, terminate now. video
SF: Segment request cancelled video P: 1662237984 A: 3 R: tracks-v2 S: 10605470.711-6
Stream: changing representation video tracks-v4 797000
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SF: Beginning request video P: 1662237984 A: 3 R: tracks-v4 S: init
SF: Beginning request video P: 1662237984 A: 3 R: tracks-v4 S: 10605470.711-6
DRM: Init data already processed. Skipping it.
Stream: new video bitrate estimate 1342405.187504026
SI: current audio inventory timeline:
10604791.87|A|10605470.71
[A] P: 1662237984 || R: tracks-a1(96000)
SF: Segment request aborted video P: 1662237984 A: 3 R: tracks-v2 S: 10605470.711-6
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
AVSB: pushing segment audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
SF: Segment request ended with success audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
AVSB: receiving order for validating end of segment audio audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
API: current media element state tick event timeupdate position 10605458.808 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==81.76==|10605460.47
                 ^10605458.808 
timeupdate
ABR: Choosing representation with bandwidth estimation. 797000 tracks-v4
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: 1 segments GCed. audio
SI: Segment partially GCed at the start audio 10604792.718 10604797.731
SI: current audio inventory timeline:
10604797.73|A|10605470.71
[A] P: 1662237984 || R: tracks-a1(96000)
Init: Refreshing the Manifest in "unsafeMode" for the 7 consecutive time.
AVSB: receiving order to push data to the SourceBuffer video 
SF: Segment request ended with success video P: 1662237984 A: 3 R: tracks-v4 S: init
AVSB: receiving order for validating end of segment video video P: 1662237984 A: 3 R: tracks-v4 S: init
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: Pushing segment strictly after previous one. audio 10605470.7133125 10605470.713
AVSB: Acknowledging complete segment audio P: 1662237984 A: 1 R: tracks-a1 S: 10605470.711-6
SI: found true buffered end audio 10605476.729 10605476.7293125
SI: current audio inventory timeline:
10604797.73|A|10605476.73
[A] P: 1662237984 || R: tracks-a1(96000)
API: current media element state tick event timeupdate position 10605458.808 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==82.00==|10605460.71
                 ^10605458.808 
timeupdate
API: Sending warning: t: MediaError (MEDIA_TIME_BEFORE_MANIFEST) The current position is behind the earliest time announced in the Manifest.
Choosing representation with bandwidth estimation. 797000 tracks-v4
SI: current video inventory timeline:
10605378.71|A|10605446.71 ~ 10605446.71|B|10605452.71 ~ 10605452.71|A|10605458.71
[A] P: 1662237984 || R: tracks-v1(3709000)
[B] P: 1662237984 || R: tracks-v2(2281000)
SI: current audio inventory timeline:
10604797.73|A|10605476.73
[A] P: 1662237984 || R: tracks-a1(96000)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 714.434999999823ms
MUS: Manifest took too long to parse. Postponing next request -13421.129999999888 -13421.129999999888
AVSB: receiving order to push data to the SourceBuffer video video P: 1662237984 A: 3 R: tracks-v4 S: 10605470.711-6
SF: Segment request ended with success video P: 1662237984 A: 3 R: tracks-v4 S: 10605470.711-6
AVSB: receiving order for validating end of segment video video P: 1662237984 A: 3 R: tracks-v4 S: 10605470.711-6
Beginning request audio P: 1662237984 A: 1 R: tracks-a1 S: 10605476.711-6
Beginning request video P: 1662237984 A: 3 R: tracks-v4 S: 10605476.711-6
DRM: Encrypted event received from media element.
DRM: Init data already processed. Skipping it.
API: current media element state tick event timeupdate position 10605458.808 seeking false internalSeek null rebuffering true freezing false ended false paused false playbackRate 0 readyState 3
API: current playback timeline:
10605378.71|==82.24==|10605460.95
                 ^10605458.808 
timeupdate
API: Sending warning: t: MediaError (MEDIA_TIME_BEFORE_MANIFEST) The current position is behind the earliest time announced in the Manifest.

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:

Screenshot 2023-01-05 104436

What might be the possible cause of such behavior? Please let me know if there is any other information I could provide.

@peaBerberian
Copy link
Collaborator

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).

@TomaszKowalik
Copy link
Author

TomaszKowalik commented Jan 9, 2023

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

@peaBerberian
Copy link
Collaborator

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

@TomaszKowalik
Copy link
Author

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.

@peaBerberian
Copy link
Collaborator

:/
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))?

@TomaszKowalik
Copy link
Author

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?

@peaBerberian
Copy link
Collaborator

peaBerberian commented Jan 17, 2023

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.

@TomaszKowalik
Copy link
Author

TomaszKowalik commented Jan 19, 2023

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...

@peaBerberian
Copy link
Collaborator

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?

@TomaszKowalik
Copy link
Author

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

@peaBerberian
Copy link
Collaborator

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.

@TomaszKowalik
Copy link
Author

@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 ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants