Closed Bug 1565769 Opened 2 months ago Closed 2 months ago

Intermittent ThreadPool.ShutdownWithTimeout | ThreadPool.ShutdownWithTimeoutThenSleep | Expected equality of these values: | Expected: (count) >= (3), actual: 2 vs 3 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:203

Categories

(Testing :: GTest, defect, P5)

Version 3
defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 unaffected, firefox68 unaffected, firefox69 unaffected, firefox70 fixed)

RESOLVED FIXED
mozilla70
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 --- unaffected
firefox70 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: KrisWright)

References

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=256322153&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/R-fnjbLASVKQgANBwhBUvw/runs/0/artifacts/public/logs/live_backing.log


04:35:08 INFO - TEST-PASS | ThreadPool.Parallelism | test completed (time: 2004ms)
04:35:08 INFO - TEST-START | ThreadPool.ShutdownWithTimeout
04:35:08 INFO - ###(0) running from thread: 0x10d43faa0
04:35:08 INFO - ###(1) running from thread: 0x10d43fbd0
04:35:08 INFO - ###(2) running from thread: 0x10d43fd00
04:35:08 INFO - ###(3) running from thread: 0x10d43fe30
04:35:08 INFO - ###(2) exiting from thread: 0x10d43fd00
04:35:08 INFO - ###(1) exiting from thread: 0x10d43fbd0
04:35:08 INFO - ###(3) exiting from thread: 0x10d43fe30
04:35:09 WARNING - TEST-UNEXPECTED-FAIL | ThreadPool.ShutdownWithTimeout | Expected equality of these values:
04:35:09 INFO - allThreadsCount
04:35:09 INFO - Which is: 3
04:35:09 INFO - 4 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:139
04:35:09 INFO - ###(0) running from thread: 0x10d43fbd0
04:35:09 INFO - ###(1) running from thread: 0x10d43fd00
04:35:09 INFO - ###(2) running from thread: 0x10d43fe30
04:35:09 INFO - ### running from thread that never ends: 0x10d43ff60
04:35:09 INFO - ###(0) exiting from thread: 0x10d43faa0
04:35:09 INFO - ###(0) exiting from thread: 0x10d43fbd0
04:35:09 INFO - ###(2) exiting from thread: 0x10d43fe30
04:35:09 INFO - ###(1) exiting from thread: 0x10d43fd00
04:35:10 WARNING - TEST-UNEXPECTED-FAIL | ThreadPool.ShutdownWithTimeout | test completed (time: 1470ms)
04:35:10 INFO - TEST-START | ThreadPool.ShutdownWithTimeoutThenSleep
04:35:10 INFO - ###(0) running from thread: 0x10d43faa0
04:35:10 INFO - ###(1) running from thread: 0x10d43fbd0
04:35:10 INFO - ###(2) running from thread: 0x10d43fd00
04:35:10 INFO - ### running from thread that sleeps for 400ms: 0x10d43fe30
04:35:10 INFO - ###(0) exiting from thread: 0x10d43faa0
04:35:10 INFO - ###(2) exiting from thread: 0x10d43fd00
04:35:10 WARNING - TEST-UNEXPECTED-FAIL | ThreadPool.ShutdownWithTimeoutThenSleep | Expected: (count) >= (3), actual: 2 vs 3 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:203
04:35:10 INFO - ###(1) exiting from thread: 0x10d43fbd0
04:35:10 INFO - ### thread awoke from long sleep: 0x10d43fe30
04:35:10 WARNING - TEST-UNEXPECTED-FAIL | ThreadPool.ShutdownWithTimeoutThenSleep | test completed (time: 512ms)
04:35:10 INFO - TEST-START | ThreadPoolListener.Test

Summary: Intermittent ThreadPool.ShutdownWithTimeout | Expected equality of these values: → Intermittent ThreadPool.ShutdownWithTimeout | Expected equality of these values: | Expected: (count) >= (3), actual: 2 vs 3 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:203
See Also: → 1561410
Duplicate of this bug: 1565806
Summary: Intermittent ThreadPool.ShutdownWithTimeout | Expected equality of these values: | Expected: (count) >= (3), actual: 2 vs 3 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:203 → Intermittent ThreadPool.ShutdownWithTimeout | ThreadPool.ShutdownWithTimeoutThenSleep | Expected equality of these values: | Expected: (count) >= (3), actual: 2 vs 3 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestThreadPool.cpp:203
Duplicate of this bug: 1565813

Seems like the failure is happening much less this past weekend. I could try looking into the patch, but it seems way over my head to be honest.,

Kris, maybe you could take a look at this while Nathan is away, as you reviewed bug 1561410?

Flags: needinfo?(kwright)

(In reply to Andrew McCreight [:mccr8] from comment #5)

Kris, maybe you could take a look at this while Nathan is away, as you reviewed bug 1561410?

This looks like another timer issue on the 1014 machines (bug 1561959). In lots of similar cases jobs are taking longer than expected to run, which is a little weird and concerning. Threads are supposed to shut down at 300ms with ShutdownWithTimeout, but occasionally one or two is lagging behind. Previous problems with timers on the 1014 try hardware (and the fact that I can't seem to get this to repro locally unless I flat out break the timers in pr_sleep) indicate that this is probably the same issue here. I may just need to tweak the timeout boundaries by which the threadpool calls ShutdownWithTimeout to account for threads that sleep for longer than expected. I'll try a few runs with some timer output to see if that's where our problem lies.

Flags: needinfo?(kwright)

Gtest jobs on the osx1014 try hardware are taking longer than anticipated to finish up, and ThreadPool.ShutdownWithTimeout tests need to wait an extra 50ms to let all threads finish on time. On the long term, when the underlying issue is fixed thread timeouts will need to be readjusted back to 300ms.

Pushed by kwright@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1f39f18907d8
Give threads an additional 50 ms to finish up in ShutdownWithTimeout tests r=erahm

Thanks for pushing a fix :kriswright!

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla70
Assignee: nobody → kwright
You need to log in before you can comment on or make changes to this bug.