Closed Bug 881404 Opened 11 years ago Closed 9 years ago

Intermittent dom/workers/test/test_closeOnGC.html on Android | Test timed out

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox24 --- disabled
firefox25 --- disabled
firefox26 --- disabled
firefox-esr31 --- fixed

People

(Reporter: RyanVM, Assigned: jonco)

References

Details

(Keywords: intermittent-failure) 

https://tbpl.mozilla.org/php/getParsedLog.php?id=23963155&tree=Mozilla-Inbound

4905 INFO TEST-START | /tests/dom/workers/test/test_closeOnGC.html
4906 INFO TEST-PASS | /tests/dom/workers/test/test_closeOnGC.html | undefined
4907 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_closeOnGC.html | Test timed out.
4908 INFO TEST-END | /tests/dom/workers/test/test_closeOnGC.html | finished in 348977ms

06-10 09:16:02.335 I/GeckoDump( 2204): 4905 INFO TEST-START | /tests/dom/workers/test/test_closeOnGC.html
06-10 09:16:02.593 I/IdleService( 2204): next timeout 1000 msec from now
06-10 09:16:02.593 I/IdleService( 2204): SetTimerExpiryIfBefore: next timeout 1000 msec from now
06-10 09:16:02.593 I/IdleService( 2204): reset timer expiry to 1010 msec from now
06-10 09:16:02.593 I/IdleService( 2204): Reset idle timeout: tell observer 6b473830 user is back
06-10 09:16:02.812 E/Profiler( 2204): BPUnw: [8 total] thread_register_for_profiling(me=0x1661de0, stacktop=0x701ffdd7)
06-10 09:16:02.976 I/GeckoDump( 2204): 4906 INFO TEST-PASS | /tests/dom/workers/test/test_closeOnGC.html | undefined
06-10 09:16:03.609 I/IdleService( 2204): Get idle time: time since reset 692 msec
06-10 09:16:03.609 I/IdleService( 2204): Idle timer callback: current idle time 692 msec
06-10 09:16:03.609 I/IdleService( 2204): next timeout 307 msec from now
06-10 09:16:03.609 I/IdleService( 2204): SetTimerExpiryIfBefore: next timeout 307 msec from now
06-10 09:16:03.609 I/IdleService( 2204): reset timer expiry to 317 msec from now
06-10 09:16:03.992 I/IdleService( 2204): Get idle time: time since reset 1075 msec
06-10 09:16:03.992 I/IdleService( 2204): Idle timer callback: current idle time 1075 msec
06-10 09:16:03.992 I/IdleService( 2204): next timeout 178924 msec from now
06-10 09:16:03.992 I/IdleService( 2204): SetTimerExpiryIfBefore: next timeout 178924 msec from now
06-10 09:16:03.992 I/IdleService( 2204): reset timer expiry to 178934 msec from now
06-10 09:16:03.992 I/IdleService( 2204): Idle timer callback: tell observer 6b473830 user is idle
06-10 09:16:15.984 E/Profiler( 2204): BPUnw: [7 total] thread_unregister_for_profiling(me=0x167f808) 
06-10 09:19:02.992 I/IdleService( 2204): Get idle time: time since reset 180081 msec
06-10 09:19:02.992 I/IdleService( 2204): Idle timer callback: current idle time 180081 msec
06-10 09:19:02.992 I/IdleService( 2204): next timeout 4294967114918 msec from now
06-10 09:19:02.992 I/IdleService( 2204): SetTimerExpiryIfBefore: next timeout 4294967114918 msec from now
06-10 09:19:02.992 I/IdleService( 2204): reset timer expiry to 4294967114928 msec from now
06-10 09:19:02.992 I/IdleService( 2204): Idle timer callback: tell observer 6b4dadd0 user is idle
06-10 09:19:02.992 I/IdleService( 2204): Notifying idle-daily observers
06-10 09:19:02.992 I/IdleService( 2204): Remove observer 6b4dadd0 (180 seconds), 1 remain idle
06-10 09:19:03.015 I/IdleService( 2204): Storing last idle time as 1370855943
06-10 09:21:49.101 I/GeckoDump( 2204): 4907 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_closeOnGC.html | Test timed out.
06-10 09:21:51.304 I/GeckoDump( 2204): 4908 INFO TEST-END | /tests/dom/workers/test/test_closeOnGC.html | finished in 348977ms
06-10 09:21:51.359 E/Profiler( 2204): BPUnw: [6 total] thread_unregister_for_profiling(me=0x1661de0)
this looks like a regression introduced yesterday, no history of it before, but a lot of failures since then.
(In reply to Joel Maher (:jmaher) from comment #18)
> this looks like a regression introduced yesterday, no history of it before,
> but a lot of failures since then.

Ben, do you have an idea what might have regressed this on 2013-06-10?
Flags: needinfo?(bent.mozilla)
this was introduced with :jandem's push: https://hg.mozilla.org/integration/mozilla-inbound/rev/1c4403cbda57 (at least it was the first push to exhibit the failure and be documented)
(In reply to Joel Maher (:jmaher) from comment #30)
> this was introduced with :jandem's push:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/1c4403cbda57 (at
> least it was the first push to exhibit the failure and be documented)

That change only affects the JS shell and is not part of the browser..
I believe I found the offending changeset:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&startdate=2013-06-07&enddate=2013-06-09&rev=4cecde6e32b0

see before/after view with this:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&startdate=2013-06-07&enddate=2013-06-09


To find the changeset, it required a lot of retriggers, probably too many over history, but it looks pretty obvious when you see it in the larger tbpl view:)

