1285459 - Firefox Nightly "burning CPU" on MacOS Sierra

Status: RESOLVED DUPLICATE of bug 1284677

(Firefox :: Untriaged, defect)

Description

[Matthew Bowker]

Firefox Nightly is being reported as "burning CPU" on MacOS Sierra Public Beta 1.  Console.app reports the following condition (These log entries are from two separate launches):

> Default	23:08:39.884154 -0600	kernel	process firefox[1044] thread 25978 caught burning CPU! It used more than 50% CPU over 180 seconds (actual recent usage: 98% over ~91 seconds).  Thread lifetime cpu usage 90.011498s, (29.763116 user, 60.248382 sys) ledger balance: 90001157591 mabs credit: 90003666996 mabs debit: 2509405 mabs limit: 90000000000 mabs period: 180000000000 ns last refill: 91331873143 ns.
> Default	23:08:39.558918 -0600	symptomsd	Received <decode failure invalid type 0 for %s>CPU usage trigger: 
>  firefox[1044] () used 90.00s of CPU over 91.33 seconds (averaging 98%), violating a CPU usage limit of 90.00s over 180 seconds.
> Default	23:08:39.795639 -0600	symptomsd	  Found DiagUsageStats for RESOURCE_NOTIFY of EXC_CPU_USAGE : NON-FATAL (firefox) - <DiagnosticCaseUsage: 0x7fc411f32920> (entity: DiagnosticCaseUsage; id: 0x4000cb <x-coredata://3A41F08F-4747-40F5-A8F5-0F3D11789C2B/DiagnosticCaseUsage/p1> ; data: >{
>    casesAccepted = 2;
>    casesSeen = 2;
>    domain = "RESOURCE_NOTIFY";
>    "interarrival_mean" = "2176.970037996769";
>    "interarrival_var" = 0;
>    lastAccepted = "2016-07-08 04:47:13 +0000";
>    lastSeen = "2016-07-08 04:47:13 +0000";
>    process = firefox;
>    subtype = "NON-FATAL";
>    type = "EXC_CPU_USAGE";
>})
>Default	23:08:39.795823 -0600	symptomsd	  2 reports for firefox is still under the limit of 5. Allowing report.
> Default	23:08:39.797492 -0600	symptomsd	Updating RESOURCE_NOTIFY report statistics for RESOURCE_NOTIFY : EXC_CPU_USAGE : NON-FATAL : firefox
> Default	23:08:39.798170 -0600	symptomsd	Updating DiagCaseUsage: <DiagnosticCaseUsage: 0x7fc411f32920> (entity: DiagnosticCaseUsage; id: 0x4000cb <x-coredata://3A41F08F-4747-40F5-A8F5-0F3D11789C2B/DiagnosticCaseUsage/p1> ; >data: {
>    casesAccepted = 2;
>    casesSeen = 2;
>    domain = "RESOURCE_NOTIFY";
>    "interarrival_mean" = "2176.970037996769";
>    "interarrival_var" = 0;
>    lastAccepted = "2016-07-08 04:47:13 +0000";
>    lastSeen = "2016-07-08 04:47:13 +0000";
>    process = firefox;
>    subtype = "NON-FATAL";
>    type = "EXC_CPU_USAGE";
>})
> Default	23:13:05.522264 -0600	kernel	process firefox[1144] thread 31571 caught burning CPU! It used more than 50% CPU over 180 seconds (actual recent usage: 99% over ~90 seconds).  Thread lifetime cpu usage 90.023716s, (30.075704 user, 59.948012 sys) ledger balance: 90012887404 mabs credit: 90015829376 mabs debit: 2941972 mabs limit: 90000000000 mabs period: 180000000000 ns last refill: 90466947112 ns.
> Default	23:13:05.146030 -0600	symptomsd	Received <decode failure invalid type 0 for %s>CPU usage trigger: 
>   firefox[1144] () used 90.01s of CPU over 90.47 seconds (averaging 99%), violating a CPU usage limit of 90.00s over 180 seconds.
> Default	23:13:05.308630 -0600	symptomsd	  Found DiagUsageStats for RESOURCE_NOTIFY of EXC_CPU_USAGE : NON-FATAL (firefox) - <DiagnosticCaseUsage: 0x7fc411f32920> (entity: DiagnosticCaseUsage; id: 0x4000cb <x-coredata://3A41F08F-4747-40F5-A8F5-0F3D11789C2B/DiagnosticCaseUsage/p1> ; data: >{
>    casesAccepted = 3;
>    casesSeen = 3;
>    domain = "RESOURCE_NOTIFY";
>    "interarrival_mean" = "1731.74432900548";
>    "interarrival_var" = "396451.8638935921";
>    lastAccepted = "2016-07-08 05:08:40 +0000";
>    lastSeen = "2016-07-08 05:08:40 +0000";
>    process = firefox;
>    subtype = "NON-FATAL";
>    type = "EXC_CPU_USAGE";
>})
>Default	23:13:05.308718 -0600	symptomsd	  Generated RESOURCE_NOTIFY report for firefox within the past 300 seconds (1467954520.1660). Disallow report.

