RFR: Rework rich PrintCompilation logs

[Vladimir Kozlov]

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:
> 
> 
>     346    C0.0                   4146         3       com.sun.tools.javac.comp.Check::checkAllDefined (66 bytes)
>     346    C0.0    Q0.0    W0.1   4144         3       com.sun.tools.javac.comp.Attr$$Lambda/0x80000004f::<init> (10 bytes)
>     346    C0.6  Q281.9    W0.1   3535      A  2       com.sun.tools.javac.parser.JavacParser::variableDeclaratorId (529 bytes)
>     346    C0.0                   4148         3       com.sun.tools.javac.comp.Check::checkDefaultMethodClashes (383 bytes)
>     346    C0.0    Q0.0    W0.1   4145         3       com.sun.tools.javac.comp.Attr$$Lambda/0x800000052::test (8 bytes)
>     346    C0.4                   2631      A  2       com.sun.tools.javac.jvm.Items$ImmediateItem::numericValue (14 bytes)
>     346    C0.0                   4149         3       com.sun.tools.javac.comp.Check::checkPotentiallyAmbiguousOverloads (79 bytes)
>     346    C0.4  Q295.2    W0.0   2631      A  2       com.sun.tools.javac.jvm.Items$ImmediateItem::numericValue (14 bytes)
>     346    C0.1  ...

I would swap `C` <-> `W`. `C` - compilation time. `W` - wait until put on queue.

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

PR Comment: https://git.openjdk.org/leyden/pull/16#issuecomment-2334658894