Open Bug 1085554 Opened 10 years ago Updated 2 years ago

Fennec logs nonstop messages about "IdleService: DailyCallback running"

Categories

(Core :: Widget, defect)

34 Branch
defect

Tracking

()

Tracking Status
firefox33 --- ?
firefox34 --- affected
firefox35 --- ?
firefox36 --- ?
fennec + ---

People

(Reporter: cpeterson, Unassigned)

References

Details

(Keywords: perf, Whiteboard: [Power:P1], tpi:-)

I see nonstop log messages about Fennec's IdleService rescheduling a "daily" timer. Note that the timers seem to be scheduled *earlier* every time!

I am running Fennec Beta 34. A few weeks ago, my phone started running out of battery every night or automatically resetting. Maybe this constant logging is related?



10-20 11:54:09.937: I/IdleService(500): DailyCallback running
10-20 11:54:09.937: I/IdleService(500): DailyCallback resetting timer to 5044805 msec
10-20 11:54:09.967: I/IdleService(500): DailyCallback running
10-20 11:54:09.967: I/IdleService(500): DailyCallback resetting timer to 5044776 msec
10-20 11:54:09.997: I/IdleService(500): DailyCallback running
10-20 11:54:09.997: I/IdleService(500): DailyCallback resetting timer to 5044752 msec
10-20 11:54:10.027: I/IdleService(500): DailyCallback running
10-20 11:54:10.027: I/IdleService(500): DailyCallback resetting timer to 5044716 msec
10-20 11:54:10.037: I/IdleService(500): DailyCallback running
10-20 11:54:10.037: I/IdleService(500): DailyCallback resetting timer to 5044698 msec
10-20 11:54:10.067: I/IdleService(500): DailyCallback running
10-20 11:54:10.067: I/IdleService(500): DailyCallback resetting timer to 5044663 msec
10-20 11:54:10.097: I/IdleService(500): DailyCallback running
10-20 11:54:10.097: I/IdleService(500): DailyCallback resetting timer to 5044638 msec
10-20 11:54:10.147: I/IdleService(500): DailyCallback running
10-20 11:54:10.147: I/IdleService(500): DailyCallback resetting timer to 5044591 msec
10-20 11:54:10.157: I/IdleService(500): DailyCallback running
10-20 11:54:10.157: I/IdleService(500): DailyCallback resetting timer to 5044574 msec
10-20 11:54:10.197: I/IdleService(500): DailyCallback running
10-20 11:54:10.197: I/IdleService(500): DailyCallback resetting timer to 5044540 msec
10-20 11:54:10.217: I/IdleService(500): DailyCallback running
10-20 11:54:10.217: I/IdleService(500): DailyCallback resetting timer to 5044515 msec
10-20 11:54:10.277: I/IdleService(500): DailyCallback running
10-20 11:54:10.277: I/IdleService(500): DailyCallback resetting timer to 5044454 msec
10-20 11:54:10.308: I/IdleService(500): DailyCallback running
10-20 11:54:10.308: I/IdleService(500): DailyCallback resetting timer to 5044426 msec
10-20 11:54:10.388: I/IdleService(500): DailyCallback running
10-20 11:54:10.388: I/IdleService(500): DailyCallback resetting timer to 5044344 msec
10-20 11:54:10.408: I/IdleService(500): DailyCallback running
10-20 11:54:10.408: I/IdleService(500): DailyCallback resetting timer to 5044326 msec
10-20 11:54:10.428: I/IdleService(500): DailyCallback running
10-20 11:54:10.428: I/IdleService(500): DailyCallback resetting timer to 5044302 msec
10-20 11:54:10.448: I/IdleService(500): DailyCallback running
10-20 11:54:10.448: I/IdleService(500): DailyCallback resetting timer to 5044283 msec
10-20 11:54:10.488: I/IdleService(500): DailyCallback running
10-20 11:54:10.488: I/IdleService(500): DailyCallback resetting timer to 5044250 msec
10-20 11:54:10.508: I/IdleService(500): DailyCallback running
10-20 11:54:10.508: I/IdleService(500): DailyCallback resetting timer to 5044228 msec
10-20 11:54:10.538: I/IdleService(500): DailyCallback running
10-20 11:54:10.538: I/IdleService(500): DailyCallback resetting timer to 5044199 msec
10-20 11:54:10.558: I/IdleService(500): DailyCallback running
10-20 11:54:10.558: I/IdleService(500): DailyCallback resetting timer to 5044173 msec
10-20 11:54:10.588: I/IdleService(500): DailyCallback running
10-20 11:54:10.588: I/IdleService(500): DailyCallback resetting timer to 5044149 msec
10-20 11:54:10.608: I/IdleService(500): DailyCallback running
10-20 11:54:10.608: I/IdleService(500): DailyCallback resetting timer to 5044131 msec
10-20 11:54:10.628: I/IdleService(500): DailyCallback running
10-20 11:54:10.628: I/IdleService(500): DailyCallback resetting timer to 5044103 msec
10-20 11:54:10.658: I/IdleService(500): DailyCallback running
10-20 11:54:10.658: I/IdleService(500): DailyCallback resetting timer to 5044077 msec
This is an nsIdleService bug, not a Fennec bug. To Core::Widget it goes!
Component: General → Widget
Product: Firefox for Android → Core
Version: Firefox 34 → 34 Branch
tracking-fennec: --- → ?
Those log messages were hard forced on in Fennec 2 years ago to detect when the behavior talked about in Bug 762620 happened. Back then some phones were effectively DDOSing our Telemetry services because of this misfiring.

