Integrated: Rework rich PrintCompilation logs

[Aleksey Shipilev]

On Fri, 6 Sep 2024 18:49:53 GMT, Aleksey Shipilev <shade at openjdk.org> wrote:

> I have been studying javac benchmark behavior, and current `PrintCompilation` logs are very useful to figure out how much time is spent in creation, queueing, work time for each task. Current logs are quite a bit confusing, though:
>  - The columns are misindented
>  - The precision is too low to capture short events: most of the times are zero
>  - Output seems to rely on "now" timestamp, which depends on _when_ we print
>  
> This PR reworks the logs to be more straightforward.
> 
> Example before:
> 
> 
>    S296 C0 Q229 3531      A  2       com.sun.tools.javac.parser.JavacParser::typeName (37 bytes)
>    S296 C0 Q245 2030      A  2       com.sun.tools.javac.tree.TreeInfo::innermostType (102 bytes)
>    S296 C0 Q0 4169         3       com.sun.tools.javac.comp.Flow$AliveAnalyzer$$Lambda/0x800000105::accept (12 bytes)
>    S296 C0 Q245 2042      A  2       com.sun.tools.javac.tree.JCTree$JCPrimitiveTypeTree::accept (9 bytes)
>    S296 C0 Q0 4170         3       com.sun.tools.javac.comp.Flow$AssignAnalyzer$$Lambda/0x800000108::accept (12 bytes)
>    S296 C0 Q0 4171         3       com.sun.tools.javac.comp.Flow$FlowAnalyzer$$Lambda/0x80000010a::accept (12 bytes)
>    S296 C0 Q245 2098      A  2       com.sun.tools.javac.code.Symbol$RecordComponent::getOriginalAnnos (24 bytes)
>    S296 C0 Q244 2348      A  2       com.sun.tools.javac.tree.TreeCopier::visitPrimitiveType (24 bytes)
>    S296 C0 Q244 2349      A  2       com.sun.tools.javac.tree.TreeCopier::visitPrimitiveType (7 bytes)
> 
> 
> Example after:
> 
> 
>     386    W0.0  Q313.7    C0.2   3524   !  A  2       com.sun.tools.javac.parser.JavacParser::literal (655 bytes)
>     386                           3858         3       java.util.stream.MatchOps$$Lambda/0x800000030::<init> (15 bytes)   made not entrant
>     386    W0.1                   2416      A  1       com.sun.tools.javac.comp.Infer$CheckInst::boundsToCheck (5 bytes)
>     386    W0.0    Q0.1    C0.2   4155         4       java.util.stream.MatchOps$$Lambda/0x800000030::<init> (15 bytes)
>     386    W0.1  Q332.7    C0.0   2416      A  1       com.sun.tools.javac.comp.Infer$CheckInst::boundsToCheck (5 bytes)
>     386    W0.2                   2902      A  2       com.sun.tools.javac.code.ClassFinder::classFileNotFound (13 bytes)
>     386    W0.2  Q327.9    C0.0   2902      A  2       com.sun.tools.javac.code.ClassFinder::classFileNotFound (13 bytes)
>     386    W0.0                   3527      A  2       com.sun.tools.javac.parser.JavacParser::parseExpression (6 bytes)
>     386    W0.0  Q314.2    C0...

This pull request has now been integrated.

Changeset: d7bd0ccc
Author:    Aleksey Shipilev <shade at openjdk.org>
Committer: Vladimir Kozlov <kvn at openjdk.org>
URL:       https://git.openjdk.org/leyden/commit/d7bd0cccea97a9cee9810f58e07a5b2d0b474d08
Stats:     40 lines in 3 files changed: 23 ins; 0 del; 17 mod

Rework rich PrintCompilation logs

Reviewed-by: kvn

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

PR: https://git.openjdk.org/leyden/pull/16