BZ #70: Mauve java.util.TreeMap.serialization fails with timeout (mutex_lock: pthread_mutex_lock failed: Invalid argument)

Status fields:

Running:

$ cacao Harness -vm cacao -showpasses java.util.Timer.taskException
java.util.TreeMap.serialization

fails with:

PASS: java.util.Timer.taskException
LOG: [0x00002ae0ecc9eaf0] mutex_lock: pthread_mutex_lock failed: Invalid argument
FAIL: java.util.TreeMap.serialization
  Test timed out.  Use -timeout [millis] option to change the timeout value.

The later testcase does not matter, so the bugger is java.util.Timer.taskException.

OpenJDK looks like this:

$ java Harness -vm java -showpasses java.util.Timer.taskException
java.util.TreeMap.serialization
WARNING: running tests on 'java'.  To set the test VM, use --with-vm when
configuring or specify -vm when running the Harness.

Exception in thread "Timer-0" java.lang.RuntimeException: eat it!!!
        at gnu.testlet.java.util.Timer.taskException$1.run(taskException.java:47)
        at java.util.TimerThread.mainLoop(Timer.java:534)
        at java.util.TimerThread.run(Timer.java:484)
PASS: java.util.Timer.taskException
PASS: java.util.TreeMap.serialization

It passes when only these two tests are run, but not when running on java.util:

Exception in thread "Timer-0" java.lang.RuntimeException: eat it!!!
        at gnu.testlet.java.util.Timer.taskException$1.run(taskException.java:47)
        at java.util.TimerThread.mainLoop(Timer.java:534)
        at java.util.TimerThread.run(Timer.java:484)
PASS: java.util.Timer.taskException
LOG: [0x0000000040062950] mutex_lock: pthread_mutex_lock failed: Invalid argument
FAIL: java.util.TreeMap.serialization
  Test timed out.  Use -timeout [millis] option to change the timeout value.

Just got in one run:

LOG: [0x0000000040041950] thread 3 set flc bit for lock-holding thread 1
LOG: [0x00002b4bacc57af0] thread 1 saw flc bit
LOG: [0x0000000040041950] mutex_lock: pthread_mutex_lock failed: Invalid argument

It also works sometimes, so it's a race (most possibly with the finalizer thread):

$ cacao Harness -vm cacao -showpasses -debug java.util.Timer.taskException
java/lang/Class/init
PASS: java.util.Timer.taskException
PASS: java.lang.Class.init

TEST RESULTS:
0 of 2 tests failed.  0 total calls to harness.check() failed.

Calling stacktrace_print_current() when an error occurs:

$ cacao Harness -vm cacao -showpasses -debug java.util.Timer.taskException
java/lang/Class/init
PASS: java.util.Timer.taskException
        at java.lang.VMRuntime.runFinalization()V(Native Method)
        at java.lang.Runtime.runFinalization()V(Runtime.java:622)
        at java.lang.System.runFinalization()V(System.java:604)
        at RunnerProcess.runtest(Ljava/lang/String;)V(RunnerProcess.java:270)
        at
RunnerProcess.runAndReport(LRunnerProcess;Ljava/lang/String;)V(RunnerProcess.java:430)
        at RunnerProcess.main([Ljava/lang/String;)V(RunnerProcess.java:242)
cacao: lock.c:1034: lock_monitor_enter: Assertion `lr->count == 0' failed.
FAIL: java.lang.Class.init
  Test timed out.  Use -timeout [millis] option to change the timeout value.

TEST RESULTS:
1 of 2 tests failed.  0 total calls to harness.check() failed.

-XX:+DebugFinalizer reveals that we first free the lockrecord for
java/util/Timer$TaskQueue and afterwards the one for java/util/Timer.  But the later
calls a synchronized method of the former.

LOG: [0x00002b15d60fbaf0] [finalizer notified]
LOG: [0x00002b15d60fbaf0] [lock_record_notify: lr=0xa48ab0, t=0x643e00,
waitingthread=0x643a00, sleeping=1, one=1]
LOG: [0x0000000040041950] [finalizer thread    : status=awake]
LOG: [0x0000000040041950] [finalizer running   : o=0x673450 p=(nil)
class=gnu/java/nio/FileChannelImpl PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x65b820 p=(nil)
class=java/io/FileInputStream PUBLIC SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x67cfa0 p=(nil)
class=gnu/java/nio/VMChannel$State PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer lockrecord: o=0x68e898 p=(nil)
class=java/util/Timer$TaskQueue FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [lock_record_free  : lr=0xcbf4d0]
LOG: [0x0000000040041950] [finalizer running   : o=0x673240 p=(nil)
class=gnu/java/nio/FileChannelImpl PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x69df30 p=(nil)
class=gnu/java/nio/FileChannelImpl PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x6a9258 p=(nil)
class=gnu/java/nio/VMChannel$State PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x68e988 p=(nil)
class=gnu/java/nio/VMChannel$State PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x6a9b18 p=(nil)
class=gnu/java/nio/VMChannel$State PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x673510 p=(nil)
class=gnu/java/nio/FileChannelImpl PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x65bb60 p=(nil)
class=java/io/FileInputStream PUBLIC SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x65ba60 p=(nil)
class=java/io/FileInputStream PUBLIC SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x673960 p=(nil)
class=gnu/java/nio/FileChannelImpl PUBLIC FINAL SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x65bc40 p=(nil)
class=java/io/FileInputStream PUBLIC SYNCHRONIZED]
LOG: [0x0000000040041950] [finalizer running   : o=0x673300 p=(nil)
class=java/util/Timer PUBLIC SYNCHRONIZED]
        <<No stacktrace available>>
LOG: [0x0000000040041950] mutex_lock: pthread_mutex_lock failed: Invalid argument

Doesn't happen anymore. There have been lots of threading/locking fixes, so I'm not
surprised by this.