Closed Bug 922919 Opened 11 years ago Closed 11 years ago

Intermittent test_BackgroundLRU.html | Test timed out.

Categories

(Firefox OS Graveyard :: General, defect)

Product:
Firefox OS Graveyard
Component:
General
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox27 fixed, firefox28 fixed, firefox-esr24 unaffected, b2g-v1.2 unaffected)

Status:
RESOLVED FIXED
Milestone:
1.3 Sprint 5 - 11/22
Tracking Flags:
Tracking Status
firefox27 --- fixed
firefox28 --- fixed
firefox-esr24 --- unaffected
b2g-v1.2 --- unaffected

People

(Reporter: KWierso, Assigned: alan.yenlin.huang)

References

Details

(Keywords: intermittent-failure)

Attachments

(5 files, 1 obsolete file)

Print out some log when doing process priority tests.
2.05 KB, patch
khuey
: review+
Details | Diff | Splinter Review
Set three preference in one asynchronous call to fix timing bug
2.02 KB, patch
khuey
: review+
Details | Diff | Splinter Review
Remove unnecessary FireTestOnlyObserverNotification calls
1.23 KB, patch
khuey
: review+
Details | Diff | Splinter Review
Backed out changeset 21b77163bf9f, which we intended to add debugging log, part 1.
963 bytes, patch
khuey
: review+
Details | Diff | Splinter Review
Backed out changeset ebcfdf7200db, which we intended to add debugging log, part 2.
2.02 KB, patch
khuey
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=28637251&tree=Fx-Team
using slave: tst-linux64-ec2-361



Not sure what to make of this. The log and the screenshot appear to be corrupted.
The funky log is unrelated, bug 921676.
Summary: Intermittent ASAN TEST-UNEXPECTED-FAIL | test_BackgroundLRU.html | Test timed out. → Intermittent test_BackgroundLRU.html | Test timed out.
Blocks: 822325
As test author, please can you take a look at the top intermittent failure? :-)
Flags: needinfo?(ahuang)
Assignee: nobody → ahuang
Flags: needinfo?(ahuang)
Hi Kyle,
I would like to add some information to see what cases I missed here. Can you help to review this? These info are enclosed and show only when "dom.ipc.processPriorityManager.testMode" is set. So I think it's won't affect the others. Thanks.
Attachment #828402 - Flags: review?(khuey)
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #155)
> Why not just uncomment
> http://mxr.mozilla.org/mozilla-central/source/dom/ipc/ProcessPriorityManager.
> cpp#46 ?

Yup, that's good. I was worried about this may dump massive logs, so I added one enclosed by testMode preference. But I did a a test just then, it seems uncomment http://mxr.mozilla.org/mozilla-central/source/dom/ipc/ProcessPriorityManager.cpp#46 won't cause that so much log. I will revise my patch, thanks.
Flags: needinfo?(ahuang)
uncomment http://mxr.mozilla.org/mozilla-central/source/dom/ipc/ProcessPriorityManager.cpp#46 and dump info in browserElementTestHelpers.js
Attachment #828402 - Attachment is obsolete: true
Attachment #828402 - Flags: review?(khuey)
Attachment #828431 - Flags: review?(khuey)
Attachment #828431 - Attachment description: bug-922919-log.patch → Print out some log when doing process priority tests.
Comment on attachment 828431 [details] [diff] [review]
Print out some log when doing process priority tests.

Review of attachment 828431 [details] [diff] [review]:
-----------------------------------------------------------------

r=me
Attachment #828431 - Flags: review?(khuey) → review+
I pushed a followup to disable this on 64 bit builds because apparently gcc doesn't like the logging code's printf modifiers.

