webrtc video transmitted by Android phones at a very slow frame rate

RESOLVED FIXED

Status

()

Core
WebRTC: Audio/Video
--
major
RESOLVED FIXED
5 years ago
3 years ago

People

(Reporter: dmose, Assigned: gcp)

Tracking

Other Branch
ARM
Android
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(5 attachments, 8 obsolete attachments)

(Reporter)

Description

5 years ago
Jesup did some wiresharking on this yesterday, and I have an IRC log of discussion about how to dig into this to figure out what's really going on.

Updated

5 years ago
Whiteboard: [WebRTC] [blocking-webrtc-]
(Reporter)

Comment 1

5 years ago
Created attachment 714099 [details]
webrtc trace from a video call

Just starting to look through this.  The call ended uncleanly before the log stopped, so it's possible that the end of the log is bogus.

One thing I noticed is a few instances of 

WARNING   ; (14:23:15:506 |  146) VIDEO CAPTUR:    3  4097;      3604; Too long processing time of Incoming frame: 11ms

Which I suppose might make something upstream of the capture code decide to throttle frame rate.  Maybe.

A fair number of these:

WARNING   ; (14:23:33:689 |   43) VIDEO RENDER:         -1;      3660; AddFrame: too old frame.

Which I assume, but don't actually know, are from the incoming video, which is presumably not relevant here.
(Reporter)

Comment 2

5 years ago
Created attachment 714159 [details]
call 2, webrtc_trace logging
(Reporter)

Comment 3

5 years ago
Created attachment 714160 [details]
call 2, nspr signaling logging

OK, the signalling log contains at least conduit log info, which adds something here.  I rather suspect I'm going to need to tweak the logging patch some more to force more of the logging on in an opt build (eg I suspect we're not getting media pipeline logging yet).  This doesn't look too hard, as there's a pattern in ImageLogging.h that should help the compiler find the places this needs to happen.

In any case, it'd be interesting to know if there's anything that can be inferred from what we've gotten so far.
(Reporter)

Comment 4

5 years ago
Created attachment 714216 [details]
call 3, webrtc_trace logging
(Reporter)

Comment 5

5 years ago
Created attachment 714218 [details]
call 3, ALL nspr signaling logging

This is with all the signalling logging forced on, from what I can tell.  The patch that does that is in bug 841641.
(Reporter)

Updated

5 years ago
Depends on: 841641
(Reporter)

Comment 6

5 years ago
Created attachment 714866 [details] [diff] [review]
WIP enable send rate logging, v1
Attachment #714099 - Attachment is obsolete: true
Attachment #714159 - Attachment is obsolete: true
Attachment #714160 - Attachment is obsolete: true
Attachment #714216 - Attachment is obsolete: true
Attachment #714218 - Attachment is obsolete: true
(Reporter)

Comment 7

5 years ago
I've just attached a somewhat icky patch enable send rate logging that generates logs that answer some of the meaningful questions here.  I imagine we'll want a less icky version if this in production at some point.

Will attach generated logs shortly.
(Reporter)

Comment 8

5 years ago
Created attachment 714871 [details]
webrtc trace from video call with bit & frame rate logging

Here's the bzipped log file that got generated.  It's giant.  Some thoughts:  if one greps for "itrate", the result show some interesting things.  One is that the bitrate is gradually ratched down to the point where it goes below the minimum.  Another is that there are alternating calls to SendStatistics that have birate 0, framerate 0.  Hmmm.

Separately, if one greps the log for "los" (since it matches both "loss" and "lost"), those numbers appear to always be zero.  Which makes it unclear why the bitrate controller is ratcheting things down in the first place.

Here's the results of the "itrate" grep:

