RFR: 7903188: Log time spent waiting to acquire exclusive access lock

[Jaikiran Pai]

On Wed, 19 Jun 2024 09:39:04 GMT, Jaikiran Pai <jpai at openjdk.org> wrote:

> Can I please get a review of this change which proposes to implement the enhancement requested in https://bugs.openjdk.org/browse/CODETOOLS-7903188?
> 
> jtreg supports the ability to sequentially execute tests, instead of concurrently, for tests belonging to a pre-configured `exclusiveAccess.dirs` directory. The `MainAction` and `ShellAction` before launching the test, first acquire a lock. The lock acquisition can be time consuming and depends on how long an already running test from that directory takes to complete. This lock acquisiton time isn't reported anywhere in the jtreg action's `section` in the report. Because of this, it sometimes makes it difficult to determine where the unaccounted time is spent.
> 
> The change in this PR prints out how long it took to acquire a exclusive access before launching the test. It's only printed if the test was configured with exclusiveAccess. The reported message will look like:
> 
> 
> #section:main
> ----------messages:(7/230)----------
> command: main Test
> reason: User specified action: run main Test 
> started: Wed Jun 19 14:45:21 IST 2024
> exclusiveAccess wait time (seconds): 20.289
> Mode: othervm
> finished: Wed Jun 19 14:45:21 IST 2024
> elapsed time (seconds): 0.123
> 
> 
> An existing self test has been updated to verify this change. All existing tests continue to pass with this change.

I've updated the PR to clean up the logic of lock acquisition, printing the wait time and the lock release. The updated change centralizes this responsibility into the base `com.sun.javatest.regtest.exec.Action` class which simplifies dealing with the lock as well as printing the wait time.

With these changes, the output will now look like:


#section:main
----------messages:(7/229)----------
command: main Test
reason: User specified action: run main Test 
exclusiveAccess wait time (seconds): 20.304
started: Thu Jun 20 15:55:38 IST 2024
Mode: othervm
finished: Thu Jun 20 15:55:38 IST 2024
elapsed time (seconds): 0.13


All tests continue to pass.

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

PR Comment: https://git.openjdk.org/jtreg/pull/208#issuecomment-2180362479