test_multiprocessing hangs intermittently on POSIX platforms

[warsaw]

BPO	3088
Nosy	@gvanrossum, @warsaw, @amauryfa, @tebeka, @mdickinson, @ncoghlan, @benjaminp
Dependencies	bpo-874900: threading module can deadlock after fork
Files	test_get.output test_multiprocessing_reduced.diff threadlocal.patch traceback.txt: Traceback from test_multiprocessing crash traceback2.txt: A second traceback multithread_traceback.txt: Traceback showing all threads

^{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 = <Date 2008-07-17.17:41:47.256>
created_at = <Date 2008-06-12.04:48:42.642>
labels = ['library', 'release-blocker']
title = 'test_multiprocessing hangs intermittently on POSIX platforms'
updated_at = <Date 2008-07-18.14:43:00.357>
user = 'https://github.com/warsaw'

bugs.python.org fields:

activity = <Date 2008-07-18.14:43:00.357>
actor = 'tebeka'
assignee = 'jnoller'
closed = True
closed_date = <Date 2008-07-17.17:41:47.256>
closer = 'jnoller'
components = ['Library (Lib)']
creation = <Date 2008-06-12.04:48:42.642>
creator = 'barry'
dependencies = ['874900']
files = ['10604', '10633', '10766', '10795', '10796', '10800']
hgrepos = []
issue_num = 3088
keywords = ['patch']
message_count = 73.0
messages = ['68053', '68055', '68059', '68062', '68063', '68064', '68065', '68066', '68067', '68068', '68072', '68077', '68136', '68150', '68153', '68198', '68209', '68237', '68240', '68295', '68384', '68466', '68467', '68485', '68856', '68877', '68929', '69025', '69026', '69106', '69108', '69109', '69110', '69119', '69120', '69121', '69122', '69123', '69124', '69125', '69127', '69128', '69130', '69131', '69133', '69138', '69142', '69149', '69151', '69154', '69155', '69156', '69158', '69159', '69160', '69181', '69182', '69185', '69188', '69414', '69424', '69425', '69431', '69433', '69434', '69435', '69737', '69738', '69740', '69747', '69754', '69895', '69955']
nosy_count = 12.0
nosy_names = ['gvanrossum', 'barry', 'amaury.forgeotdarc', 'tebeka', 'mark.dickinson', 'ncoghlan', 'Rhamphoryncus', 'donmez', 'paulmelis', 'roudkerk', 'benjamin.peterson', 'jnoller']
pr_nums = []
priority = 'release blocker'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue3088'
versions = ['Python 2.6', 'Python 3.0']

[warsaw]

For me, test_multiprocessing hangs consistently on OS X 10.5.3. It
passes just fine on Ubuntu 8.04.

[donmez]

I can confirm this on Leopard too.

[benjaminp]

It passes for me on Leopard. Can you post the test running in verbose
mode so we can see where it hangs?

[jnoller]

On python-3000 trunk, _multiprocessing doesn't even compile:

/Users/jesse/open_source/subversion/python-
3000/Modules/_multiprocessing/semaphore.c: In function ‘semlock_iszero’:
/Users/jesse/open_source/subversion/python-
3000/Modules/_multiprocessing/semaphore.c:515: warning: unused variable
‘sval’

[warsaw]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Jun 12, 2008, at 9:02 AM, Benjamin Peterson wrote:

It passes for me on Leopard. Can you post the test running in verbose
mode so we can see where it hangs?

It never hangs when run standalone, though it crashes about half the
time. Running it under gdb doesn't help; it always gives me an
interrupted syste call in os.waidpid() in forking.py.

The hang occurs during 'make test', and it's always the second run
that hangs. Perhaps some lock isn't getting cleaned up properly the
first time?

• -Barry

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Darwin)

iQCVAwUBSFEicXEjvBPtnXfVAQLGNwP/S6f2IrO7c7SET0Gx8FXqdPmot3jcmopx
TFxDA5csh/pVaDQCVW6DiLMXsu2TkQGPPbbo8Bx9iPmV/iIHFqy4nDtETqqjKdRp
BvVtBmvSrP6wmymlKFlFC5qdfbbvguZq/hO60XulQk+WU4F8N7oHQck0tA2JhdDh
lS5SAFAIovA=
=xzs6
-----END PGP SIGNATURE-----

[jnoller]

I did a make clean && ./configure && make and it started compiling for me
again. Sorry for the noise.

[gvanrossum]

If it's only failing during the second run of "make test", typically
there's some implicit dependency on something that is disturbed by
running a test that's later in the suite of tests. This could be either
the fault of that other test (not restoring some global setting or
environment var) or the fault of the test that fails (making unwarranted
assumptions or not initializing some needed settings before starting).

If it works for some folks and not for others, on the same platform,
compare the set of extension modules that are not built, reported by
"make" in a message starting with "Failed to find the necessary bits to
build these modules:". Likely, Barry has the most complete set, while
Jesse has a few more extensions missing.

Finding this is usually a painful process of bisecting the set of tests
run. Randomizing the tests with regrtest.py -r might also be helpful.