Chris, I'd be very interested what phone and Android version you are running, and if you notice anything odd about the phone's clock etc!
Flags: needinfo?(cpeterson)
I'm not sure you'll be able to get a regression window for this, it's quite possible this bug might have been there forever. Please confirm it's actually a regression first.

Chris, are you able to produce the bug in a build with all logging on? Look in Bug 762620 to see what to turn on etc.
(In reply to Chris Peterson (:cpeterson) from comment #0)
> I see nonstop log messages about Fennec's IdleService rescheduling a "daily"
> timer. Note that the timers seem to be scheduled *earlier* every time!

That's expected, see the logic here:
https://bugzilla.mozilla.org/attachment.cgi?id=639402&action=diff

We're trying to set a timer for the next IdleDaily event, which we calculate as being 1.4 hours in the future. Yet, when we set that timer, it returns nearly instantly!

Before, we'd run IdleDaily (and DDOS the Telemetry servers trying to submit telemetry each time. The fixes in bug 762620 changed the logic to calculate the remaining time and reschedule the timer. Because it returns instantly each time (way before the programmer interval), we keep rescheduling with a slightly reduced duration.

The question is why the timer stops early.
I am running Firefox Beta 34 on a Nexus 4 running JB 4.3.1 (CyanogenMod 10.2.1). I don't see anything unusual about my phone's clock; the time is correct and it's set automatically by the network.

I will see if I can reproduce this again with logging.
I'll see if I can reproduce this on my stock N4
Flags: needinfo?(mark.finkle)
I haven't had time to debug this problem yet, but the "good news" is that I can still reproduce the problem.
A possible dupe with bug 1092623, where the user noticed Firefox would hang loading pages and start running hot.
The dupe was also on CyanogenMod, but we shouldn't jump to conclusions because the kind of people who can obtain the relevant log are probably correlated to the kind of users that runs Cyanogen.
Blocks: powah
Keywords: perf
I'm running a debug build of Fennec now, but I have not been able to reproduce the problem again yet.
Flags: needinfo?(cpeterson)
Chris, we have STR in bug 1092623 comment 6 - can you repro with these steps?
Flags: needinfo?(cpeterson)
I can't reproduce the IdleService messages with those STR.
Flags: needinfo?(cpeterson)
Chris, the following steps are reproducible on my device. Could you try?

1. Insert charging cable into device and plug it in.
2. Load news.google.com (other pages seem to do the same) into Android Firefox
3. Use power button to switch off screen

Result: Phone runs hot after 30-60 minutes, GeckoIdleService messages appear in logs.

With a different browser of without the charging cable, there are no problems.

(Samsung Galaxy S2, Cyanogenmod 10.1, Android 4.2.2, Firefox 36.0a1 nightly 2014-11-05)
Flags: needinfo?(cpeterson)
Thanks, Alex. Indeed, in comment 13, I had tested without the charging cable. I just tried with the charging cable and I was able to repro with a debug build. I will email my debug log to gcp.
Flags: needinfo?(cpeterson)
Incorrect wakelock assumptions, maybe?
Rule out a CM only problem?
tracking-fennec: ? → +
Flags: needinfo?(mark.finkle)
Whiteboard: [Power]
rnewman said the following on the dev-power list.

> There's some history there that implies this being seen in the wild (Bug 762620). It's also possible
> that this'll either (a) stop your device from charging because it's drawing too much current (which
> I've seen!), or (b) cause the horrific data usage that we've seen in Bug 1022569, if that IdleService
> callback ends up touching the network.
> 
> This seems like the loose end of a fairly serious thread, so I think this is important enough to at
> least move towards a diagnosis before retriaging. P1, IMO.
Whiteboard: [Power] → [Power:P1]
Whiteboard: [Power:P1] → [Power:P1], tpi:-
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.