STATEINFO ; (21:10: 7:493 |    0) VIDEO CODING:    0     0;      9445; Codec: VP8, Payload type 120, Height 288, Width 352, Bitrate 100, Framerate 30.
DEBUGINFO ; (21:10: 7:510 |    0)        VIDEO:    2     0;      9445; SetReceiveCodec: codec: 0, pl_type: 120, width: 640, height: 480, bitrate: 300,maxBr: 2000, min_br: 200, frame_rate: 30
STATEINFO ; (21:10: 7:511 |    0) VIDEO CODING:    0     0;      9445; Codec: VP8, Payload type 120, Height 480, Width 640, Bitrate 300, Framerate 30.
STATEINFO ; (21:10: 7:568 |    0) VIDEO CODING:    0     0;      9445; Codec: VP8, Payload type 120, Height 288, Width 352, Bitrate 100, Framerate 30.
DEBUGINFO ; (21:10: 7:590 |    6)        VIDEO:    3     0;      9445; SetSendCodec: codec: 0, pl_type: 120, width: 640, height: 480, bitrate: 300maxBr: 2000, min_br: 200, frame_rate: 30, qpMax: 0,numberOfSimulcastStreams: 0 )
MODULECALL; (21:10: 7:592 |    0)     RTP/RTCP:    3     0;      9445; SetTargetSendBitrate: 300000bit
DEBUGINFO ; (21:10: 8:399 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 325000, fraction_lost: 0, rtt_ms: 0
DEBUGINFO ; (21:10: 8:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
MODULECALL; (21:10: 8:548 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 325000bit
DEBUGINFO ; (21:10: 8:561 |    1)        VIDEO:    3     0;      9700; SendStatistics: bitrate 31, framerate 3
DEBUGINFO ; (21:10: 9:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10: 9:604 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 193, framerate 3
STREAM    ; (21:10: 9:619 |    0)     RTP/RTCP:         -1;      9694; BWE: Increase rate to currentBitRate = 30001 kbps
DEBUGINFO ; (21:10:10:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:10:480 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 352000, fraction_lost: 0, rtt_ms: 0
MODULECALL; (21:10:10:624 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 352000bit
DEBUGINFO ; (21:10:10:624 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 383, framerate 4
DEBUGINFO ; (21:10:11:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:11:606 |    2)        VIDEO:    3     0;      9700; SendStatistics: bitrate 424, framerate 4
DEBUGINFO ; (21:10:12:478 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 200000, fraction_lost: 0, rtt_ms: 0
DEBUGINFO ; (21:10:12:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
MODULECALL; (21:10:12:675 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 200000bit
WARNING   ; (21:10:12:675 |    0)     RTP/RTCP:         -1;      9458; The configured min bitrate (200 kbps) is greater than the estimated available bandwidth (190 kbps).
DEBUGINFO ; (21:10:12:676 |    1)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 200000, fraction_lost: 0, rtt_ms: 0
MODULECALL; (21:10:12:676 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 200000bit
DEBUGINFO ; (21:10:12:676 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 489, framerate 3
DEBUGINFO ; (21:10:13:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:13:724 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 200000, fraction_lost: 0, rtt_ms: 0
DEBUGINFO ; (21:10:13:847 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 215, framerate 2
MODULECALL; (21:10:13:847 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 200000bit
WARNING   ; (21:10:13:847 |    0)     RTP/RTCP:         -1;      9458; The configured min bitrate (200 kbps) is greater than the estimated available bandwidth (195 kbps).
DEBUGINFO ; (21:10:13:847 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 200000, fraction_lost: 0, rtt_ms: 0
MODULECALL; (21:10:13:847 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 200000bit
DEBUGINFO ; (21:10:14:317 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 200000, fraction_lost: 0, rtt_ms: 0
MODULECALL; (21:10:14:317 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 200000bit
DEBUGINFO ; (21:10:14:479 |    0)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:14:590 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 433, framerate 2
STREAM    ; (21:10:14:613 |    0) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
STREAM    ; (21:10:15:271 |    1) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
DEBUGINFO ; (21:10:15:479 |    3)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:15:728 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 202675, fraction_lost: 0, rtt_ms: 0
DEBUGINFO ; (21:10:15:731 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 368, framerate 3
MODULECALL; (21:10:15:732 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 202675bit
STREAM    ; (21:10:15:744 |    0) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
STREAM    ; (21:10:16:276 |    0) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
STREAM    ; (21:10:16:445 |    0) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
DEBUGINFO ; (21:10:16:479 |    2)        VIDEO:    2     0;      9694; SendStatistics: bitrate 0, framerate 0
DEBUGINFO ; (21:10:16:799 |    0)        VIDEO:    3     0;      9700; SendStatistics: bitrate 320, framerate 4
DEBUGINFO ; (21:10:16:915 |    0)        VIDEO:    3     0;      9458; OnNetworkChanged(bitrate_bps: 207965, fraction_lost: 0, rtt_ms: 0
MODULECALL; (21:10:17:174 |    0)     RTP/RTCP:    3     0;      9458; SetTargetSendBitrate: 207965bit
STREAM    ; (21:10:17:211 |    0) VIDEO CODING:    0     0;      9701; Drop frame due to bitrate
dmose-laptop:~ dmose$
(Reporter)

Comment 9

5 years ago
Created attachment 714872 [details]
nsprlog trace from the same video call
I haven't looked into things closely yet, but I'll note the grep shows it hitting the 'floor' bitrate of 200K, and then slowly starting to come off it and move up (to 207965).  Given this is only a max 17 second snippet, that's not unreasonable-sounding - if the estimation of bandwidth available is in any manner correct, which may be a lot of the issue.
(Reporter)

Comment 11

5 years ago
Created attachment 715016 [details] [diff] [review]
WIP enable send rate logging, v2

Enabled more logging helpful for debugging send rate and bandwidth stuff.  This will probably want to spin out to another bug before long.
Attachment #714866 - Attachment is obsolete: true
(Reporter)

Comment 12

5 years ago
Created attachment 715018 [details]
bzipped of webrtc call log on dual-core S3 with even more detail
Attachment #714871 - Attachment is obsolete: true
(Reporter)

Comment 13

5 years ago
Created attachment 715019 [details] [diff] [review]
nspr signaling log of the same dual-core S3 video call
Attachment #714872 - Attachment is obsolete: true
(Reporter)

Comment 14

5 years ago
If one greps this trace for OnNetworkChanged, it looks less extremely bad (everything 200k and above).  I still have a big list of stuff to investigate, and the fact that SendStatistics calls get bitrate=0 framerate=0 literally every other call still strikes me as weird, since the calls that do have frames have between 2 and 4.  I'm surprised these aren't spread out more unevenly.
(Reporter)

Updated

5 years ago
Attachment #715018 - Attachment description: bzipped of webrtc call log with even more detail → bzipped of webrtc call log on dual-core S3 with even more detail
(Reporter)

Updated

5 years ago
Attachment #715019 - Attachment description: nspr signaling log of the same video call → nspr signaling log of the same dual-core S3 video call
(Reporter)

Comment 15

5 years ago
Created attachment 715023 [details] [diff] [review]
bzipped webrtc log of N4 -> Mac call
(Reporter)

Comment 16

5 years ago
Created attachment 715024 [details]
nspr signaling log of N4 -> Mac call
(Reporter)

Comment 17

5 years ago
So, just tried on a Nexus 4 running Android 4.2.2.  Video is still choppy, but noticably less so.  Grepping the dual-core S3 logs of OnNetworkChanged() showed estimated available bitrates in the 180k -> 300k+ range.  Grepping the N4 logs shows estimates in the range of 440k -> 578k.  This is consistent with derf's hypothesis that CPU-bandwidth for encoding is a bottleneck.
(Assignee)

Updated

5 years ago
Assignee: dmose → gpascutto
gian-carlo - is this still relevant?  Even if there are still quality/perf issues, I suspect this exact bug is no longer relevant.
Flags: needinfo?(gpascutto)
Whiteboard: [WebRTC] [blocking-webrtc-]
(Assignee)

Comment 19

3 years ago
Assuming this is fixed by the boatloads of improvements since.
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Flags: needinfo?(gpascutto)
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.