Closed Bug 929431 Opened 6 years ago Closed 5 years ago

Long delay before starting WebRTC session due to camera reinitialisation

Categories

(Core :: WebRTC: Audio/Video, defect, P2)

x86_64
Windows 7
defect

Tracking

()

RESOLVED FIXED
mozilla34
Tracking Status
firefox33 --- fixed
firefox34 --- fixed

People

(Reporter: gcp, Assigned: gcp)

References

Details

Attachments

(4 files, 2 obsolete files)

When starting a WebRTC call in talky.io (but I presume it happens with other sites - that's just the one I use most) there is often a very long delay on my Windows 7 machine before the call initializes. During this time, I can see the "camera on" light on my Logitech C910 webcam flicker constantly. As far as I can tell, Firefox is constantly enabling and then disabling the camera again for some reason.

The delay does not happen on Android and the delay/light flicker doesn't happen in any other RTC apps.
Can you get timestamp,mediamanager:5,getusermedia:5,webrtc_trace:65535 logs (with WEBRTC_TRACE_FILE=whatever)? Thanks
Flags: needinfo?(gpascutto)
Whiteboard: [getusermedia]
Attached file NSPR log (obsolete) —
Flags: needinfo?(gpascutto)
Attached file webrtc.zip (obsolete) —
2013-10-24 10:24:19.865000 UTC - 0[5ed438]: mozilla::MediaManager::MediaManager: default prefs: 640x480 @30fps (min 10)
2013-10-24 10:24:19.866000 UTC - 0[5ed438]: New Media thread for gum
2013-10-24 10:24:35.266000 UTC - 4628[19dcd790]: mozilla::MediaEngineWebRTC::EnumerateVideoDevices Logging webrtc to webrtc.log level 65535

Note the 15 second delay. I think it's opening/closing/reinitializing the camera for each and every possible video mode it supports.
I have a c915 (with ~30 video modes, vs 23 for my W530's internal camera, and 56 in your c910).  Starting audio/video gum with that takes <1 second on my Win7.  also, the 15 second delay there is from startup until getUserMedia was called I believe.

There is a 4 second delay it appears opening audio, or actually starting the camera in the selected mode (though that seems to take ~ 0.7 seconds a bit after audio).

Please retry with "webrtc_trace:65535" added to the modules, and another env var "WEBRTC_TRACE_FILE=whatever", and then send both files.  That has a lot more internal data.

Thanks.
Flags: needinfo?(gpascutto)
That file is already attached to the bug...webrtc.zip
As pointed out in the previous comment, the requested logs were already in the first comment. Clearing needinfo.
Flags: needinfo?(gpascutto)
This bug still reproduces. I really wouldn't actually want to use WebRTC on the machine this happens on (which happens to be my main development machine, yay), so I'm going to make this a blocker.
Blocks: 970426
I've been looking at this.  It appears the long delay was *before* the webrtc.log started (or was overwritten by a new instance)
Assignee: nobody → rjesup
GCP: can you get an updated logset?  We may need to make a patch to avoid overwriting the trace log with a new one, which appeared to be happening.

This may be specific to the C910.  I'm removing blocking Media-for-MVP until we have confirmation it's not a device-specific problem.
No longer blocks: 970426
Flags: needinfo?(gpascutto)
Logs from current attempt. NSPR logged less than I would have expected, but I think the webrtc trace shows the delay:

DEBUGINFO ; ( 8:58:54:322 |    1) VIDEO CAPTUR:    0  4097;      4520; GetMediaType position 3, width 640, height 480, biCompression 0x47504a4d
DEBUGINFO ; ( 8:58:54:322 |    0) VIDEO CAPTUR:    0  4097;      4520; CheckMediaType width:640 height:480 Compression:0x0

STREAM    ; ( 8:59:31:373 |37051) VIDEO CAPTUR:    0  4097;      2976; IncomingFrame width 640, height -480
STREAM    ; ( 8:59:31:373 |    0)        VIDEO:    0  4097;      2976; 

(Note the whitespace!)
Attachment #821589 - Attachment is obsolete: true
Attachment #821593 - Attachment is obsolete: true
Flags: needinfo?(gpascutto)
Priority: -- → P2
Target Milestone: --- → mozilla33
Target Milestone: mozilla33 → mozilla35
Fix some newlines that make the logs more annoying to read.
Attachment #8472484 - Flags: review?(rjesup)
Do a better job of selecting a matching capability by refining on the FPS
and the format the camera sends us. This brings us closer to GetBestMatchedCapability
in the WebRTC code (which is where the list of "interesting" formats comes from), but 
which we can't use because we're not really doing the same thing and it's not easily 
accessible at this point.

On my camera, this fixes the video being sent to Firefox in RGB24 and causes it to
receive I420 instead, removing at least one needless format conversion.
Attachment #8472489 - Flags: review?(rjesup)
When we start the DirectShow camera capture code, it initializes the camera 
in order to get a lock on it. For this, it uses a specific default 640x480@30.

If the constraints don't overrule us, our capture default is 640x480@60, so
that's what a lot of WebRTC stuff will end up capturing at.

Because they don't match up, the camera seemingly has to be initialized
twice. This is unfortunate.

What's even more unfortunate is that when we request that res@60, my
camera can't do it and gives us the closest thing, being @30. When we
start the stream, the code notices that the constraints it had used
for allocating the camera don't match up with the current ones, and
decides the camera needs to be reinitialized...despite the fact that
it's already in that mode.

This reworks the WebRTC code to remember what the camera actually is
at, and only reinitialize if needed.

For me, this seems to solve the original bug.
Attachment #8472500 - Flags: review?(rjesup)
Attachment #8472484 - Flags: review?(rjesup) → review+
Comment on attachment 8472489 [details] [diff] [review]
Improve matching of camera capabilities to WebRTC restraints

Review of attachment 8472489 [details] [diff] [review]:
-----------------------------------------------------------------

::: content/media/webrtc/MediaEngineWebRTCVideo.cpp
@@ +323,5 @@
> +        if (cap.rawType == webrtc::RawVideoType::kVideoI420
> +          || cap.rawType == webrtc::RawVideoType::kVideoYUY2
> +          || cap.rawType == webrtc::RawVideoType::kVideoYV12) {
> +          mCapability = cap;
> +        }

This is good; we still might want to consider the comparison between MJPEG vs RGB24, etc (I suspect in most cases we'll prefer MJPEG, but it's an interesting question).  Another question would be if one of the width/height match but not the other, or if they're "close".  For another day
Attachment #8472489 - Flags: review?(rjesup) → review+
Comment on attachment 8472500 [details] [diff] [review]
Don't reinitialize DirectShow if it's not actually needed. r=

Review of attachment 8472500 [details] [diff] [review]:
-----------------------------------------------------------------

r+ so long as this doesn't monopolize the camera (other apps can't open it) or leave the camera light on.  I'm rather concerned about the first...  Please test against various apps before committing.
Attachment #8472500 - Flags: review?(rjesup) → review+
bas: any comments about leaving the graph connected?
Flags: needinfo?(bas)
There's no change in the relevant behavior there. The old code would keep the graph connected and disconnect+immediately reconnect if the resolution/fps/format change, or just keep it connected if it was exactly the same. The new code is just smarter about what "the same" really is.
Flags: needinfo?(bas)
(In reply to Randell Jesup [:jesup] from comment #16)
> bas: any comments about leaving the graph connected?

I doubt it's going to make a lot of difference whether the graph remains connected or not. Obviously if we changed the lifetime of the nodes that might affect our memory use, keeping nodes connected in itself should not make a difference. I don't think it will cause use to monopolize the camera as long as we don't keep the stream active.
Should consider for Aurora since it may fix a lot of cameras out there.
Assignee: rjesup → gpascutto
Whiteboard: [getusermedia] → [getusermedia][webrtc-uplift]
Target Milestone: mozilla35 → mozilla34
Comment on attachment 8472489 [details] [diff] [review]
Improve matching of camera capabilities to WebRTC restraints

Approval Request Comment
[Feature/regressing bug #]: getting WebRTC working
[User impact if declined]: Cameras with crappy drivers (probably all of them) won't work as well.
[Describe test coverage new/current, TBPL]: Landed on m-c a few days ago, getting happy reports from the field.
[Risks and why]: Might break some cameras with drivers that are broken in another way.
[String/UUID change made/needed]: None
Attachment #8472489 - Flags: approval-mozilla-aurora?
Comment on attachment 8472484 [details] [diff] [review]
Remove spurious newlines from the logging. r=

See above.
Attachment #8472484 - Flags: approval-mozilla-aurora?
Comment on attachment 8472500 [details] [diff] [review]
Don't reinitialize DirectShow if it's not actually needed. r=

See above.
Attachment #8472500 - Flags: approval-mozilla-aurora?
Attachment #8472484 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8472489 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8472500 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Blocks: 1044707
I couldn't reproduce the initial issue using old Nightly builds with Genius and Logitech webcams under Win 7 64-bit and with the integrated camera of an ultrabook with Win 8 64-bit.

Can someone else please verify? I'm removing the keywords since we can't reproduce it.
Keywords: qawanted, verifyme
I'm not sure who else besides me experienced this, but the camera now starts instantly under Nightly, and other people in bug 1044707 were happy. (I can't mark the bug verified, though)
Whiteboard: [getusermedia][webrtc-uplift]
You need to log in before you can comment on or make changes to this bug.