Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8273112: -Xloggc:<filename> should override -verbose:gc #5295

Closed
wants to merge 4 commits into from

Conversation

@weixlu
Copy link
Contributor

@weixlu weixlu commented Aug 30, 2021

According to java 16 specifications for java command (https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html), the command line option -Xloggc should override -verbose:gc if both options are given with the same java command. However, gc information still outputs to console even if gc log file is specified.

$java -Xloggc:gc.log -verbose:gc -version
[0.000s][warning][gc] -Xloggc is deprecated. Will use -Xlog:gc:gc.log instead.
[0.003s][info ][gc] Using G1
$cat gc.log
[0.003s][info][gc] Using G1

As a result, we propose to put off the log configuration of -verbose:gc option until we are confident that there isn’t -Xloggc option.


Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/5295/head:pull/5295
$ git checkout pull/5295

Update a local copy of the PR:
$ git checkout pull/5295
$ git pull https://git.openjdk.java.net/jdk pull/5295/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 5295

View PR using the GUI difftool:
$ git pr show -t 5295

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/5295.diff

@bridgekeeper
Copy link

@bridgekeeper bridgekeeper bot commented Aug 30, 2021

👋 Welcome back weixlu! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

Loading

@openjdk openjdk bot added the rfr label Aug 30, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Aug 30, 2021

@weixlu The following label will be automatically applied to this pull request:

  • hotspot-runtime

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Aug 30, 2021

Loading

@mseledts
Copy link
Member

@mseledts mseledts commented Aug 30, 2021

Please consider providing a test for this change, or modifying an existing test with this test case.

Loading

Copy link
Member

@iklam iklam left a comment

https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html only mentions that -verbose:gc will be overridden by -Xloggc:<filename> (and -Xloggc:<filename> has been replaced with -Xlog:gc:file=<filename>). It doesn't mention the other three -verbose options (class, module, jni). We need to discuss what (if anything) should be done for those three options.

Loading

