929431 - Long delay before starting WebRTC session due to camera reinitialisation

Status: RESOLVED FIXED

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

Description

[Gian-Carlo Pascutto [:gcp]]

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.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Can you get timestamp,mediamanager:5,getusermedia:5,webrtc_trace:65535 logs (with WEBRTC_TRACE_FILE=whatever)? Thanks

Comment 2

[Gian-Carlo Pascutto [:gcp]]

Attachment: NSPR log

Comment 3

[Gian-Carlo Pascutto [:gcp]]

Attachment: webrtc.zip

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.

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

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.

Comment 5

[Gian-Carlo Pascutto [:gcp]]

That file is already attached to the bug...webrtc.zip

Comment 6

[Gian-Carlo Pascutto [:gcp]]

As pointed out in the previous comment, the requested logs were already in the first comment. Clearing needinfo.

Comment 7

[Gian-Carlo Pascutto [:gcp]]

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.

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

I've been looking at this.  It appears the long delay was *before* the webrtc.log started (or was overwritten by a new instance)

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

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.

Comment 10

[Gian-Carlo Pascutto [:gcp]]

Attachment: Logs 2nd attempt webrtclogs.zip

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

Comment 11

[Gian-Carlo Pascutto [:gcp]]

Attachment: Remove spurious newlines from the logging. r=

Fix some newlines that make the logs more annoying to read.

Comment 12

[Gian-Carlo Pascutto [:gcp]]

Attachment: Improve matching of camera capabilities to WebRTC restraints

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.

Comment 13

[Gian-Carlo Pascutto [:gcp]]

Attachment: Don't reinitialize DirectShow if it's not actually needed. r=

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.

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

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

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

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.

Comment 16

[Randell Jesup [:jesup] (needinfo me)]

bas: any comments about leaving the graph connected?

Comment 17

[Gian-Carlo Pascutto [:gcp]]

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.

Comment 18

[Bas Schouten (:bas.schouten)]

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

Comment 19

[Gian-Carlo Pascutto [:gcp]]

https://tbpl.mozilla.org/?tree=Try&rev=4c26641d9195

Comment 20

[Gian-Carlo Pascutto [:gcp]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/22108bb9a24a
https://hg.mozilla.org/integration/mozilla-inbound/rev/cdd3b3f73c79
https://hg.mozilla.org/integration/mozilla-inbound/rev/d26db5427e8a

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/22108bb9a24a
https://hg.mozilla.org/mozilla-central/rev/cdd3b3f73c79
https://hg.mozilla.org/mozilla-central/rev/d26db5427e8a

Comment 22

[Randell Jesup [:jesup] (needinfo me)]

Should consider for Aurora since it may fix a lot of cameras out there.

Comment 23

[Gian-Carlo Pascutto [:gcp]]

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

Comment 24

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8472484 [details] [diff] [review]
Remove spurious newlines from the logging. r=

See above.

Comment 25

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8472500 [details] [diff] [review]
Don't reinitialize DirectShow if it's not actually needed. r=

See above.

Comment 26

[Gian-Carlo Pascutto [:gcp]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/86335dfe8418
https://hg.mozilla.org/releases/mozilla-aurora/rev/8e039cfde354
https://hg.mozilla.org/releases/mozilla-aurora/rev/4d0bbb50982d

Comment 27

[Petruta Horea [:phorea], Desktop Test Engineering (back on Sep 5th)]

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.

Comment 28

[Gian-Carlo Pascutto [:gcp]]

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)