RFR: 8229517: Support for optional asynchronous/buffered logging [v18]

[Thomas Stuefe]

On Sat, 22 May 2021 01:03:29 GMT, Xin Liu <xliu at openjdk.org> wrote:

>> This patch provides a buffer to store asynchrounous messages and flush them to
>> underlying files periodically.
>
> Xin Liu has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Add threadump support for AsyncLog Thread.
>   
>   when jstack requests to dump threads:
>   "AsyncLog Thread" os_prio=0 cpu=239.26ms elapsed=52.13s tid=0x00007fb814c76ec0 nid=0x9023 runnable
>   
>   When jvm crash, thread dump is written to hs_err_pid$pid.log.
>   0x00007fa8d824e450 Thread "AsyncLog Thread" [stack: 0x00007fa880d44000,0x00007fa880e44000] [id=126290]

> _Mailing list message from [Liu, Xin](mailto:xxinliu at amazon.com) on [hotspot-dev](mailto:hotspot-dev at mail.openjdk.java.net):_
> 
> hi, David,
> 
> I am aware of this issue. There are a few gtest testcases can't run in
> async logging mode. The rootcause is testing code assumes logging is
> synchronous.
> 
> eg. this testcase opens and reads 'TestLogFileName' right after
> log_trace(). This is perfectly fine in sequential execution. It's unsafe
> and TestLogFileName may haven't been written yet. fopen could fail(no
> error check in current testing) and then fread yields NULL pointer for
> strcmp.
> 
> TEST_VM_F(LogTest, prefix) {
> set_log_config(TestLogFileName, "logging+test=trace");
> log_trace(logging, test)(LOG_LINE_STR);
> EXPECT_TRUE(file_contains_substring(TestLogFileName, LOG_PREFIX_STR
> LOG_LINE_STR));
> }
> 
> It's also not MT-safe to do concurrent fread() (gtest EXPECT/ASSERT)
> while fwrite is onging(AsyncLog Thread). Random execution may happen if
> FILE has been corrupted.
> 
> I manage to fix those hard crashes in gtests. It would up a non-trivial
> patch, and it just fixed hard crashes. I reckon I give up running gtest
> in async mode and provide an isolated and a clean room to test it.

Hi Xin,

I agree that these UL tests are annoying because they modify global VM state - resetting global UL options which ideally should just be set at VM startup and then never touched. gtest should not do this.

I struggled with the same thing with NMT in this upcoming PR: https://github.com/openjdk/jdk/pull/2921.

As I wrote before, in my view, it should be possible to execute the gtest suite with any form of UL options - or VM options in general - and the gtests should at most *react* on those options, never change them. In the case of UL, maybe conditionally execute or skip some tests if UL is on or off. 

In other words, I should be able to run `gtestLauncher -jdk:... -Xlog:os` and the gtests should run through successfully with these flags. And then, as a complimentary step, we execute the gtests (or selected parts of them with --gtest_filter) with selected, non-default, VM options. E.g. with UL turned on. I know you do this already for some of the Async tests, and maybe thats the way to go for all UL gtests. We do this also for Metaspace- and large-page-tests. And I will modify the NMT gtests to not modify NMT state anymore:https://github.com/openjdk/jdk/pull/2921/files#diff-c1004f2502ccc5f5340e7752264c7e0274f6a5fe4da0554d89d3bc8209801199 )

Moreover, things like "log to a file and scan for expected output" are really better suited for jtreg tests anyway, which spawn a child VM with options and scan the log output. Doing this in gtests seems wrong. Jtreg gives more fine-grained control, I can `-retain` the output files, I can execute them in parallel, Problemlist them, etc. I don't have to execute test logic like reading the log output file *inside* the logging VM.

So maybe (future RFE?) we need to move part or all of the UL tests out of the gtest suite and make them jtreg tests. 

Cheers, Thomas

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

PR: https://git.openjdk.java.net/jdk/pull/3135