After CODETOOLS-7903183 was implemented, we found the following in the jtreg logs:
----------messages:(8/425)----------
command: compile /opt/mach5/mesos/work_dir/jib-master/install/2022-05-13-0719296.daniel.jelinski.jdk/src.full/open/test/jdk/java/net/httpclient/websocket/PendingTextPongClose.java
started: Fri May 13 07:37:09 UTC 2022
finished: Fri May 13 07:37:09 UTC 2022
elapsed time (seconds): 0.059
----------messages:(7/555)----------
command: testng -Djdk.internal.httpclient.debug=true -Djdk.internal.httpclient.websocket.debug=true -Djdk.httpclient.sendBufferSize=8192 PendingTextPongClose
started: Fri May 13 07:40:34 UTC 2022
finished: Fri May 13 07:41:14 UTC 2022
elapsed time (seconds): 40.95
there's a long gap between the end of compilation and the start of test run.
The gap can probably be attributed to waiting to acquire a lock; the test in question is contained in a directory listed under exclusiveAccess.dirs, meaning that the tasks in that directory cannot run in parallel.
Locking code can be found here: https://github.com/openjdk/jtreg/blob/836af95829deb58b9a725740c1eacbfc722e6385/src/share/classes/com/sun/javatest/regtest/exec/MainAction.java#L344
It would be great if we could see the time spent waiting to acquire that lock in jtreg output.
----------messages:(8/425)----------
command: compile /opt/mach5/mesos/work_dir/jib-master/install/2022-05-13-0719296.daniel.jelinski.jdk/src.full/open/test/jdk/java/net/httpclient/websocket/PendingTextPongClose.java
started: Fri May 13 07:37:09 UTC 2022
finished: Fri May 13 07:37:09 UTC 2022
elapsed time (seconds): 0.059
----------messages:(7/555)----------
command: testng -Djdk.internal.httpclient.debug=true -Djdk.internal.httpclient.websocket.debug=true -Djdk.httpclient.sendBufferSize=8192 PendingTextPongClose
started: Fri May 13 07:40:34 UTC 2022
finished: Fri May 13 07:41:14 UTC 2022
elapsed time (seconds): 40.95
there's a long gap between the end of compilation and the start of test run.
The gap can probably be attributed to waiting to acquire a lock; the test in question is contained in a directory listed under exclusiveAccess.dirs, meaning that the tasks in that directory cannot run in parallel.
Locking code can be found here: https://github.com/openjdk/jtreg/blob/836af95829deb58b9a725740c1eacbfc722e6385/src/share/classes/com/sun/javatest/regtest/exec/MainAction.java#L344
It would be great if we could see the time spent waiting to acquire that lock in jtreg output.
- relates to
-
CODETOOLS-7902942 Elapsed time of MainAction is including serialization wait time
- Resolved
- links to
-
Commit openjdk/jtreg/d8a65183
-
Review(master) openjdk/jtreg/208