https://hg.mozilla.org/integration/mozilla-inbound/rev/21b77163bf9f
(In reply to TBPL Robot from comment #161)
> Tomcat
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30265578&tree=Mozilla-
> Inbound
> Ubuntu VM 12.04 mozilla-inbound opt test mochitest-2 on 2013-11-07 03:19:18
> revision: e6e339fbf953
> slave: tst-linux32-ec2-034
> 
> 2405 ERROR TEST-UNEXPECTED-FAIL |
> /tests/dom/browser-element/mochitest/priority/test_BackgroundLRU.html | Test
> timed out.

03:24:52     INFO -  ProcessPriorityManager - Making background LRU pool with size(1)

Ah, this is really weird. It seems http://hg.mozilla.org/mozilla-central/file/70f21fad60a4/dom/ipc/ProcessPriorityManager.cpp#l1229 failed, so mLRUPoolLevels is 1.

But we did set this preference in http://hg.mozilla.org/mozilla-central/file/70f21fad60a4/dom/browser-element/mochitest/browserElementTestHelpers.js#l46 so mLRUPoolLevels is 2. 
2 << 1 - 1 = 3, so normally in the test log, I see 
INFO -  ProcessPriorityManager - Making background LRU pool with size(3)

http://hg.mozilla.org/mozilla-central/file/70f21fad60a4/dom/browser-element/mochitest/browserElementTestHelpers.js#l46 must be called, otherwise dom.ipc.processPriorityManager.testMode won't set true. We won't even start test mode.

No idea yet ...
(In reply to TBPL Robot from comment #168)
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30337420&tree=Mozilla-
> Inbound

(In reply to TBPL Robot from comment #170)
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30346129&tree=Mozilla-
> Central

(In reply to TBPL Robot from comment #173)
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30364569&tree=B2g-Inbound

09:41:56     INFO -  ProcessPriorityManager - Making background LRU pool with size(1)

So, it seems all these are the same case.
No longer blocks: 822325
Depends on: 822325
http://hg.mozilla.org/mozilla-central/file/16949049f03d/dom/browser-element/mochitest/browserElementTestHelpers.js#l46

We should set above three preference in one synchronized call, instead of three. Maybe there are other corner cases, but I don't see them right now. I'm trying to fix this first.
(In reply to Alan Huang [:ahuang] from comment #178)
> http://hg.mozilla.org/mozilla-central/file/16949049f03d/dom/browser-element/
> mochitest/browserElementTestHelpers.js#l46
> 
> We should set above three preference in one synchronized call, instead of
> three. Maybe there are other corner cases, but I don't see them right now.
> I'm trying to fix this first.

Fix typo, "set above three preference in one asynchronous call"
Hi Kyle,
Can you help to take a look at this patch? I think this can fix the cases I saw.
Attachment #830583 - Flags: review?(khuey)
Comment on attachment 830583 [details] [diff] [review]
Set three preference in one asynchronous call to fix timing bug

Review of attachment 830583 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not sure that this will work but I guess it doesn't hurt to try.
Attachment #830583 - Flags: review?(khuey) → review+
Keywords: checkin-needed
50 runs on each Linux platform without any failures looks promising :)

https://hg.mozilla.org/integration/b2g-inbound/rev/200d1941898e
Keywords: checkin-needed
Whiteboard: [leave open]
https://hg.mozilla.org/mozilla-central/rev/200d1941898e
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Wait more days to see whether this still happens.

If https://hg.mozilla.org/mozilla-central/rev/200d1941898e fixes this,
I will back out below two commits which are for adding log:
https://hg.mozilla.org/mozilla-central/rev/ebcfdf7200db
https://hg.mozilla.org/mozilla-central/rev/21b77163bf9f
(In reply to Alan Huang [:ahuang] from comment #191)
> Wait more days to see whether this still happens.

(In reply to TBPL Robot from comment #192)
> philor
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30586017&tree=Fx-Team
https://hg.mozilla.org/integration/fx-team/pushloghtml?startID=3482&endID=3483

Obviously, this still happens ... :(
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(In reply to TBPL Robot from comment #192)
> philor
> https://tbpl.mozilla.org/php/getParsedLog.php?id=30586017&tree=Fx-Team
> Ubuntu VM 12.04 x64 fx-team debug test mochitest-2 on 2013-11-14 20:56:30
> revision: b2fab608772f
> slave: tst-linux64-ec2-373

Unfortunately, this is a x64 platform which lacks our log. :(
I think I figure out another failure root cause.

21:03:52     INFO -  browserElementTestHelpers got notify: topic process-priority-manager:TEST-ONLY:process-priority-with-background-LRU-set, data 4:BACKGROUND:CPU_NORMAL:0
21:03:52     INFO -  id(4) != childID(3)

I shouldn't let the one who didn't actually set and LRU value (default is 0) send out notification to observer.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/ebe2d9a86870
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → 1.3 Sprint 5 - 11/22
Lets leave this open for a bit.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #210)
> Lets leave this open for a bit.

Good call :)
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #217)
> (In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #210)
> > Lets leave this open for a bit.
> 
> Good call :)

Yup ...

I now find out the latest case shows another bug. This only affects the test case and won't affect our function in 822325. I'm now fixing it :)


12:47:22     INFO -  ProcessPriorityManager - Making background LRU pool with size(1)
12:47:22     INFO -  ProcessPriorityManager[child-id=1, pid=-1] - Destroying ParticularProcessPriorityManager.

Previous test case is trying to destroy a pppm, then triggers ppm to construct a LRU pool!
That's a bug I never considered. I will take this to bug 822325 and fix this there.
Alan, please file a new bug to fix this issue.
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #219)
> Alan, please file a new bug to fix this issue.
I see, okay :)
Depends on: 942040
The last few comments are not related.  It doesn't look like we've seen this on central since bug 942040 landed.  Great job Alan!
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #260)
> The last few comments are not related.  It doesn't look like we've seen this
> on central since bug 942040 landed.  Great job Alan!

Ugh, yeah, sorry about that. Something was pushed that made a bunch of stuff timeout, including backgroundLRU.html, and I accidentally starred them as this before I realized that it was unrelated.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/54530ab9a190

Do we care about landing this on Aurora/Beta as well or can it stay as-is?
It's test only logging, leaving it there won't hurt anything.
Actually, no, I take that back.  We should revert the changes to ProcessPriorityManager.cpp at least.
Whiteboard: [checkin-needed-aurora][checkin-needed-beta]
https://hg.mozilla.org/releases/mozilla-aurora/rev/cf74f3212bc8

The logging patches never hit Fx27, so yay.
Whiteboard: [checkin-needed-aurora][checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: