1224845 - High CPU usage while using WebRTC

Status: RESOLVED FIXED

(Core :: WebRTC: Networking, defect, P1)

Description

[Marco Castelluccio [:marco]]

A call drained my battery in ~30 minutes, Firefox was using ~100% of one of the CPU cores.

Comment 1

[Marco Castelluccio [:marco]]

This is pretty bad, even on my new ThinkPad W541.

Comment 2

[Marco Castelluccio [:marco]]

Attachment: Profile

Comment 3

[Marco Castelluccio [:marco]]

83.9% of the profile is in the poll syscall.
I guess this is either a WebRTC or graphics issue.

Comment 4

[Marco Castelluccio [:marco]]

22% is in XUnlockDisplay.

16% is in mozilla::FrameLayerBuilder::PaintItems(nsTArray<mozilla::FrameLayerBuilder::ClippedDisplayItem>.

So I think it's a Graphics bug.

Comment 5

[Marco Castelluccio [:marco]]

CPU usage was high even when disabling video on both ends.

Comment 6

[Marco Castelluccio [:marco]]

Looks like it's not only in Firefox Hello, but also other websites using WebRTC (e.g. https://apprtc.blogspot.com/).

Comment 7

[Marco Castelluccio [:marco]]

Here's the regression range: https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=4eade4f528d48b6a82eb5141e145ef11cb915793&tochange=dfb822545e3446e8d01bb3fb25e4313350c72c0e

Comment 8

[Marco Castelluccio [:marco]]

I suspect bug 797262.

Comment 9

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

FYI

Comment 10

[Nils Ohlmeier [:drno]]

I'm wondering if the amount of IPv6 addresses increases the problem. Because my Ubuntu desktop machine in the Mozilla Mountain View office seems to collect IPv6 addresses like crazy. Marco could you please check if and how many IPv6 addresses your laptop has?

Comment 11

[Marco Castelluccio [:marco]]

I have three addresses for the WiFi interface:
2001:450:1d:232:5ec5:d4ff:fedf:985a/64 Scope:Global
2001:450:1d:232:a90f:5e7:398a:2032/64 Scope:Global
fe80::5ec5:d4ff:fedf:985a/64 Scope:Link

Comment 12

[Nils Ohlmeier [:drno]]

Indeed we have a regression here between 41 and 42 on Linux only. On my Ubuntu desktop machine I get for a WebRTC call in appr.tc:
- 41: ~80% CPU load (IPv4 connection)
- 42: ~140% CPU load (over IPv4 and IPv6 connections)

On Mac I only see a difference of maybe 5-10% in CPU load, but I would assume that is in the area of measurement fault.

Comment 13

[Nils Ohlmeier [:drno]]

Forgot to add that I think the Gecko profiler data doesn't help us much here, because even on Mac the Gecko Profiler shows me that Firefox spends 80-90% of its time in polling the network connections (which makes perfect sense because we receive and send packets at very high rates).

Comment 14

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

e10s or not?  I think 41 and 42 had e10s on in Nightly, but certainly not in beta or release, so I'm assuming not.

Gecko Profiler only profiles threads that opt-in, and that doesn't include webrtc.org threads/pthreads generally.

System-level profilers or the internal jprof profiler do work.  jprof is linux-only but that's what we need here.

add ac_add_options --enable-jprof to .mozconfig, and 'JPROF_FLAGS="JP_DEFER JP_PERIOD=0.002"' to the env vars

Then after starting firefox, do kill -PROF <pid of process>.

Let the test run for a little while (longer the better - a few minutes is more than enough).  Then "kill -USR1 <pid>" to stop profiling (you can turn it on and off multiple times - even from JS in non-e10s mode, though I haven't tried that recently).

Comment 15

[Nils Ohlmeier [:drno]]

I used 41 and 42 release builds download from our website. So no e10s involved.

Comment 16

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

I tried 41 & 42 (and the revs before and after the ipv6 landing) on Fedora 22 (with a local ipv4 address used, though I have an IPV6 address it appears).  No change in CPU usage worth speaking of.  Talky.io calls were ~55-62%.

$ ifconfig
em1: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.1.17  netmask 255.255.255.0  broadcast 192.168.1.255
        inet6 fe80::1a03:73ff:fec5:2cdc  prefixlen 64  scopeid 0x20<link>
        ether 18:03:73:c5:2c:dc  txqueuelen 1000  (Ethernet)

Comment 17

[Marco Castelluccio [:marco]]

I found the regression range using mozregression.
The easiest way to reproduce the issue was disabling e10s (which makes CPU usage clearer to see) and opening https://apprtc.appspot.com/.

Comment 18

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

(In reply to Marco Castelluccio [:marco] from comment #17)
> I found the regression range using mozregression.
> The easiest way to reproduce the issue was disabling e10s (which makes CPU
> usage clearer to see) and opening https://apprtc.appspot.com/.

I don't see a CPU difference between 41 and 42, let alone on either side of the regression range.  (Maybe it's 55-60% vs 57-63%, maybe - that's way less than anything reported, and in the noise floor).  My jprof runs aren't any use if I'm not seeing the effect.

My guess is it has to do either with networking differences between Ubuntu and Fedora, network driver differences (unlikely), or the network environment (in particular IPV6 addresses and LAN setup).  Any details on the network setup, OS version, network config and HW would be hugely helpful.

You could try building on either side of the regression (opt builds) with ac_add_options --enable-jprof in .mozconfig.  Then cd to objdir/dist/bin, start firefox (using a non-e10s profile) with env vars of JPROF_FLAGS="JP_DEFER JP_PERIOD=0.002".  Start a webrtc call.  from another shell, use "kill -PROF <pid_of_firefox>".  Let it sit for 5 minutes, then "kill -USR1 <pid_of_firefox>".  Quite firefox, and do "./jprof firefox jprof.log >/tmp/profile.html".

I realize this does require doing local builds - sorry.  Do this once for before the regression, and once after, and attach the html files here.

Comment 19

[Marco Castelluccio [:marco]]

I'm currently at home for the holidays, where I can't reproduce the issue. I can do that once I'm back in my office, but it's going to take some time.

Maybe Nils can do it earlier than me?

Comment 20

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

Nils is away for the holidays as well.  Whomever gets home first wins! ;-)

Comment 21

[Nils Ohlmeier [:drno]]

Attachment: jprofiler output from a webrtc call

Looks like canceling poll() in our GTK code is adding massive delays.

Comment 22

[Nils Ohlmeier [:drno]]

After digging around in the profiler output and the code a little bit more it looks to me like:
A) The higher CPU usage is not caused by the way WebRTC/nICEr uses the network sockets
B) It looks to me this is some strange bug caused by the way how necko uses poll(), probably in combination with some OS specific (Ubuntu?) or other environment infused problem.

