JDK-8204916 : CompileBroker::print_heapinfo should redirected to log stream.
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11
  • Priority: P4
  • Status: Closed
  • Resolution: Won't Fix
  • Submitted: 2018-06-12
  • Updated: 2019-01-15
  • Resolved: 2018-06-14
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
Currently  CompileBroker::print_heapinfo is called in several places when logging of codecahe is enabled.

However it is always printed to tty even if logging is redirected to file like
./build/linux-x64/images/jdk/bin/java -Xlog:all=trace:file=trace.log
Comments
I agree, let's close this. Please re-open if there are any objections.
14-06-2018

I would suggest to close this bug as Will Not Fix based on reasons we listed and existing workaround.
14-06-2018

It looks like VM allows to specify the same file for trace logging and LogFile: java -Xlog:all=trace:file=trace.log -XX:-DisplayVMOutput -XX:LogFile=trace.log -version Trace logs added at the end of file after codecache info.
14-06-2018

As Lutz said we avoided LogStream in print_heapinfo() because it produces not readable format: [0.117s][debug][class,preorder ] java.lang.Number source: /export/kvn/jdkjdk/build/fastdebug/images/jdk/lib/modules [0.117s][trace][class,loader,data ] Adding k: 0x0000000800012720 java.lang.Number to loader data: 0x00007fb2f8335be0 of <bootloader> [0.117s][trace][module ] Setting package: class: java.lang.Number, package: java/lang, loader: <bootloader>, module: java.base and screws up nicely formatted codecache info output. And as I understand we can't say to LogStream to not do that. If the concern is that we should redirect output into specified file then we can work on it by using other stream output but the same file if possible. Or we can do nothing and use existing '-XX:-DisplayVMOutput -XX:LogFile=heap.log' diagnostic flags combination to catch output into file without output to tty.
14-06-2018

Hi all, we had this discussion back in March when JDK-8198691 was in RFR. See, for example, here: http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2018-March/028574.html We agreed that output as produced by CodeHeap state analytics (can be thousands of lines) is not suitable for he log stream. UL macros are used to trigger the output because -XX:+Print* cmdline flags are deprecated. Some additional reasoning from a mail conversation with Vladimir Kozlov: --- BEGIN ---- I agree that this does not require UL. As I understand we want few places for produced data. - On exit as statistic output - On full codecache - On jcmd request (sending data to jcmd) On 3/20/18 3:44 AM, Schmidt, Lutz wrote: Thank you, Vladimir! The comments in heap.hpp (decls that were moved further down to the "public" area) are unnecessary. It's a SAP habit to leave the stuff (as comment) where it came from. I notice also few commented lines in codeHeapState.hpp: 141, 142, 208. And in codeHeapState.cpp few lines with out->print_cr. Our code stile requires to have 'if' condition and body on different lines. And body should be enclosed in {}. For example, next code in codeHeapState.cpp should be fixed: if (segment_granules && StatArray[ix].stub_count > 0) print_blobType_single(ast, StatArray[ix].type); else print_count_single(ast, StatArray[ix].stub_count); The commented code in codeCache.cpp and java.cpp is not "left over", but intended to serve as coding alternative. With the comments from Tobias and Thomas, I tend to abandon the idea of printing the CodeHeap state analytics to the log stream. I see several reasons: I agree with that. Vladimir - Logging, in my opinion, is to record events that happen from time to time. One event produces a few output lines at most. CodeHeap state analytics is exactly NOT that. - Universal Logging offers control over the "decorators" on the command line. I could not find a way to disable decorators selectively, e.g. in the LogStream ctor. - Universal Logging does not detect '\n' (newline) characters in the output string. That messes up my output big time. - jcmd output is not intended to go to the log stream. - Control over the print destination, as UL offers, would be nice to have. But you can't have everything. Please let me know your opinion. Thanks, Lutz --- END --- Where do we go from here? If Leonid's statement (first line of his comment) is the absolute truth (no discussions), CodeHeap state analytics can't be controlled by UL macros. Leonid's recommended fix was one variant I tried in the course of RFR discussions. It proved unsuitable for the reasons detailled above. Introducing a new -XX:+PrintCodeHeapAnalytics command line parameter was ruled out during RFR discussions (-XX:+Print* is deprecated). Is there another (suitable, supported) way to control/redirect vm output? If no, CodeHeap state analytics can't be triggered by vm events. To reiterate, that vm event itself should be recorded by UL, but not the bulky output from CodeHeap state analytics.
13-06-2018

Thanks [~thartmann] Hi [~lucy], Request your help here. It seems code related to this 8204916 was introduced by JDK-8198691 changes. Assigning this to you now. Please reassign back if any issues. Thanks.
13-06-2018

ILW = Logs wrongly printed in tty instead of in redirect log file; logging, diagnostic issue - if logging redirected to file; none = MLH = P4
13-06-2018

Once LagTarget is checked it is needed to respect all other logging parameters. Fix should be like this: diff -r 075e9982b409 src/hotspot/share/code/codeCache.cpp --- a/src/hotspot/share/code/codeCache.cpp Tue Jun 12 01:31:49 2018 +0200 +++ b/src/hotspot/share/code/codeCache.cpp Tue Jun 12 14:18:31 2018 -0700 @@ -1391,7 +1391,8 @@ if (heap->full_count() == 0) { LogTarget(Debug, codecache) lt; if (lt.is_enabled()) { - CompileBroker::print_heapinfo(tty, "all", "4096"); // details, may be a lot! + LogStream ls(lt); + CompileBroker::print_heapinfo(&ls, "all", "4096"); // details, may be a lot! } } } diff -r 075e9982b409 src/hotspot/share/runtime/java.cpp --- a/src/hotspot/share/runtime/java.cpp Tue Jun 12 01:31:49 2018 +0200 +++ b/src/hotspot/share/runtime/java.cpp Tue Jun 12 14:18:31 2018 -0700 @@ -319,7 +319,8 @@ // Does also call NMethodSweeper::print(tty) LogTarget(Trace, codecache) lt; if (lt.is_enabled()) { - CompileBroker::print_heapinfo(NULL, "all", "4096"); // details + LogStream ls(lt); + CompileBroker::print_heapinfo(&ls, "all", "4096"); // details } else if (PrintMethodFlushingStatistics) { NMethodSweeper::print(tty); } @@ -387,7 +388,8 @@ // Does also call NMethodSweeper::print(tty) LogTarget(Trace, codecache) lt; if (lt.is_enabled()) { - CompileBroker::print_heapinfo(NULL, "all", "4096"); // details + LogStream ls(lt); + CompileBroker::print_heapinfo(&ls, "all", "4096"); // details } else if (PrintMethodFlushingStatistics) { NMethodSweeper::print(tty); }
12-06-2018