JDK-8209913 : Compiler output is enabled with -Xlog but doesn't use logging
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,12
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2018-08-23
  • Updated: 2019-09-13
  • Resolved: 2018-12-03
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 12
12Resolved
Related Reports
Duplicate :  
JDK-8214526 - Change CodeHeap State Analytics control from UL to Print*
Duplicate :  
JDK-8204916 - CompileBroker::print_heapinfo should redirected to log stream.
Relates :  
JDK-8209150 - [TESTBUG] Add logging to verify JDK-8197901 to a different test
Relates :  
JDK-8214526 - Change CodeHeap State Analytics control from UL to Print*
Relates :  
JDK-8198691 - CodeHeap State Analytics
Description
java -Xlog:all=trace:file=all.log -version

sends the logging output to all.log but this also turns on compiler logging that prints 2500 lines to stdout.

Nobody would do this, but the compiler logging should either not be enabled with -Xlog or it should use logging to print output somewhere not on the screen.
Comments
Closing as duplicate. Thank you for addressing this.
03-12-2018
Can we close this bug now as duplicate of JDK-8214526?
03-12-2018
Bug JDK-8214526 was created to revert back from UL to -XX:+PrintCodeHeapAnalysis
30-11-2018
Also please note, as this is a P4 task, if a fix not planned to be in before rampdown the 'Fix Version' maybe changed to 'tbd' for now and updated with a correct version later when available. (https://openjdk.java.net/projects/jdk/12/).
29-11-2018
File docs subtask as we did for JDK-8198691 and explain that you need to update documentation for JDK 12 after the change. I don't know if you can see that subtask: JDK-8199213. Here is link to JDK 11 'java' documentation which has "Code Heap State Analytics" section: https://docs.oracle.com/en/java/javase/11/tools/java.html#GUID-7F6FB589-CB59-4B94-BE01-02F48C400243 I am not sure if we should backport this change to jdk 11 - I know it is LTS release but only we (JVM developers) most likely will use this flag. I looked and it seems we can do backport of docs changes too if needed.
28-11-2018
Before I proceed and revert to a Print* option, I would like to point out that there was some documentation associated with the original enhancement. This documentation describes how to use CodeHeap Analysis with UL settings. Is it possible to just change the "how to"? Is it external documentation?
28-11-2018
[~lucy] I hadn't seen that discussion. I would have disagreed with it for this case. In general there shouldn't be any more tty->print but some things aren't nice with UL and this is definitely one of them. I suggest changing to what you had. Send it on hotspot-dev so I get the email.
28-11-2018
Coleen, this is exactly what I had implemented in the first place. Back then, using a Print* option was strongly discouraged, e.g. by Robbin Ehn and Tobias Hartmann. See comments in JDK-8198691, around March 2nd, 2018. So I changed my code to use UL. It's an easy task to revert back to a Print* option. What I would not like to do is flipping back and forth every few months. Thank you, Vladimir, for supporting that "third output type". Not because I suggested it, but because I believe that leads to a good solution.
28-11-2018
Or if this code cache printing is something you want to do outside of UL, why not just add a PrintCodeHeapAnalysis flag and have the output controlled by that and not by UL? We can and do have hybrid of UL and the old PrintX code, and I don't know if there's any good reason to change it for the reasons that Lucy states above. The PrintX flags seem appropriate to keep for this: eg. do this: // CodeHeap State Analytics. // Does also call NMethodSweeper::print(tty) if (PrintCodeHeapAnalysis) { CompileBroker::print_heapinfo(NULL, "all", "4096"); // details } else if (PrintMethodFlushingStatistics) { NMethodSweeper::print(tty); } Just don't have it use UL as the condition.
28-11-2018
We can't close it - we need to fix it one way or an other. Currently there are 2 proposal which I think could be done. Short term solution for this bug could be filter out 'codecache' from -Xlog:all. In long term, and I agree with Lucy, we need 3rd type for big output for which we can't use UL. Like PrintOptoAssembly and others.
27-11-2018
Request help on next steps here for this 8209913 bug From the comments it seems there is no easy solution here because there is no suitable output mechanism for this kind of debugging output! So can we close this bug as 'Won't fix' (similar to other JDK-8204916) ?
22-11-2018
With the deprecation of the -XX:+Print* cmdline arguments, a capability gap was opened. Much of the output previously controlled by -XX:+Print* perfectly fits into the UL scope: - record events that happen "from time to time" - create a single line (or very few) per event - add a time stamp and other decorators - ... But, there is output which does not fit, first of all because it's not directly related to an event, but is the result of some processing. Take the cmdline arguments PrintCompilation (event, suitable for UL) and PrintOptoAssembly (bulky output, not for UL) as opposite examples. To separate concerns, we would need a third method (and destination) to control output, besides UL and JFR. ULraw could be a step in the right direction. But, do we really need to mix such bulky output with the UL stream? We would obscure the original purpose of logging: show the sequence of events on the time line.
03-09-2018
There seems to be a fundamental disconnect here between the basic principle of UL that allows the user to control decorators, and which applies decorators to all logging output, and a perception by the developer that some specific kind of logging not only doesn't benefit from decorators but is harmed by it. Perhaps what we need is an additional "raw" logging API that doesn't include the decorators? Something like a "continuation line" perhaps: log(Trace, Foo)("This is the primary 'introductory' line with decorators"); log_cont(Trace, Foo)("This is a continuation of the primary log line. No decorators and possibly indented"); Won't work well with concurrent log output but better than special casing (which breaks the "Unified" part of UL!)
02-09-2018
There is workaround to redirect logfile using java -Xlog:all=trace:file=trace.log -XX:-DisplayVMOutput -XX:LogFile=trace.log ... It could be used in tests. While it still really confusing to me that people get something in stdout using just java -Xlog:all=trace:file=trace.log
24-08-2018
It is the dup of JDK-8204916
24-08-2018
I've gone through that. You can configure the log tags, but you can't get rid go them. That's at least my understanding. I don't claim to be an UL expert, though. If there is a way, I'm happy to adapt my code.
24-08-2018
The test in the linked bug uses -Xlog:all=trace:file=all.txt to verify a crash that we had with logging. It's going to generate too much output which works with jtreg now, but I think we've seen problems with jtreg and excessive output from tests.
24-08-2018
Maybe there's a way to make the log stream for this output use UL without the tags. You might be able to change the configuration before printing. I don't know exactly so I've added a couple of people as watchers who might. [~pliden] [~rehn] ?
24-08-2018
Hmmm, I clearly understand Coleen's concerns/objections. I even would say I agree. But: my statement - which Tobias cited above - still holds true. Using the log stream, as it works now, is not a feasible option. What could be done? The easiest remedy would be if UL provided a "raw" log stream, basically an output stream without all the UL prefixing. Would such an UL extension destroy fundamental UL design principles? If a raw log stream can't be provided, I see no other option than exempting the "codecache" tag from printing with -Xlog:all. In other words: If you want CodeHeap state analytics, you have to request it specifically. I could live with that. UL in it's current implementation does not provide that possibility, at least to my knowledge. Further comments welcome!
24-08-2018
Lutz, what do you think?
24-08-2018
ILW = Unexpected logging to screen, with -Xlog:all=trace:file=all.log, no workaround = MLH = P4
24-08-2018
The output is from the code heap state analytics (JDK-8198691) and I remember that there were some discussions about where the printing should go: http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2018-March/028476.html "I clearly understand and support the intention to get rid of the Print* command line arguments. Therefore, the PrintCodeHeapState command line argument is gone. You can request the CodeHeap state analytics with the -Xlog:codecache=Trace (vm shutdown) or -Xlog:codecache=Debug (CodeCache full and vm shutdown) switches. The output is directed to tty, not to the log stream. The reason for not using the log stream is simple: UL prefixes every line with a timestamp and the trace tags. Unfortunately, that messes up my formatting big time. The jcmd output, on the other hand, will not have the UL prefixes. I would have to distinguish between UL and jcmd output when formatting. In addition, I do not see a benefit from adding the same UL prefix to thousands of lines."
24-08-2018