has_verbose_gc = false;
}
if (ts->contains(LogTag::_class) && ts->has_output_to_file()) {
has_verbose_class = false;
Copy link
Member

@iklam iklam Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This doesn't seem correct to me. If the command line is:

java -Xlog:class+resolve=debug:file=log.txt -verbose:class -version

We should have the following:

(a) class,load -> stdout
(b) class,unload -> stdout
(c) class,resolve -> log.txt

But your change will disable both (a) and (b).

Also, what is the proposed behavior with this?

java -Xlog:class+load:file=log.txt -verbose:class -version

Will we have [A]:

class,load -> log.txt
class,unload -> stdout

or [B]?

class,load -> log.txt
class,unload -> disabled

Loading

Copy link
Contributor Author

@weixlu weixlu Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For your java command:

java -Xlog:class+load:file=log.txt -verbose:class -version

We will have [B] according to the current commit:

class,load -> log.txt
class,unload -> disabled

But I'm not sure whether this behavior is correct. The website (https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html) doesn't give us explicit clue. It only says -verbose:class equals -Xlog:class+load=info,class+unload=info.
For the command above, maybe we can propose a third way [C]:

class,load -> log.txt and stdout
class,unload -> stdout

In addition, what if the command is:

java -Xlog:class+load=error,class+unload=info:log.txt -verbose:class -version

In this case, since class+load=error is ”weaker" than class+load=info, maybe -verbose should not be overriden by -Xlog?
To make things simple, in my commit, as long as "class" shows up, no matter it's -Xlog:class or -Xlog:class+resolve or -Xlog:class=debug , then -verbose:class is to be overiden. But I'm quite uncertain about whether it is correct. Looking forward to your suggestions.

Loading

for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
if (ts->contains(LogTag::_gc) && ts->has_output_to_file()) {
has_verbose_gc = false;
}
Copy link
Member

@iklam iklam Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if the command-line is this?

java -Xlog:gc+heap=foo.txt -verbose:gc -version

Loading

Copy link
Contributor Author

@weixlu weixlu Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According to the current commit, we will have

gc -> disabled
gc+heap ->foo.txt

But the same as the comment above, I'm not sure about its correctness. So maybe we should discuss what if the selections in Xlog is not the same as -Xlog:gc.

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Sep 1, 2021

I find it very unfortunate that it states that -verbose:gc will be overridden by -Xloggc:<filename> and -Xlog as that makes the logic for dealing with this GC case very convoluted. It would make much more sense that -verbose:x simply be treated as its corresponding -Xlog variant. Then we would need no special logic at all.
I'm unclear how the non-GC versions of -verbose:x are treated with respect to explicit -Xlog:x commands?

Loading

@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 1, 2021

I find it very unfortunate that it states that -verbose:gc will be overridden by -Xloggc:<filename> and -Xlog as that makes the logic for dealing with this GC case very convoluted. It would make much more sense that -verbose:x simply be treated as its corresponding -Xlog variant. Then we would need no special logic at all.

Things are quite easy if -verbose:x is treated as -Xlog. Multiple -Xlog arguments for the same output override each other in their given order, according to https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html.

I'm unclear how the non-GC versions of -verbose:x are treated with respect to explicit -Xlog:x commands?

I have looked up some documents but unfortunately haven't found relevant statements.

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Sep 1, 2021

There are no statements about how the other -verbose:x options interact with their -Xlog:x equivalents, but I was wondering how the implementation actually works?

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Sep 1, 2021

I also can't see how to implement the "overrides" semantics without scanning the entire command-line to collate the different forms of the flag and then collapse them into a single appropriate -Xlog definition. And that would be a startup hit.

Loading

@iklam
Copy link
Member

@iklam iklam commented Sep 1, 2021

I find it very unfortunate that it states that -verbose:gc will be overridden by -Xloggc:<filename> and -Xlog as that makes the logic for dealing with this GC case very convoluted. It would make much more sense that -verbose:x simply be treated as its corresponding -Xlog variant. Then we would need no special logic at all.

Things are quite easy if -verbose:x is treated as -Xlog. Multiple -Xlog arguments for the same output override each other in their given order, according to https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html.

I'm unclear how the non-GC versions of -verbose:x are treated with respect to explicit -Xlog:x commands?

I have looked up some documents but unfortunately haven't found relevant statements.

History:

See https://docs.oracle.com/javase/8/docs/technotes/tools/windows/java.html

Before UL was implemented, we had this:

" -Xloggc:filename -- Sets the file to which verbose GC events information should be redirected for logging. The information written to this file is similar to the output of -verbose:gc with the time elapsed since the first GC event preceding each logged event. The -Xloggc option overrides -verbose:gc if both are given with the same java command."

~/jdk/official/jdk8_b132/linux_amd64$ ./bin/java -verbose:gc -cp ~/tmp HelloGC
[GC (System.gc())  391K->536K(1029632K), 0.0243973 secs]
[Full GC (System.gc())  536K->259K(1029632K), 0.0079780 secs]
~/jdk/official/jdk8_b132/linux_amd64$ ./bin/java -Xloggc:foo -verbose:gc -cp ~/tmp HelloGC
~/jdk/official/jdk8_b132/linux_amd64$ ./bin/java -verbose:gc -Xloggc:foo -cp ~/tmp HelloGC
~/jdk/official/jdk8_b132/linux_amd64$ 

After UL was implemented, we changed the man page to say this, but unfortunately the "overrides" part is no longer working:

"Sets the file to which verbose GC events information should be redirected for logging. The -Xloggc option overrides -verbose:gc if both are given with the same java command. -Xloggc:filename is replaced by -Xlog:gc:filename. See Enable Logging with the JVM Unified Logging Framework."


UL doesn't support the notion of "overriding" as required by the java8 man page. If -Xlog:gc is specified for both a file and stdout, both will be written:

$ rm foo
$ tbjava -Xlog:gc:file=foo -Xlog:gc:stdout -version
[0.003s][info][gc] Using G1
java version "18-internal" 2022-03-15
Java(TM) SE Runtime Environment (build 18-internal+0-adhoc.iklam.open)
Java HotSpot(TM) 64-Bit Server VM (build 18-internal+0-adhoc.iklam.open, mixed mode, sharing)
$ cat foo 
[0.003s][info][gc] Using G1
$ rm foo
$ tbjava -Xlog:gc:stdout -Xlog:gc:file=foo -version
[0.003s][info][gc] Using G1
java version "18-internal" 2022-03-15
Java(TM) SE Runtime Environment (build 18-internal+0-adhoc.iklam.open)
Java HotSpot(TM) 64-Bit Server VM (build 18-internal+0-adhoc.iklam.open, mixed mode, sharing)
$ cat foo 
[0.003s][info][gc] Using G1
$ 

I think the ability to "override" -verbose:gc with -Xloggc:filename is rather useless. We should just change the man page to match the current behavior (i.e., -verbose:gc is an alias to -Xlog:gc:stdout) and remove the mention of overriding. If someone really wants the old behavior, they should remove -verbose:gc from their command-line.

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Sep 2, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 1/09/2021 5:36 pm, Xiaowei Lu wrote:

On Wed, 1 Sep 2021 02:03:48 GMT, Ioi Lam <iklam at openjdk.org> wrote:

According to java 16 specifications for java command (https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html), the command line option -Xloggc should override -verbose:gc if both options are given with the same java command. However, gc information still outputs to console even if gc log file is specified.

$java -Xloggc:gc.log -verbose:gc -version
[0.000s][warning][gc] -Xloggc is deprecated. Will use -Xlog:gc:gc.log instead.
[0.003s][info ][gc] Using G1
$cat gc.log
[0.003s][info][gc] Using G1

In addition, since -Xloggc:filename is replaced by -Xlog:gc:filename, can we assume that -Xlog:gc:filename should override -verbose:gc as -Xloggc:filename? Currently, gclog still outputs to both stdout and file if -Xlog and -verbose are given with the same java command.

$java -Xlog:gc:gc.log -verbose:gc -version
[0.003s][info][gc] Using G1
$cat gc.log
[0.003s][info][gc] Using G1

As a result, we propose to put off the log configuration of -verbose option until we are confident that there isn?t -Xloggc or -Xlog options.

src/hotspot/share/runtime/arguments.cpp line 2965:

2963: }
2964: if (ts->contains(LogTag::_class) && ts->has_output_to_file()) {
2965: has_verbose_class = false;

This doesn't seem correct to me. If the command line is:

java -Xlog:class+resolve=debug:file=log.txt -verbose:class -version

We should have the following:

(a) class,load -> stdout
(b) class,unload -> stdout
(c) class,resolve -> log.txt

But your change will disable both (a) and (b).

Also, what is the proposed behavior with this?

java -Xlog:class+load:file=log.txt -verbose:class -version

Will we have [A]:

class,load -> log.txt
class,unload -> stdout

or [B]?

class,load -> log.txt
class,unload -> disabled

For your java command:

java -Xlog:class+load:file=log.txt -verbose:class -version

We will have [B] according to the current commit:

class,load -> log.txt
class,unload -> disabled

But I'm not sure whether this behavior is correct. The website (https://docs.oracle.com/en/java/javase/16/docs/specs/man/java.html) doesn't give us explicit clue. It only says -verbose:class equals -Xlog:class+load=info,class+unload=info.
For the command above, maybe we can propose a third way [C]:

class,load -> log.txt and stdout
class,unload -> stdout

In addition, what if the command is:

java -Xlog:class+load=error,class+unload=info:log.txt -verbose:class -version

In this case, since ``class+load=error`` is ?weaker" than ``class+load=info``, maybe -verbose should not be overriden by -Xlog?

There is no specification that states that -verbose:X is overridden by
-Xlog:X except for GC. For the non-GC case the -verbose:X argument
should be processed in its -Xlog form and the full command-line
processed as-if only -Xlog had been used. That is very clear and simple
to implement.

The GC case is more problematic as per my other comment. There is no
clear definition of what override means, but I would think that "ignore"
would be appropriate. The main problem is that you have to scan the
entire command-line to know what to do with the -verbose:gc.

David
-----

Loading

@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 2, 2021

@iklam Yes, the introduction of UL has reconstructed many codes about logging. But a lot of Java users, as far as we know, are quite confused about the not working of such overrides for many days. These users have just upgraded to new java versions from java8 under our persuasion and they are more familiar with the behavior in java8. So I guess the ability to override may be useful for them.

Loading

@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 2, 2021

@dholmes-ora In my commit, the behavior of override is much like "ignore" as you say. We put off the process of -verbose:gc until the entire command-line has been parsed. Then we decide whether to ignore -verbose:gc or not. As far as I'm concerned, we have to scan the entire command-line firstly.

Loading

@iklam
Copy link
Member

@iklam iklam commented Sep 2, 2021

@iklam Yes, the introduction of UL has reconstructed many codes about logging. But a lot of Java users, as far as we know, are quite confused about the not working of such overrides for many days. These users have just upgraded to new java versions from java8 under our persuasion and they are more familiar with the behavior in java8. So I guess the ability to override may be useful for them.

If that's the case, those users aren't using -Xlog:gc yet. Maybe we should implement strictly what the man page says: if -Xloggc:<filename> is used, then -verbose (or -verbose:gc) will not cause gc logs to be printed to the stdout.

We shouldn't do anything to the other components of -verbose, and we shouldn't consider the interaction between -Xlog and -verbose.

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Sep 2, 2021

Before UL -verbose:gc simply set PrintGC=true. If you specified -Xloggc:<file> then it also set PrintGC=true and PrintGCTimestamps=true. So to describe this as "overriding" is misleading in the extreme - it simply changed the output destination and added a timestamp. It also made no difference what order the flags were specified in, or even if they were passed mutiple times.

With UL -verbose:gc enables logging of "gc" at "Info" level to stdout. However -Xloggc:<file> sets _gc_log_filename which in turns causes logging at either the "gc" or "gc*" levels depending on PrintGCDetails. That logging is at the default level - which is Info. So as far as I can see, we are doing the right thing in terms of preserving the pre-UL relationship between -verbose:gc and -Xloggc:<file> - except that with UL ordering does matter and that is where we have lost the "override" so to speak.

So as far as I can see the only thing we need to fix here is to track the use of both legacy flags, and to hold back on the actual UL configuration until processing of the command-line is complete. That also avoids the need of scanning the entire command-line. This isn't completely trivial to track but I'd be using a simple struct/class as follows:

struct LegacyGCLogging {
char* tags; // "gc" or "gc*"
char* file; // NULL ->stdout
int lastFlag; // -1 not set; 0 -> -verbose:gc; 1 -> -Xloggc
}
If lastFlag was 1 and we encounter -verbose:gc then we do nothing - ensuring the override. Then at the end of argument processing we see what has been set and use that to configure GC logging.

This has the side-effect of ignoring some explicit -Xlog:gc arguments, but that is okay in my view because we are simply treating the legacy flags as-if they appeared last on the command-line and where converted to -Xlog in place.

Cheers,
David

Loading

@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 2, 2021

Thanks for your suggestions. Yes, I think we should merely focus on the man page and let -Xloggc: override -verbose:gc. Thus in the new commit, I put off the process of these two legacy flags (in Arguments::handle_deprecated_print_gc_flags()) until the entire command-line has been parsed.

Loading

iklam
iklam approved these changes Sep 3, 2021
Copy link
Member

@iklam iklam left a comment

LGTM

Loading

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Not surprisingly this looks good to me! :)

I think this captures the desired/expected behaviour.

Thanks,
David

Loading

@@ -93,6 +92,8 @@ bool Arguments::_enable_preview = false;
char* Arguments::SharedArchivePath = NULL;
char* Arguments::SharedDynamicArchivePath = NULL;

LegacyGCLogging Arguments::_legacyGCLogging = { 0 };
Copy link
Member

@dholmes-ora dholmes-ora Sep 3, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

{ 0, 0} ? Or is it implied the other members are zero-initialized?

Loading

Copy link
Contributor Author

@weixlu weixlu Sep 3, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dholmes-ora I think compiler will assign 0 to all members of this struct. Since you have mentioned this here, let's explicitly use { 0, 0} to avoid potential problems.

Loading

@openjdk
Copy link

@openjdk openjdk bot commented Sep 3, 2021

@weixlu This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8273112: -Xloggc:<filename> should override -verbose:gc

Reviewed-by: iklam, dholmes

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 55 new commits pushed to the master branch:

  • dd87181: 8214761: Bug in parallel Kahan summation implementation
  • 7fff22a: 8272805: Avoid looking up standard charsets
  • 92b05fe: 8273251: Call check_possible_safepoint() from SafepointMechanism::process_if_requested()
  • 29e0f13: 8272385: Enforce ECPrivateKey d value to be in the range [1, n-1] for SunEC provider
  • aaa6f69: 8273250: Address javadoc issues in Deflater::setDictionationary
  • 5ee5dd9: 8272914: Create hotspot:tier2 and hotspot:tier3 test groups
  • 5245c1c: 8273147: Update and restructure TestGCLogMessages log message list
  • 632a7e0: 8273165: GraphKit::combine_exception_states fails with "matching stack sizes" assert
  • c2e015c: 8273229: Update OS detection code to recognize Windows Server 2022
  • 0c1b16b: 8273243: Fix indentations in java.net.InetAddress methods
  • ... and 45 more: https://git.openjdk.java.net/jdk/compare/f55d5ab5177b6e08e8499abc181a320a98b28a5f...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@iklam, @dholmes-ora) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