Randel what are your thoughts on the profiler output?

Comment 23

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

The DoPollIteration numbers implies to me TONS of poll wakeups.  That's 4.6% directly in that routine (walking the socket arrays), and 60% spent in that routine or others it calls (~19% in poll(), ~22% in nsSSLIOLayerPoll(PRFileDesc*, short, short*))

On Nightly Linux64 Fedora 22 debug, I see 2.1% total in DoPollIteration() in an apprtc call to another machine on the lan. I do have (1) IPV6 address assigned, in addition to a 192.168.x.x

Comment 24

[Nils Ohlmeier [:drno]]

Attachment: Profile from Ubuntu 14.04.3 with 2 IPv6 addresses

Another profile from the same machine, same call via appr.tc, approximately same call length of about 5 mins. Only difference is that at the time of the first profile the machine had 4 IPv6 addresses. For this run the machine had only 2 IPv6 addresses.

Comment 25

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

The difference is basically in the noise.  57% DoPollIteration vs 60%
If you can try with IPV6 support disabled (or the interfaces disable/blocked) that would be good.

Comment 26

[Nils Ohlmeier [:drno]]

Attachment: Profile from Fedora 21 with 1 IPV6 address

Profile of the same call but from Fedora 21 with only one IPv6 address.

That still looks like a lot of time being spend in DoPollIteration().

Comment 27

[Nils Ohlmeier [:drno]]

Attachment: Profile from Fedora 21 with IPv4 adresses only

This is the same call as before, but with IPv6 disabled via sysctl on the same Fedora 21 machine.

Clearly we have networking issue with IPv6.

Comment 28

[Nils Ohlmeier [:drno]]

Attachment: NSPR Log from nsSocketTransport for IPv4 only

NSPR log file taken with nsSocketTransport:5 on the machine with only a single IPv4 address active.

Comment 29

[Nils Ohlmeier [:drno]]

Attachment: NSPR Log from nsSocketTransport for IPv4 and IPv6

NSPR log taken with nsSocketTransport:5 on the same machine, this time the single Ethernet interface on the machine had IPv4 and IPv6 addresses available. The WebRTC called used only the v4 addresses as the other side did not provide v6 addresses.

Comment 30

[Nils Ohlmeier [:drno]]

The two nsSocketTransport log files look quite a bit different to me.

But I still can't tell what is going wrong here. Is simply that with IPv6 17 instead of 11 are polled?
The other difference seems to be the number of socket just with the PR_POLL_READ flag is a lot higher. So it looks almost as if most of our IPv4 socket have PR_POLL_READ & PR_POLL_EXCEPT set, but the IPv6 socket have only PR_POLL_READ. But I have no idea why that would cause so much more time getting spend in poll calls.
Any advice on how to debug this further?

