test_default_timeout() of test_threading.BarrierTests failure: BrokenBarrierError

[vstinner]

BPO	11871
Nosy	@db3l, @vstinner, @skrah, @native-api
Files	test_barrier_timeout.diff

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2011-04-18.21:59:03.506>
labels = ['3.8', '3.7', 'tests', '3.9']
title = 'test_default_timeout() of test_threading.BarrierTests failure: BrokenBarrierError'
updated_at = <Date 2022-02-04.10:23:01.964>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2022-02-04.10:23:01.964>
actor = 'vstinner'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Tests']
creation = <Date 2011-04-18.21:59:03.506>
creator = 'vstinner'
dependencies = []
files = ['22761']
hgrepos = []
issue_num = 11871
keywords = ['patch', 'needs review']
message_count = 15.0
messages = ['133995', '134583', '141124', '141241', '141263', '141270', '141274', '200564', '340889', '340949', '344118', '347533', '361753', '394791', '412502']
nosy_count = 6.0
nosy_names = ['db3l', 'vstinner', 'skrah', 'neologix', 'python-dev', 'Ivan.Pozdeev']
pr_nums = []
priority = 'normal'
resolution = None
stage = 'resolved'
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue11871'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[vstinner]

While trying to reproduce issue bpo-11870 using "gdb -args ./python Lib/test/regrtest.py -F -v --timeout=600 test_threading", I had the following error on Linux:
----------------------

test_default_timeout (test.test_threading.BarrierTests) ... [Thread 0x7ffff1acf700 (LWP 27178) exited]
[New Thread 0x7ffff1acf700 (LWP 27181)]
[New Thread 0x7ffff12ce700 (LWP 27182)]
[New Thread 0x7ffff3c99700 (LWP 27183)]
[New Thread 0x7ffff325a700 (LWP 27184)]
Unhandled exception in thread started by <function task at 0x1302340>
Unhandled exception in thread started by <function task at 0x1302340>
Unhandled exception in thread started by <function task at 0x1302340>
Traceback (most recent call last):
Unhandled exception in thread started by <function task at 0x1302340>
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 37, in task
Traceback (most recent call last):
Traceback (most recent call last):
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 37, in task
Traceback (most recent call last):
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 37, in task
    f()
    f()
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 37, in task
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 838, in f
ERROR
----------------------

---

ERROR: test_default_timeout (test.test_threading.BarrierTests)

Traceback (most recent call last):
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 843, in test_default_timeout
    self.run_threads(f)
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 672, in run_threads
    f()
  File "/home/haypo/prog/HG/cpython/Lib/test/lock_tests.py", line 838, in f
    i = barrier.wait()
  File "/home/haypo/prog/HG/cpython/Lib/threading.py", line 472, in wait
    self._enter() # Block while the barrier drains.
  File "/home/haypo/prog/HG/cpython/Lib/threading.py", line 496, in _enter
    raise BrokenBarrierError
threading.BrokenBarrierError

---

The error occured on:

• Ubuntu 10.04
• Python 3.3 (2127df2c972e)
• Intel(R) Core(TM)2 Quad CPU Q9300 @ 2.50GHz
• 4 GB of memory

[neologix]

The most obvious explanation for that failure is that the barrier's timeout is too low.

   def test_default_timeout(self):
       """
       Test the barrier's default timeout
       """
       #create a barrier with a low default timeout
       barrier = self.barriertype(self.N, timeout=0.1)

If the last thread waits on the barrier more than 0.1s after the first thread, then you'll get a BrokenBarrierError.
A 0.1s delay is not that much, 100ms was the default quantum with Linux O(1) scheduler...

[neologix]

The attached patch bumps the barrier's default timeout to 300ms: it should be more than enough (unless you got a really crappy scheduler, or a really heavily loaded machine), especially since this problem doesn't seem to occur often (AFAICT).

[neologix]

Victor, can I commit it?

[vstinner]

YES YOU CAN

[python-dev]

New changeset aa9c0fdf2143 by Charles-François Natali in branch '3.2':
Issue bpo-11871: In test_threading.BarrierTests, bump the default barrier timeout
http://hg.python.org/cpython/rev/aa9c0fdf2143

New changeset e8da570d29a8 by Charles-François Natali in branch 'default':
Issue bpo-11871: In test_threading.BarrierTests, bump the default barrier timeout
http://hg.python.org/cpython/rev/e8da570d29a8

[neologix]

YES YOU CAN

:-)

[skrah]

It looks like it happened again:

http://buildbot.python.org/all/builders/x86%20Gentoo%20Non-Debug%203.x/builds/5223/steps/test/logs/stdio

======================================================================
ERROR: test_default_timeout (test.test_threading.BarrierTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/test/lock_tests.py", line 876, in test_default_timeout
    self.run_threads(f)
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/test/lock_tests.py", line 705, in run_threads
    f()
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/test/lock_tests.py", line 871, in f
    i = barrier.wait()
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/threading.py", line 616, in wait
    self._wait(timeout)
  File "/var/lib/buildslave/3.x.murray-gentoo-wide/build/Lib/threading.py", line 654, in _wait
    raise BrokenBarrierError
threading.BrokenBarrierError

---

Ran 138 tests in 22.880s

[vstinner]

The test still fails randomly:
https://buildbot.python.org/all/#/builders/3/builds/2469

[db3l]

I should mention that a high level of test parallelism on the part of my worker might have be a contributing factor in this most recent case.

The worker was recently upgraded to a faster 4-core VM, but with limited I/O. In a test run the test processes invariably end up stuck on I/O heavy tests, idling the CPUs.

So I've been running the tests under -j8, as I found it the most effective combination of supporting tests stuck on I/O while keeping the CPUs busy, but it does mean that in some cases there's a lot pending on the CPUs, and depending on the exact test ordering in a run presumably some more sensitive tests could be impacted.

I have in fact seen an increase in random tests generating warnings (fail, then pass) than the worker had previously. I suspect the benefits of the extra parallelism on total test time (-j8 is about 20% faster than -j4) probably isn't valuable enough and will most likely be reducing it a bit.

[native-api]

Got this issue today in AppVeyor's PR check: https://ci.appveyor.com/project/python/cpython/builds/24945165, so it's not local to David's worker.
(At rerun, the test succeeeded, so the check status was not affected.)