RFR: 7902942: Elapsed time of MainAction is including serialization wait time

[Stefan Karlsson]

If you run othervm tests with a concurrency > 1, then the reported test times get inflated. You can see this by running:
make -C ../build/fastdebug test TEST=test/hotspot/jtreg/vmTestbase/vm/gc/compact JTREG="VERBOSE=all"

and looking at the elapsed time for the main action:

$ grep -r "othervm specified" -A1 jtreg_open_test_hotspot_jtreg_vmTestbase_vm_gc_compact/jtreg.log | grep elapsed
elapsed time (seconds): 121.194
elapsed time (seconds): 240.631
elapsed time (seconds): 359.092
elapsed time (seconds): 478.718
elapsed time (seconds): 597.433
elapsed time (seconds): 716.628
elapsed time (seconds): 836.638
elapsed time (seconds): 955.156
elapsed time (seconds): 1074.476
elapsed time (seconds): 1193.712
elapsed time (seconds): 1314.116
elapsed time (seconds): 1433.632
elapsed time (seconds): 1553.563
elapsed time (seconds): 1672.996
elapsed time (seconds): 1792.846
elapsed time (seconds): 1913.112
elapsed time (seconds): 1926.819
elapsed time (seconds): 1926.809
elapsed time (seconds): 1926.921
elapsed time (seconds): 1927.093
elapsed time (seconds): 1927.192
elapsed time (seconds): 1927.07
elapsed time (seconds): 1926.896
elapsed time (seconds): 1927.31
elapsed time (seconds): 1927.244
elapsed time (seconds): 1927.33
elapsed time (seconds): 1927.221
elapsed time (seconds): 1927.42
elapsed time (seconds): 1927.158
elapsed time (seconds): 1927.315
elapsed time (seconds): 1927.316
elapsed time (seconds): 1927.311
elapsed time (seconds): 1927.532
elapsed time (seconds): 1927.379

Each test is supposed to be run for 120 seconds, but the reported time ramps up in ~120s increments until it reaches the number that matches the "jtreg concurrency" number, which in my run is 16.

I think this happens because we start "concurrent" tests. Each test starts by taking a timestamp, then looks if we need "exclusiveAccess" and if we do, then a lock is taken before the othervm test process is forked. This serializes the tests and inflates the times.

The proposed fix moves the start of the action to after the lock has been acquired, and end of the action before releasing the lock.

The patch has only been tested by running the following:

make -C ../build/fastdebug test TEST=test/hotspot/jtreg/vmTestbase/vm/gc/compact JTREG="TIMEOUT_FACTOR=0.1"

and manually verifying that the elapsed time stops increasing. Any guidance on how to further test this would be appreciated.

-------------

Commit messages:
 - Also move endAction into the lock scope
 - 7902822: Elapsed time of MainAction is including serialization wait time

Changes: https://git.openjdk.java.net/jtreg/pull/11/files
 Webrev: https://webrevs.openjdk.java.net/?repo=jtreg&pr=11&range=00
  Issue: https://bugs.openjdk.java.net/browse/JDK-7902942
  Stats: 11 lines in 1 file changed: 8 ins; 3 del; 0 mod
  Patch: https://git.openjdk.java.net/jtreg/pull/11.diff
  Fetch: git fetch https://git.openjdk.java.net/jtreg pull/11/head:pull/11

PR: https://git.openjdk.java.net/jtreg/pull/11