Loading

@openjdk openjdk bot added the ready label Sep 3, 2021
@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 3, 2021

@iklam @dholmes-ora Thanks for your review and helpful suggestions. Could you please sponsor this change?

Loading

@weixlu
Copy link
Contributor Author

@weixlu weixlu commented Sep 3, 2021

/integrate

Loading

@openjdk openjdk bot added the sponsor label Sep 3, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Sep 3, 2021

@weixlu
Your change (at version 5f69d62) is now ready to be sponsored by a Committer.

Loading

@weixlu weixlu changed the title 8273112: -Xloggc and -Xlog should override -verbose 8273112: -Xloggc should override -verbose Sep 3, 2021
@weixlu weixlu changed the title 8273112: -Xloggc should override -verbose 8273112: -Xloggc:<filename> should override -verbose:gc Sep 3, 2021
@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Sep 3, 2021

/sponsor

Loading

@openjdk
Copy link

@openjdk openjdk bot commented Sep 3, 2021

Going to push as commit fa9c865.
Since your change was applied there have been 55 commits pushed to the master branch:

  • dd87181: 8214761: Bug in parallel Kahan summation implementation
  • 7fff22a: 8272805: Avoid looking up standard charsets
  • 92b05fe: 8273251: Call check_possible_safepoint() from SafepointMechanism::process_if_requested()
  • 29e0f13: 8272385: Enforce ECPrivateKey d value to be in the range [1, n-1] for SunEC provider
  • aaa6f69: 8273250: Address javadoc issues in Deflater::setDictionationary
  • 5ee5dd9: 8272914: Create hotspot:tier2 and hotspot:tier3 test groups
  • 5245c1c: 8273147: Update and restructure TestGCLogMessages log message list
  • 632a7e0: 8273165: GraphKit::combine_exception_states fails with "matching stack sizes" assert
  • c2e015c: 8273229: Update OS detection code to recognize Windows Server 2022
  • 0c1b16b: 8273243: Fix indentations in java.net.InetAddress methods
  • ... and 45 more: https://git.openjdk.java.net/jdk/compare/f55d5ab5177b6e08e8499abc181a320a98b28a5f...master

Your commit was automatically rebased without conflicts.

Loading

@openjdk openjdk bot closed this Sep 3, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Sep 3, 2021

@dholmes-ora @weixlu Pushed as commit fa9c865.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

Loading

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
4 participants