Jonco- this was a bug introduced on your changeset, if you cannot back this out, I assume you can own debugging and fixing this?  If you have questions about Android automation, I would be happy to help.
Flags: needinfo?(jcoppeard)
Assignee: general → jcoppeard
Flags: needinfo?(jcoppeard)
(In reply to Joel Maher (:jmaher) from comment #41)

No problem, I'll have a look.
A couple of these failures on here (comments 46 and 43) are for crashes on MacOS - this bug is for timeouts on Android, so we should be a different bug if these are happening regularly.

As for the timeout, the test is waiting for a worker to be destroyed after the last reference to it is set to null.  The problem is that we currently have a conservative garbage collector, so we don't actually guarantee that will happen.

Hopefully, when we move to exact rooting with the introduction of generational GC this will go away.
when are we planning on moving to generational GC/exact rooting?  Sounds like a logical approach.  Will that also help out on timeouts on osx since it appears we are starting to see that?
:jonco -- please reply to Comment 48.

This is one of the most frequent Android test failures (and adds an additional 3+ minutes to test run time, even on success!) -- we need to do something about this.
Flags: needinfo?(jcoppeard)
(In reply to Joel Maher (:jmaher) from comment #48)

Sorry I missed your question!

We're working on GGC at the moment, but it's going to be a couple of months at least before it lands.  I guess this has become more of an urgent problem now the frequency of failures has increased.

I don't like suggesting this, but would it be possible to disable this test on android for the time being?

The crashes on MacOS look like a different problem - I see bug 890841 is already open for that.
Flags: needinfo?(jcoppeard)
Summary: Intermittent dom/workers/test/test_closeOnGC.html | Test timed out → Intermittent dom/workers/test/test_closeOnGC.html on Android | Test timed out
(In reply to Jon Coppeard (:jonco) from comment #182)
> I don't like suggesting this, but would it be possible to disable this test
> on android for the time being?

Done :-)

https://hg.mozilla.org/integration/mozilla-inbound/rev/f8ce7dca775d
Whiteboard: [test disabled on Android][leave open]
Please file a followup to re-enable this!
Flags: needinfo?(bent.mozilla)
(In reply to ben turner [:bent] from comment #186)
> Please file a followup to re-enable this!

This bug will remain open (see whiteboard), so is the followup :-)
The test got re-enabled by the fix for bug 967614 so I'm closing this as fixed.
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
status-firefox-esr31: --- → fixed
Depends on: 967614
Whiteboard: [test disabled on Android][leave open]
Target Milestone: --- → mozilla33
You need to log in before you can comment on or make changes to this bug.