1565769 - 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

Status: RESOLVED FIXED

(Testing :: GTest, defect, P5)

Description

[Treeherder Bug Filer]

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

Comment 3

[Intermittent Failures Robot]

11 failures in 4710 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• mozilla-central: 2
• mozilla-inbound: 2
• try: 2

Platform breakdown:

• macosx1014-64-shippable: 5
• macosx1014-64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1565769&startday=2019-07-08&endday=2019-07-14&tree=all

Comment 4

[Edwin Takahashi (:egao | infrequent contributor)]

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.,

Comment 5

[Andrew McCreight [:mccr8]]

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

Comment 6

[Kris Wright :KrisWright]

(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.

Comment 7

[Kris Wright :KrisWright]

Attachment: Bug 1565769 - Give threads an additional 50 ms to finish up in ShutdownWithTimeout tests

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.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1f39f18907d8
Give threads an additional 50 ms to finish up in ShutdownWithTimeout tests r=erahm

Comment 10

[Edwin Takahashi (:egao | infrequent contributor)]

Thanks for pushing a fix :kriswright!

Comment 11

[Oana Pop-Rus]

https://hg.mozilla.org/mozilla-central/rev/1f39f18907d8

Comment 12

[Intermittent Failures Robot]

16 failures in 4298 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-inbound: 1
• try: 4
• mozilla-central: 2

Platform breakdown:

• macosx1014-64-shippable: 4
• macosx1014-64: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1565769&startday=2019-07-15&endday=2019-07-21&tree=all