Chasing LiveTV in a Web Browser client, buffer size?

Channels DVR Server
#41

Now on Firefox v76.0 which was just released.

Figured out why it wasn't working for me.

I was entering Hls.DefaultConfig.debug = true in the multi-line editor mode which required pressing CTRL-ENTER to execute. I switched to single-line editor mode and it worked.

I'm able to get the console output and figured out how to turn on timestamps, select all output and save to a file.

Did a quick test to see how much console output there would be and after watching for about 9:13 it started buffering so I submitted diagnotic logs f346c0ad-c649-44c2-b8c8-84f68a04b948 and emailed the captured console output file console-export-2020-5-6_14-14-17.txt

1 Like
#42

What buffer is low?
I was watching a minute behind live and it stopped, showed buffering at 4:27 even though it had buffered to 5:27.

10:16:20.990 event 
Object { Type: "activities.set", Name: "7-ch735-dANY-ip192.168.1.2", Value: "Watching ch735 from 192.168.1.2 (Remux Running at 2mbps: 5m26s @ 1.00x (59.94fps)): strength=97% quality=100% symbol=100% rate=1.9Mb/sec" }
bundle.js:32:4684972
10:16:21.028 [debug] > call to loadLevel bundle.js:62:30745
10:16:21.029 [log] > Attempt loading level index 0 with URL-id 0 bundle.js:62:30745
10:16:21.029 [debug] > Loading playlist of type level, level: 0, id: 0 bundle.js:62:30745
10:16:21.029 [debug] > Calling internal loader delegate for URL: http://192.168.1.4:8089/devices/ANY/channels/735/hls/stream.m3u8?abitrate=128&abr=false&acodec=aac&bitrate=2779&deinterlacer=hardware&indexed=true&resolution=720&ssize=1&vcodec=copy bundle.js:62:30745
10:16:21.628 [log] > same live playlist, reload twice faster bundle.js:62:30745
10:16:21.629 [log] > live playlist, reload in 496 ms bundle.js:62:30745
10:16:21.629 [log] > level 0 loaded [1,328],duration:325.3167140000005 bundle.js:62:30745
10:16:21.629 [log] > live playlist sliding:0.000 bundle.js:62:30745
10:16:21.879 [warn] > Playback stalling at @267.754677 due to low buffer bundle.js:62:30745

I skipped back 10 secs and it played to 4:27 again and stopped, showing buffering.

10:17:23.469 [log] > media seeking to 257.755 bundle.js:62:30745
10:17:23.495 [log] > same live playlist, reload twice faster bundle.js:62:30745
10:17:23.495 [log] > live playlist, reload in 514 ms bundle.js:62:30745
10:17:23.496 [log] > level 0 loaded [1,377],duration:387.3246890000003 bundle.js:62:30745
10:17:23.496 [log] > live playlist sliding:0.000 bundle.js:62:30745
10:17:23.865 [log] > media seeked to 257.755 bundle.js:62:30745
...
10:17:34.481 [log] > level 0 loaded [1,385],duration:399.3326890000003 bundle.js:62:30745
10:17:34.482 [log] > live playlist sliding:0.000 bundle.js:62:30745
10:17:35.151 [warn] > Playback stalling at @267.754677 due to low buffer bundle.js:62:30745

I also noticed that this sequence of main stream:IDLE->FRAG_LOADING->PARSING->PARSED->IDLE stopped here at 267 seconds, where the buffering appears in playback.

10:15:19.992 [log] > Loading 266 of [1 ,268],level 0, currentTime:207.073,bufferEnd:264.960 bundle.js:62:30745
10:15:19.994 [log] > main stream:IDLE->FRAG_LOADING bundle.js:62:30745
10:15:20.634 [log] > Loaded 266 of [1 ,268],level 0 bundle.js:62:30745
10:15:20.635 [log] > Parsing 266 of [1 ,268],level 0, cc 0 bundle.js:62:30745
10:15:20.635 [log] > main stream:FRAG_LOADING->PARSING bundle.js:62:30745
10:15:20.650 [warn] > Injecting 1 audio frame @ 266.283s due to 31 ms gap. 2bdb07f5-7dfa-4329-ada8-4ea723318c06:1:6202
10:15:20.651 [log] > Parsed audio,PTS:[264.960,267.755],DTS:[264.960/267.755],nb:131,dropped:0 bundle.js:62:30745
10:15:20.653 [log] > Parsed video,PTS:[265.052,267.847],DTS:[264.952/267.763],nb:150,dropped:0 bundle.js:62:30745
10:15:20.655 [log] > main stream:PARSING->PARSED bundle.js:62:30745
10:15:20.663 [log] > main buffered : [12.650,106.744][106.777,267.755] bundle.js:62:30745
10:15:20.664 [log] > main stream:PARSED->IDLE bundle.js:62:30745
10:15:20.677 event 
Object { Type: "activities.set", Name: "7-ch735-dANY-ip192.168.1.2", Value: "Watching ch735 from 192.168.1.2 (Remux Running at 2mbps: 4m28s @ 1.01x (59.82fps)): strength=97% quality=100% symbol=100% rate=3.9Mb/sec" }
bundle.js:32:4684972

I can email you this console output if you want.

#43

Very interesting. I noticed our version of hls.js is out of date, so I've updated from 0.12.4 to 0.13.2. There are some changes mentioned which may help this situation.

Generally low buffer means the client is not receiving new segments in the playlist to play. But the transcoder logs (and activity updates in the js console) show that the remux is still ticking along since the time increases. So maybe its a client bug and the new library version will fix it. The update is part of v2020.05.07.2058

1 Like
#44

Thanks, will try it out tonight or tomorrow and let you know either way.
Is your pull request
logger.warn(Playback stalling at @${media.currentTime} due to low buffer (buffer=${bufferLen}));
included in v2020.05.07.2058?

#45

Would like to know if playing back a recording of the same live tv session that fails has anything to do with this hls.js streaming player fix.

Appears playback of the recording isn't the same as playing the live session, since playing live buffers and playing the recording of the same program has no issues. Does playback of the recording also use the same hls.js?

I'm guessing that watching a program live vs. watching the recording of the same program uses different remux/transcode/player/?

Hopefully tomorrow or this weekend I can verify this new version playing live tv remuxing in my web browser.

#46

No it's not included.

Yes the same player is used, but the Transcoder works differently when the entire file is available recorded

#47

Thanks, thought so, as this has been an issue with live playback for quite some time in the web player client where it couldn't keep sync with the live hls transcoded/remuxed streaming. Never has been an issue playing a recording back in my web client players.

Not sure if this affects other clients besides the web UI player since I either don't have or use them, but seems to be an issue with other platform clients was why I asked. I do have paid for iOS clients, but rarely use them.

#48

NO GO

Tried again tonight using Channels Plus DVR v2020.05.07.2058 and Firefox v76.0

Set a recording from 7-8pm for the same channel I would be watching live.
Started watching the channel live from the grid guide at 6:50pm, letting it buffer 1 min before starting to watch live.
Buffering like crazy, gave up watching live for tonight.
Submitted diagnostic logs 802d48ad-efbf-42e3-ab1a-51709abddd2d
Emailed console logs console-export-2020-5-8_19-4-18.txt

#49

Did you get the email with the consolde log showing buffering every 1-5 secs?

18:59:46.847 [warn] > Playback stalling at @518.143999 due to low buffer bundle.js:115:649
18:59:49.346 [warn] > playback not stuck anymore @518.144001, after 2800ms bundle.js:115:649
19:00:01.822 [warn] > Playback stalling at @522.325332 due to low buffer bundle.js:115:649
19:00:03.130 [warn] > playback not stuck anymore @522.325334, after 1650ms bundle.js:115:649
19:00:09.818 [warn] > Playback stalling at @524.821332 due to low buffer bundle.js:115:649
19:00:10.619 [warn] > playback not stuck anymore @524.821334, after 1101ms bundle.js:115:649
19:00:18.480 [warn] > Playback stalling at @526.293332 due to low buffer bundle.js:115:649
19:00:19.982 [warn] > playback not stuck anymore @526.293335, after 1782ms bundle.js:115:649
19:00:24.318 [warn] > Playback stalling at @527.829332 due to low buffer bundle.js:115:649
19:00:25.416 [warn] > playback not stuck anymore @527.829335, after 1392ms bundle.js:115:649
19:00:35.664 [warn] > Playback stalling at @532.159999 due to low buffer bundle.js:115:649
19:00:38.294 [warn] > playback not stuck anymore @532.160001, after 2941ms bundle.js:115:649
19:00:45.133 [warn] > Playback stalling at @536.149332 due to low buffer bundle.js:115:649
19:00:46.034 [warn] > playback not stuck anymore @536.149335, after 1210ms bundle.js:115:649
19:01:02.349 [warn] > Playback stalling at @540.159999 due to low buffer bundle.js:115:649
19:01:05.979 [warn] > Trying to nudge playhead over buffer-hole bundle.js:115:649
19:01:05.979 [warn] > Nudging 'currentTime' from 540.159999 to 540.259999 bundle.js:115:649
19:01:06.161 [warn] > playback not stuck anymore @540.313186, after 135ms bundle.js:115:649
19:01:12.277 [warn] > Playback stalling at @541.951999 due to low buffer bundle.js:115:649
19:01:14.652 [warn] > playback not stuck anymore @541.952019, after 2675ms bundle.js:115:649
19:01:26.857 [warn] > Playback stalling at @546.261332 due to low buffer bundle.js:115:649
19:01:28.359 [warn] > playback not stuck anymore @546.261352, after 1802ms bundle.js:115:649
19:01:35.000 [warn] > Playback stalling at @548.671999 due to low buffer bundle.js:115:649
19:01:36.004 [warn] > playback not stuck anymore @548.672019, after 1304ms bundle.js:115:649
19:02:07.773 [warn] > Playback stalling at @556.671999 due to low buffer bundle.js:115:649
19:02:08.893 [warn] > playback not stuck anymore @556.672019, after 1420ms bundle.js:115:649
19:02:17.749 [warn] > Playback stalling at @561.685332 due to low buffer bundle.js:115:649
19:02:22.444 [warn] > playback not stuck anymore @561.685352, after 4995ms bundle.js:115:649
19:02:23.205 [warn] > Playback stalling at @561.877332 due to low buffer bundle.js:115:649
19:02:26.231 [warn] > playback not stuck anymore @561.877353, after 3372ms bundle.js:115:649
19:02:40.232 [warn] > Playback stalling at @566.549332 due to low buffer bundle.js:115:649
19:02:41.449 [warn] > playback not stuck anymore @566.549352, after 1570ms bundle.js:115:649
#50

Interesting. We have not had a chance to investigate the logs in detail yet. You could try the "Old Transcoder" setting in the experimental area. If it works with that then it may suggest a bug in the new live transcoder.

#51

Still happens using Old Transcoder.
Submitted diagnostics 27bb3c43-3898-412b-981f-03d7846ab556
emailed consolde debug console-export-2020-5-10_11-30-31.txt