Comment 31

[Nils Ohlmeier [:drno]]

Might be interesting to note that WebRTC's nICEr uses/sets PR_POLL_READ and PR_POLL_WRITE, but PR_POLL_EXCEPT doesn't show up at all in media/metransport/*. So I guess PR_POLL_EXCEPT gets set on the IPv4 sockets by some network code, but not on the IPv6 sockets. Could this result in the network code missing some errors and thus getting into this busy mode?

Comment 32

[Patrick McManus [:mcmanus]]

poll() exceptions are often unmaskable (they will be returned whether or not you ask for them at the OS level).. so i could imagine some code in necko adding the POLL_EXCEPT because it had an explicit error path to deal with it, but the media transport code not being aware to look for it (but still getting the wakeup when it just polled for read, because it is unmaskable).

nsSocketTransport2 never (afaik anyhow) sets READ or WRITE without also setting except at the pollflags level. but I think you're using a different transport, right? (i.e. using sockettransportservice, but not sockettransport..)

Comment 33

[Nils Ohlmeier [:drno]]

Once I'm back in the office I can try to add POLL_EXCEPT if we set READ or WRITE and see what happens. Although that still leaves the questions open how it can happen that in the IPv4 scenario something apparently sets POLL_EXCEPT, but does not seem to set it for IPv6.

The bigger more important question: do you think trying to investigate the POLL_EXCEPT differences makes sense, or what else would you suggest to find out why with IPv6 sockets poll() seems to return so much more often?

Comment 34

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

It'd be easy to find where POLL_EXCEPT is set for IPV4 using rr

Comment 35

[Nils Ohlmeier [:drno]]

So I added PR_POLL_EXCEPT to nICEr's READ and WRITE flags. As expected this results in all of the pollflags in the NSPR log to be mostly 5's and very few 7's. But CPU usage is still as high as before.

Comment 36

[Nils Ohlmeier [:drno]]

Added a line to the nICEr code which gets called if PR_POLL_EXCEPT gets set. Result: never enters that line in the debugger.

So I guess the whole PR_POLL_EXCEPT business is a red herring.

Any other ideas how to find out what is going wrong here?

Comment 37

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

We could run it under rr in v4 and v6 modes, and see if anything looks odd.  THat does warp a lot of things

Comment 38

[Nils Ohlmeier [:drno]]

I did get rr working after some fighting. But by the time my Ubuntu machine had collected several temporary IPv6 addresses again. I'll try to get a new log tomorrow with only a single or two IPv6 addresses, as I know that the amount of IPv6 addresses does not affect the problem.
What I can tell from playing a little bit around with the rr recording is that poll() basically returns super quickly (you can basically extract information already from the NSPR logs) claiming 40 sockets have updates, but when the NSPR poll loop iterates through the sockets it does not find a single socket in the 'ready' state.
I started working on modifying one of our unit tests to see if I can get it to reproduce the problem. Unfortunately it turns out that our nICEr socket tests don't use poll() at all. And our TransportService tests use local pipes. So it requires some hacking to get there...

Comment 39

[Nils Ohlmeier [:drno]]

These are the "returned after" numbers from the two NSPR logs:

     IPv4            IPv6
     #  ms           #  ms
   1458 0        199579 0
    348 1          2974 1
    334 2             5 2
    293 3             5 3
    227 4             5 4
    250 5             3 5
    105 6             3 6
     58 7             3 7
     48 8             3 8
     39 9             2 9
     46 10            1 10
     25 11
     25 12            3 12
     30 13            4 13
     35 14            3 14
     32 15
     49 16
     33 17            2 17
      9 18            1 18
      3 19
      1 20
      ...             ...
      1 9575          1 3892

Another evidence that the presence of IPv6 sockets results in lot less sleeping.

Comment 40

[Nils Ohlmeier [:drno]]

Apparently trying to connect to a IPv4 address from a IPv6 TCP socket results in a POLLHUP being generated. And our OnSocketReady() only pays attention to PR_POLL_READ and PR_POLL_WRITE, as these are the only two flags we set :-(

Comment 41

[Nils Ohlmeier [:drno]]

I'll test a patch I have created once I'm back in the office.

Comment 42

[Marco Castelluccio [:marco]]

I can test it if you attach the patch here (or even better send it to try).

Comment 43

[Patrick McManus [:mcmanus]]

(In reply to Nils Ohlmeier [:drno] from comment #40)
> Apparently trying to connect to a IPv4 address from a IPv6 TCP socket
> results in a POLLHUP being generated. And our OnSocketReady() only pays
> attention to PR_POLL_READ and PR_POLL_WRITE, as these are the only two flags
> we set :-(

this is a great find.. and this is the kind of thing I was thinking of when I said that some errors are unmaskable at the OS level...

Comment 44

[Nils Ohlmeier [:drno]]

Attachment: Catch socket errors and avoid 6 to 4 connection attempts

As mozreview is down right now here is the patch which fixes the problem. Is has two parts in it:
1) close sockets once NSPR tells us about any error on a socket (to avoid the busy loop we were trapped in)
2) don't try to connect a v6 socket to a v4 TURN TCP server (which caused the problem in the first problem)

Comment 45

[Maire Reavy [:mreavy]]

Thanks for digging into this, Nils.  At this point, it makes sense for you to (officially) take this over.

Comment 46

[Nils Ohlmeier [:drno]]

Attachment: MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

Review commit: https://reviewboard.mozilla.org/r/32917/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/32917/

Comment 47

[Nils Ohlmeier [:drno]]

Comment on attachment 8713946 [details]
MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/32917/diff/1-2/

Comment 48

[Nils Ohlmeier [:drno]]

Comment on attachment 8713946 [details]
MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/32917/diff/2-3/

Comment 49

[Nils Ohlmeier [:drno]]

Comment on attachment 8713946 [details]
MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/32917/diff/3-4/

Comment 50

[Nils Ohlmeier [:drno]]

Marco in case you want to double check my patch a try run is finally on its way: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1d38c10b6b0b

Comment 51

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

Comment on attachment 8713946 [details]
MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

https://reviewboard.mozilla.org/r/32917/#review29735

Comment 52

[Nils Ohlmeier [:drno]]

Looks like the patch is causing a almost perma orange on Linux debug builds. Need to investigate...

Comment 53

[Marco Castelluccio [:marco]]

I've tried the try build, it doesn't really make a difference for me.

Comment 54

[Nils Ohlmeier [:drno]]

(In reply to Marco Castelluccio [:marco] from comment #53)
> I've tried the try build, it doesn't really make a difference for me.

Quick question Marco: are you running things in e10s mode?
I just realized that tested everything only without e10s. Quite possible that it is still broken with e10s turned on.

Comment 55

[Marco Castelluccio [:marco]]

(In reply to Nils Ohlmeier [:drno] from comment #54)
> Quick question Marco: are you running things in e10s mode?
> I just realized that tested everything only without e10s. Quite possible
> that it is still broken with e10s turned on.

e10s was enabled, but I was using Firefox Hello (that only works in a non-e10s window).

Comment 56

[Nils Ohlmeier [:drno]]

I tried profiling a plain e10s call and don't see anything strange. For a Firefox Hello call CPU usage is higher then for a plain WebRTC A/V call. But the profiling of such a call just points to the screen sharing taking a lot of CPU.
I also double checked that for me the patch here drops the CPU usage in a Firefox Hello call from ~220% to ~140% (FYI a plain WebRTC A/V call is ~90% CPU).

If the problem is still not better with the patch applied I think we would now need a profile from your machine Marco, to get an idea where it's spending its CPU time.

Comment 57

[Marco Castelluccio [:marco]]

I attached a profile, I'll collect another one with your patch applied.
I'll test again with a plain A/V call with/without your patch.

Comment 58

[Nils Ohlmeier [:drno]]

Comment on attachment 8713946 [details]
MozReview Request: Bug 1224845: close sockets on errors and don't connect to IPv4 TURN TCP from IPv6 sockets. r=jesup

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/32917/diff/4-5/

Comment 59

[Nils Ohlmeier [:drno]]

Looks like the oranges were actually not caused by my patch. Lets see how a rebased try run will perform.

Comment 60

[Nils Ohlmeier [:drno]]

Try run looks good now. Let's land this as I'm 100% certain that this fixes real problems.

Marco if you are still experiencing problem with/after this fix, we can look at that in a new bug.

Comment 61

[Marco Castelluccio [:marco]]

(In reply to Nils Ohlmeier [:drno] from comment #60)
> Try run looks good now. Let's land this as I'm 100% certain that this fixes
> real problems.
> 
> Marco if you are still experiencing problem with/after this fix, we can look
> at that in a new bug.

I've tested again. CPU usage is still quite high, but the patch fixes the original regression.

Most of the time is still spent in poll: https://cleopatra.io/#report=f71a7c620f0cbd72ff6fabc15352bb1743d99aff

Comment 62

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ad2838be66f2

Comment 63

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/ad2838be66f2

Comment 64

[Marco Castelluccio [:marco]]

Should I file a new bug for the profile in comment 61 or is there nothing we can do?

Comment 65

[Nils Ohlmeier [:drno]]

Macro I filled bug 1245590 as a follow up to investigate if we can reduce the overhead from screen share. I think that is an appropriate bug to add your information to.