Log MSE discontinuities to chrome://media-internals
Reported by
t...@ubnt.com,
Jun 3 2016
|
||||||||
Issue descriptionUserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Example URL: Steps to reproduce the problem: I have no idea, it's intermittent. What is the expected behavior? Video should play back, the displayed frame should be accurate to the currentTime on the video element. What went wrong? https://www.youtube.com/watch?v=thr9p3Z3HbE&feature=youtu.be Video above (watch in 1080p). Summary : - video.paused is false, video should be playing - video.currentTime keeps getting updated - The actual frame displayed is static, it never changes despite the video "playing". - Calling pause() then play() on the video gets it unstuck and it then starts to play as it should. Sometimes it works, sometimes it affects more than one video at a time, sometimes all of them work fine. Sometimes they work fine for 5-10 min then get "stuck" with the same behavior. I did not notice this behavior in versions earlier than 51, so this seems like a regression of some sorts. Did this work before? Yes >= 50 Is it a problem with Flash or HTML5? HTML5 Does this work in other browsers? Yes Chrome version: 51.0.2704.79 Channel: stable OS Version: OS X 10.10.5 Flash Version: Shockwave Flash 21.0 r0
,
Jun 3 2016
I should note that this issue doesn't only affect OSX, been reported on Windows and Linux as well.
,
Jun 8 2016
,
Jun 18 2016
To add a little bit : these videos have audio. Audio continues to play, but video is completely stuck on a frame.
This is for an IP surveillance product, so this is kind of a big deal...
Calling play() does not have any affect since it's already playing, instead we have to pause() first and then play() and even that doesn't work all of the time to unstick it.
Making matters worse, v.pause(); v.play(); sequentially throws an error of "Uncaught (in promise) DOMException: The play() request was interrupted by a call to pause()." Weird API design here... play() returns a promise but pause() doesn't? How am I supposed to know when I can call play() again?
So, basically I currently now have this in my code :
v.pause(); setTimeout(function(){v.play();}, 0); and it doesn't always work.
,
Jun 18 2016
Do you have any errors shown in chrome://media-internals for the stream?
,
Jun 18 2016
All info from media-internals will be really helpful. Can you set up a mimimized repro? Maybe save off a small bytestream that you're appending to MSE and make a little test page that just appends that video and demonstrates the error.
,
Jun 18 2016
See attached. Nothing.
,
Jun 18 2016
It's a bit hard to isolate into a simple example. We have WebRTC data channels that we are sending fragmented MP4 over. We are sending video/audio frames first then the corresponding moof/mdat atoms after and reassembling. We append full segments at a time, but since Chrome 50 our segments are not GOP sized, (to reduce latency, we do 1 segment every 100ms). I can set you up with access via video.ubnt.com, you'll be able to connect and repro on your machine. Does that work?
,
Jun 18 2016
Yes, if you can provide access I can debug further. I've restricted view on this bug to just those who are already included on the thread - this way you can post test account credentials or private info that only we can see.
,
Jun 18 2016
Also, about to head home for the day (week). See you Monday.
,
Jun 18 2016
Great thanks. I'll post the info on Monday. Have a good weekend!
,
Jun 18 2016
,
Jun 18 2016
,
Jun 18 2016
So, even though older versions of Chrome didn't exhibit this behavior our streams might not be 100% pristine. I attached 5 video players to the same bytestream, (creating different SourceBuffers for each though) and all 5 froze at the same time, leading me to believe something might be wrong with the actual content. Then, I set it up to cache the binary data as I was feeding it, when it froze, I downloaded the last 30 seconds. I attached two mp4s. bad.mp4 actually illustrates the behavior in browser, by just hitting play. Opening it up in VLC it seems to play back fine until you get to sec 16 or so at which point there is an obvious glitch. In the good.mp4, playback works as expected. I'll debug the actual contents of the mp4 on Monday, perhaps something is a little odd in the bad.mp4, probably something dts/pts related.
,
Jun 18 2016
Okay, so I've finally narrowed it down. The bad.mp4 I posted was actually inaccurate, due to an issue with how I was saving the file, I errantly included a segment from much earlier. Interestingly, it exhibits the same behavior and I still think it's an issue that needs to get addressed. Specifically, the audio track and video tracks should stay in sync. As for reproducing : The issue only arises if I append fragments that contain partial GOPs. Checking the buffered property on the SourceBuffer when appending partial GOP fragments, I see that there are multiple time ranges. I believe the video gets stuck at the end of one time range, while audio continues to play seamlessly. If I only append full GOP fragments, there is only one time range, despite multiple calls to append. I think I can put together a simple repro showing both scenarios, will try to get that together today or tomorrow.
,
Jun 18 2016
Okay, was able to break it down to a simple repro example. See attached. Note, you'll have to run this from a web server locally, I guess createObjectURL does not work with file:// urls.
,
Jun 18 2016
In the zip, there is also one combined mp4 (debug.mp4) which includes the MOOV and all of the fragments in one file. If you replace the call to loadFiles() with ` appendFile('mp4/debug.mp4');` you get the same result.
Inspecting the MP4 frames, the frames are there yet somehow Chrome is skipping over them when appending it seems. I.e.
1 0x000000000006289e 0x00000244 7156642 0 1000 66
1 0x0000000000062ae2 0x000001de 7156709 0 1000 66
1 0x0000000000062ee9 0x00000209 7156776 0 1000 66
1 0x000000000006214c 0x000002e8 7156842 0 1000 66
1 0x0000000000062434 0x00000235 7156909 0 1000 66
Those are the video frames in the file, yet Chrome has a gap in the TimeRanges
One Range ends at 7156.642721
And the next one starts at 7156.90975
It appears as if the 3 frames in between go missing somehow.
,
Jun 20 2016
Thanks for providing the zip file. So far I've taken just a quick look, but I notice that the audio buffers appear to have gaps. This is a mixed audio/video SourceBuffer, so whenever either of the streams has a gap, the whole SourceBuffer has a gap (SourceBuffer.buffered is the intersection of all the buffered streams in that SourceBuffer). Here are some logs for a few of the early gaps I'm seeing in the audio stream: Pushing frame: aud=1, key=1, dur=92, dts=7153937, cts=7153937, size=365 Pushing frame: aud=1, key=1, dur=92, dts=7154123, cts=7154123, size=365 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) Pushing frame: aud=1, key=1, dur=92, dts=7154030, cts=7154030, size=364 ProcessFrame: Discontinuity: reprocessing frame - frame is out of order, timestamp lower than previous frame Pushing frame: aud=1, key=1, dur=92, dts=7154216, cts=7154216, size=364 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) ... (range of good frames here) Pushing frame: aud=1, key=1, dur=92, dts=7155609, cts=7155609, size=365 Pushing frame: aud=1, key=1, dur=92, dts=7155795, cts=7155795, size=365 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) Pushing frame: aud=1, key=1, dur=92, dts=7155702, cts=7155702, size=364 ProcessFrame: Discontinuity: reprocessing frame - frame is out of order, timestamp lower than previous frame Pushing frame: aud=1, key=1, dur=92, dts=7155888, cts=7155888, size=364 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) ... (range of good frames here) Pushing frame: aud=1, key=1, dur=92, dts=7156538, cts=7156538, size=364 Pushing frame: aud=1, key=1, dur=92, dts=7156816, cts=7156816, size=365 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) Pushing frame: aud=1, key=1, dur=92, dts=7156631, cts=7156631, size=365 ProcessFrame: Discontinuity: reprocessing frame - frame is out of order, timestamp lower than previous frame Pushing frame: aud=1, key=1, dur=92, dts=7156723, cts=7156723, size=364 Pushing frame: aud=1, key=1, dur=92, dts=7156909, cts=7156909, size=364 ProcessFrame: Discontinuity: reprocessing frame - frames are too far apart (pts delta >= 2x the duration of prev frame) ... etc. I suspect these gaps are the root (or at least a significant part) of the problem. Can you fix these and see if things resolve?
,
Jun 20 2016
MSE is strict about timing. To avoid gaps, you should have each buffer such that timestamp_current = timestamp_previous + duraiton_previous And never have timestamps move backward.
,
Jun 20 2016
I just compared those same files from the source and I don't see any out of order or missing audio samples. We have an audio clock rate of 11025, is it possible there is a rounding error when converting samples to ms time? Will continue investigating on my end. Are we able to add a colleague of mine to this issue? Thanks.
,
Jun 20 2016
So, it appears that while we don't have any gaps. We do have out of sequence samples/frames due to receiving the frames out of sequence from the camera. I am still getting stuck video occasionally when there is only one TimeRange, but it might still be related to out-of-sequence frames. So I'll try to resolve the sequence issue on my side, but I feel like something needs to change in Chrome as well. Right now it fails silently, even if it threw an exception that would be better than what currently happens. Thanks.
,
Jun 20 2016
Re: adding your colleague, yes definitely. Seems we didn't need any private info to get your repro. If its OK with you I can re-open the issue to the public and your colleague can contribute. Or I can just CC them directly. LMK Re: gaps, I think you're probably correct with the out of sequence frames still being a problem, even when buffered reports only one TimeRange. LMK how things look when your frames are in perfect sequence. Whenever MSE sees a gap it will start discarding all non-key frames until the next key frame is appended. For audio/video in a single SourceBuffer, a gap in just the audio stream is still enough to trigger this discard behavior for both the audio and the video streams [0]. This means that even if the whole is plugged by going back and inserting the out-of-order audio frame, the video stream is likely to be missing frames now. I think whats happening is your out-of-order appends create gaps, which cause video frames to be discarded. Some of those gaps get plugged, but some don't. The video freezes because lots of video frames were discarded and ultimately the audio freezes (full pause) because currentTime bumps into a gap in the buffered TimeRanges. Gaps are situation-normal for MSE, but perhaps we could be more helpful by logging to chrome://media-internals every time a gap is created. Would that have helped you here? [0] See "Set the need random access point flag on all track buffers to true." https://www.w3.org/TR/media-source/#sourcebuffer-coded-frame-processing
,
Jun 20 2016
Well, the baviour I'm speaking of is : paused on the video element is false, currentTime keeps getting incremented and I hear audio but video is stuck in the past. If I do video.currentTime = video.currentTime the video catches up to where it should be. That doesn't seem like intended behavior does it? In the example I posted you can see what I mean by typing video.currentTime = video.currentTime into the console while it is playing to see the video unstick for a little bit before getting stuck again. It's the appearance that everything is fine when it isn't. The video pausing and actually returning true from the paused property would be fine, currentTime not continuing to increment would also be fine.
,
Jun 20 2016
Oh yeah totally fine to open up the issue btw.
,
Jun 20 2016
,
Jun 21 2016
Issue is now open to all. "It's the appearance that everything is fine when it isn't." The challenge here is you haven't done anything illegal as far as API usage goes. Appending data with out of order timestamps can be a legitimate use of MSE, and its hard to know the intent of the API user. This is why I suggested maybe giving a FYI log in chrome://media-internals. I need to spend a little more time digging into why setting currentTime seems to have some effect. I'm also a little surprised to see the audio go so long without video (I expect no more than 3 seconds of audio-only before pause). Even if these turn out to be bugs, I still don't think we can throw exceptions when users append out-of-order.
,
Jun 21 2016
Understood, I don't really have an issue with out-of-order appends. I get the TimeRanges thing too, but if I get to the end of a TimeRange, everything should stop, video/audio and currentTime should not continue to increment. The issue is that I have video/audio for time N, and audio for that time will continue to play but video will be frozen. If I set the currentTime to the same value after it's stuck, then it will unstick.
,
Jun 21 2016
"but if I get to the end of a TimeRange, everything should stop" I generally agree. We expect audio should play for about 3 seconds beyond video before seeing everything stop. This 3 second timeout is by-design in the case where we still have audio but no video. This helps streaming sites to avoid a full pause when new video frames are just about to arrive. When I test on current stable (51.0.2704.103), I hear audio continue playing about 10 seconds after the video freezes. But when I test with canary on OSX (or more recent dev builds on linux), I find that everything pauses after 3 seconds of no video frames. I have no idea why that's changed from stable to canary, but I'm happy to see it back to normal. Dale, any clues? This 3 second stall timer is also why setting video.currentTime = video.currentTime is able to temporarily resume playback. Note that SourceBuffer.buffered is an intersection of the buffered TimeRanges for the audio and video streams. Video has a gap about 2 seconds into the stream (caused by out-of-sequence stuff in earlier discussion), but audio doesn't have a gap there (since the out-of-order frame did eventually arrive). In the window of 3 seconds, audio continues playing, advancing currentTime into (and beyond) the region of video's gap. When you set currentTime = currentTime, you are seeking the video stream past the gap it was snagged on (only to have it hit another gap shortly after). Sometimes audio ends up paused right in the middle of video's gaps... so setting currentTime = currentTime does no good.
,
Jun 21 2016
That makes sense, however, something still doesn't quite add up. From what you say, TimeRanges are an intersection of A/V, so if I have continuous audio or video, it should extend the TimeRange right? I guess, if say audio plays 3 seconds past the last video frame, then if there is video within that 3 second window, it should resync and continue to play right? IMO video.currentTime should be the source of truth for both the audio and video tracks. If that's only true some of the time, it makes it really hard to reason about. If content for a track is missing, that would be fine, that track could still get extended with empty contents. Obviously, we definitely need to fix the issue with our input, but I also want to achieve resiliency if we can.
,
Jun 21 2016
I believe M51 stable does not have my underflow fixes for low delay mode which would mean it would not reliably trip the 3 second window.
,
Jun 21 2016
"From what you say, TimeRanges are an intersection of A/V, so if I have continuous audio or video, it should extend the TimeRange right? " This would be true for union, but for intersection gaps in one stream = gaps in the combined intersection. This is how the MSE spec describes it. "I guess, if say audio plays 3 seconds past the last video frame, then if there is video within that 3 second window, it should resync and continue to play right?" This is theoretically possible, but its probably not what we want to do. We're already being a little loose with the spec by waiting 3 seconds to report video underflow. Skipping over gaps entirely is much looser still. We prefer to stay as close to the spec as possible to give inter-operable well defined behavior and keep the implementation maintainable. "IMO video.currentTime should be the source of truth for both the audio and video tracks. If that's only true some of the time, it makes it really hard to reason about." I hear you. currentTime is the source of truth for all tracks the overwhelming majority of the time. But this caveat about video underflow does exist. "If content for a track is missing, that would be fine, that track could still get extended with empty contents." This is the opposite of what the spec would have us do.
,
Jun 21 2016
Okay, fair enough. What about the scenario where there is a video gap, but we have audio so we continue to play for 3 seconds, in that period the video gap is filled... what happens then? What I've seen happen in stable is audio plays for a long long time after video has frozen. So, even though there is a gap, the audio playing back is part of a new range, from what you describe it sounds like we should never automatically jump into a new range, is that correct? As long as that's true and TimeRanges really are intersected then that would be fine. Doesn't seem to be the case currently though.
,
Jun 22 2016
>What about the scenario where there is a video gap, but we have audio so we continue to play for 3 seconds, in that period the video gap is filled... what happens then? Then playback would proceed normally. We would skip rendering of a few video frames that are now behind currentTime, but you wouldn't hear audio stutter and video would appear to suddenly unfreeze. >So, even though there is a gap, the audio playing back is part of a new range, from what you describe it sounds like we should never automatically jump into a new range, is that correct? As long as that's true and TimeRanges really are intersected then that would be fine. Doesn't seem to be the case currently though. Its complicated. You're correct that we should never automatically jump into a new range, and you will definitely not see any range-jumping if you have a gap in both streams. But you're also right that our 3 sec timer may cause audio to advance slightly past a gap that really only exists in the video stream (which will appear as a gap in the intersected SourceBuffer.buffered). If that gap remains un-filled it will stop shortly thereafter (except when we have bugs...). This subtlety/complexity is a tradeoff for delaying video-underflow by 3 seconds.
,
Jun 22 2016
So, to update I got to the root of the issue. We were indeed appending moof/mdat pairs out of order (sometimes). I.e. we would occasionally append in the order of A, C, B instead of A, B, C. This would happen if the updating property of the SourceBuffer was true when we tried to append, thus we delayed the append 'til the updateend event. Adding to a queue and always shifting from that queue on appends resolved the issue.
,
Jun 23 2016
Awesome! I'll leave this open as a reminder to add some chrome://media-internals logging when we detect discontinuities in appends. There are lots of legit reasons to have a discontinuity, so the logging will just be an FYI, not a warning.
,
Aug 18 2016
|
||||||||
►
Sign in to add a comment |
||||||||
Comment 1 by shrike@chromium.org
, Jun 3 2016