FWIW, when I tried (on Leopard) "make test
TESTOPTS=test_multiprocessing" it hung on the first set. When I ran
"./python Lib/test/test_multiprocess.py -v" it reported 122 tests
passed. But when I ran "./python Lib/test/regrtest.py -v
test_multiprocessing" one test failed:

======================================================================
ERROR: test_remote (test.test_multiprocessing.WithManagerTestRemoteManager)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/Users/guido/p/Lib/test/test_multiprocessing.py", line 1167, in
test_remote
    queue = manager2.get_queue()
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 650, in temp
    authkey=self._authkey, exposed=exp
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 902, in
AutoProxy
    incref=incref)
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 711, in
__init__
    self._incref()
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 758, in
_incref
    dispatch(conn, None, 'incref', (self._id,))
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 94, in
dispatch
    raise convert_to_error(kind, result)
RemoteError: 
---------------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 196, in
handle_request
    result = func(c, *args, **kwds)
  File "/Users/guido/p/Lib/multiprocessing/managers.py", line 412, in incref
    self.id_to_refcount[ident] += 1
KeyError: '5f2828'

---

[gvanrossum]

I should add this was in the trunk (2.6).

[paulmelis]

I think I'm having a similar lockup on fedora core 4 (smp machine). This
is with the py3k branch, freshly svn updated. When running "make test
TESTOPTS=test_multiprocessing" the first of the two test runs always
succeeds in something like 10-15 seconds, while the second one
occasionally hangs. I tried running with -v as extra argument but can't
get it to hang in that case (to figure out which test is the culprit).

[paulmelis]

After a few more runs with -v and redirecting output to a file it seems
the lockup I get is in
test_notify_all (test.test_multiprocessing.WithManagerTestCondition)

[jnoller]

It's taking me longer to get to this than I planned, any help is
appreciated.

[jnoller]

I can get an intermittent (1 every 15 or so runs) lock in:
test_get (main.WithProcessesTestQueue) ...

Executed like this:
./python Lib/test/test_multiprocessing.py

When I control-c it the stack looks like this:
...snip
File "/root/py/python-3000/Lib/multiprocessing/pool.py", line 57, in
worker
task = get()
File "/root/py/python-3000/Lib/multiprocessing/queues.py", line 337,
in get
task = get()
File "/root/py/python-3000/Lib/multiprocessing/queues.py", line 339,
in get
racquire()
KeyboardInterrupt
task = get()
File "/root/py/python-3000/Lib/multiprocessing/queues.py", line 337,
in get
task = get()
File "/root/py/python-3000/Lib/multiprocessing/queues.py", line 337,
in get
return recv()
File "/root/py/python-3000/Lib/pickle.py", line 1327, in loads
racquire()
KeyboardInterrupt
racquire()
KeyboardInterrupt
def loads(s, *, encoding="ASCII", errors="strict"):
KeyboardInterrupt

I'm not seeing frequent locks/failures when run with regrtest, but I am
seeing them with "make test TESTOPTS=test_multiprocessing"

I've attached full output. Still trying to figure it out

[paulmelis]

I made a copy of test_multiprocessing.py (to test_mp.py) and basically
removed all test classes, except _TestCondition. In it, I commented all
test methods except test_notify_all. When run with make test
TESTOPTS="-v test_mp" there's the lockups every few runs, but I also got
(only three times in 40 or so runs so far):

9:57|paul@tabu:~/c/py3k-svn> make test TESTOPTS="-v test_mp"

Failed to find the necessary bits to build these modules:
_gestalt
To find the necessary bits, look in setup.py in detect_modules() for the
module's name.

find ./Lib -name '*.py[co]' -print | xargs rm -f
./python -E -bb ./Lib/test/regrtest.py -v test_mp
test_mp
test_notify_all (test.test_mp.WithProcessesTestCondition) ... ok
test_notify_all (test.test_mp.WithThreadsTestCondition) ... ok
test_notify_all (test.test_mp.WithManagerTestCondition) ... ok

----------------------------------------------------------------------
Ran 3 tests in 1.087s

OK
1 test OK.
CAUTION:  stdout isn't compared in verbose mode:
a test that passes in verbose mode may fail without it.
./python -E -bb ./Lib/test/regrtest.py -v test_mp
test_mp
test_notify_all (test.test_mp.WithProcessesTestCondition) ... ok
test_notify_all (test.test_mp.WithThreadsTestCondition) ... ok
test_notify_all (test.test_mp.WithManagerTestCondition) ... Exception in
thread Thread-28:
Traceback (most recent call last):
  File "/home/paul/c/py3k-svn/Lib/threading.py", line 492, in
_bootstrap_inner
    self.run()
  File "/home/paul/c/py3k-svn/Lib/threading.py", line 447, in run
    self._target(*self._args, **self._kwargs)
  File "/home/paul/c/py3k-svn/Lib/test/test_mp.py", line 208, in f
    cond.wait(timeout)
  File "/home/paul/c/py3k-svn/Lib/multiprocessing/managers.py", line
973, in wait
    return self._callmethod('wait', (timeout,))
  File "/home/paul/c/py3k-svn/Lib/multiprocessing/managers.py", line
748, in _callmethod
    raise convert_to_error(kind, result)
RuntimeError: cannot wait on un-aquired lock