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.

Hello Alan,

> I wonder if "exclusiveAccess wait time ..." could be printed before the "started ..." line. That is, the waiting happens before the test starts so would be confusing to have a "wait" log message between "started" and "finished".

I had thought of that, but it would need a slightly more involved change because the construct that allows the code write these messages (the `section`) is instantiated within the `startAction()` method which writes the `started` message. So it's only after that `startAction()` method returns, we get a `section` instance through which we can write out the exclusive access wait time. 

Having said that, I do agree with what you state. Let me see if I can keep it simple and yet be able to write it in that sequence.

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

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