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

[Jonathan Gibbons]

On Mon, 24 May 2021 07:10:55 GMT, Stefan Karlsson <stefank at openjdk.org> wrote:

> 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.

In general, it would be better to have a test, but that may be hard in this case.

Please type `/integrate` so that I can `/sponsor` it.

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

Marked as reviewed by jjg (Lead).

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