Firefox Nightly becomes unresponsive and does not start after this output.

Comment 1

[:Gijs (he/him)]

Under what circumstances does this happen? Startup? Sometime after? Does the same thing happen with release versions of Firefox, or if you start nightly with a clean profile?

Comment 2

[Matthew Bowker]

Startup, before the profile switcher.  It does not occur on the latest stable firefox (47.0.1).  Clean profile does not affect it.

Comment 3

[:Gijs (he/him)]

(In reply to Matthew Bowker from comment #2)
> Startup, before the profile switcher.  It does not occur on the latest
> stable firefox (47.0.1).  Clean profile does not affect it.

Well, if you start up from the commandline and point to a specific profile with the -P or --profile switch, does that produce the same issue?

I'm a bit surprised that this basically seems to imply we spent 90 seconds to just show the profile dialog. Is that actually the case? Can you repeatedly reproduce this against a fresh copy of nightly (given comment #0 says you now can't start it) ?

Comment 4

[Markus Stange [:mstange]]

If you're saying that Nightly doesn't start at all, not even the profile manager (it's not clear to me whether that's what you're saying), then this may be bug 1284677. I know that you said you're on Beta 1, so that's a little confusing since I've only seen bug 1284677 on Beta 2, but maybe it's still caused by the same issue. Bug 1284677 certainly causes us to burn lots of CPU because we're stuck in a loop.

Comment 5

[Matthew Bowker]

(In reply to :Gijs Kruitbosch from comment #3)
> (In reply to Matthew Bowker from comment #2)
> > Startup, before the profile switcher.  It does not occur on the latest
> > stable firefox (47.0.1).  Clean profile does not affect it.
> 
> Well, if you start up from the commandline and point to a specific profile
> with the -P or --profile switch, does that produce the same issue?
> 
> I'm a bit surprised that this basically seems to imply we spent 90 seconds
> to just show the profile dialog. Is that actually the case? Can you
> repeatedly reproduce this against a fresh copy of nightly (given comment #0
> says you now can't start it) ?

I received the following when I tried to launch Nightly from the command line: 
> Traveler-2:~ Matthew$ /Applications/FirefoxNightly.app/Contents/MacOS/firefox -P
> firefox(3692,0x7fffc5a353c0) malloc: *** malloc_zone_unregister() failed for 0x7fffc5a2c548

(In reply to Markus Stange [:mstange] from comment #4)
> If you're saying that Nightly doesn't start at all, not even the profile
> manager (it's not clear to me whether that's what you're saying), then this
> may be bug 1284677. I know that you said you're on Beta 1, so that's a
> little confusing since I've only seen bug 1284677 on Beta 2, but maybe it's
> still caused by the same issue. Bug 1284677 certainly causes us to burn lots
> of CPU because we're stuck in a loop.

The output from above does seem to indicate the bug.  Note, I am on Public Beta 1, which is different than  the developer beta (I know it's confusing...)

Comment 6

[Markus Stange [:mstange]]

Ah, I see. I didn't know about the different Beta channels. Then yes, I think this is just bug 1284677.