Record build details to Java FlightRecorder, rather than SpeedTracer #10194
Conversation
Adds a simple JFR event and util class, and uses it from two places in the compiler, plus updates SpeedTracerLogger to write all logs to it. The output is pretty terrible (turns out we almost definitely want specialized Event types per use case, as well as carefully structured categories and so on), but you definitely can see the structure of the compile if you work at it. Edited samples to enable jfr and speedtracer (with one worker). Fixed a confusingly labeled event for DuplicateClinitRemover, and edited a few other keys as well.
* optstats now write jfr events * js passes should log change counts, instead of "1" * neither loop should keep lists of unused stats * inline java loop to match js slightly better * clean up return type to match usage * remove speedtracer events where optstats has it covered * inline most visiblefortesting methods away, to be clear about the optimization context in use
This reverts commit c86870c.
|
This patch has gone through a few iterations as I learned both how these events are used, and also how JFR itself works. I think this is roughly on the right track, but open to feedback. Currently failing CI due to a Java 17 issue. This has to do with the SettingDefinition type I've created, which might need to be removed (made into a system property perhaps?), or maybe we let Java 17 run with --release=17. This setting is intended to support developers disabling those events to restrict what source code a jfr log might include, so that traces can be submitted with bug reports without concerns about confidential information being shared. I'm not confident in the package approach, should events be closer to the producer, or keep them in a single package. Closer to the producer (especially as one-off static inner classes) lowers friction to more detail in specific event types, but may also make reuse harder where it is appropriate, and may make Java 8 / 9+ compat harder (since these classes can only be used in Java 9+ environments). With all of the try-with-resources blocks, this patch is mostly easier to read with whitespace disabled. A handful of events were recorded more than once, so I've removed them. Technically, there is support in JFR for "relational" fields that link events, but no event viewer I've tried yet does anything constructive with them. As such, I've tried to avoid "parent" events except where there is some detail that is better just expressed once when looking at the event timeline. So far, "Java JFR Profiler" is my favorite viewer for these events, which happens to be based on Firefox's profiler - there's a certain symmetry to transitioning from a Chrome plugin to part of firefox - and if I'm not mistaken, this plugin functions in IJ by running in an embedded chrome instance, so we've really come full circle. On a meta note: the only actionable information I have so far from looking at traces is that moderate sized apps run more than 9 Java loops, so it is a little silly to have the max optimization level be 9. There do tend to be fewer JS loops though. Finer grained control of loops might make sense, or a tool that quickly runs just 1, just 2, just 3 loops and compares output size to elapsed time. |
|
Log with this enabled (as part of the ant samples command): Output is available at https://colinalworth.com/showcase.jfr |
|
Note that due to #10195, this can no longer build as it stands - taking away Java 11 features from all of gwt-user just so GWT servlet can run on old JDKs means we can't use JFR in generators. There are only 6 events here that will get lost (all are just named events, no other data attached), but it seems a shame to outright remove them. That's the easiest option though. Could make it part of the GeneratorContext, but there's a fair bit of indirection for some of these to be used that way. Apparently Could also set up a serviceloader or the like and make a new Java8 compatible SimpleEvent-lite that delegates to the real impl, so that the code can be compiled under Java 8, but will only effectively run with Java 11+. This seems like the most compatible option, so I'll try it quickly, but probably will confine us somewhat in future instrumentation options. Edit: it was a little easier than that, since gwt-user depends on gwt-dev... we just can't reference at compile time types that are part of Java9+ if we use release=8, but we can still reference types compiled with java9+. Added a note in the class to explain why this hack is in place. |
|
|
||
| @Override | ||
| public void close() { | ||
| event.close(); |
There was a problem hiding this comment.
Shouldnt this call end instead of close, what I see is that close will call commit from the abstract class, but if we are closing the event, should we still be able to do more commits later?
There was a problem hiding this comment.
When you call commit, that calls end for you if necessary.
https://docs.oracle.com/en/java/javase/21/docs/api/jdk.jfr/jdk/jfr/Event.html#commit()
| fragment++; | ||
| return toReturn; | ||
| } | ||
| event.end(); |
There was a problem hiding this comment.
So here now it used to end the event, but now it just commit it. Is this a change in the how SpeedTracer vs JFR handling things. see my comment on SimpleEvent.
There was a problem hiding this comment.
In short, yes. Since (as above) commit() calls end(), we get an end() automatically here - and while speedtracer has its own separate "write the buffer to disk" thread, when we call commit() we leave it to jfr to write when it wants to.
| SpeedTracerLogger.start(CompilerEventType.WRITE_SYMBOL_MAPS); | ||
| ByteArrayOutputStream out = new ByteArrayOutputStream(); | ||
| for (CompilationResult result : artifacts.find(CompilationResult.class)) { | ||
| try (SimpleEvent ignored = new SimpleEvent("Write SymbolMaps")) { |
There was a problem hiding this comment.
I don't really want to have a single big file of constants - but maybe constants for event names at the top of each class that uses simple events?
|
One thing I noticed is that Events creation now has 3 different forms, using SimpleEvent, Typed events living inside the package where they are used, and some uses a factory method, feels inconsistent, also for SimpleEvent name instances even when the name will appear only in one place I still think keeping them as constants in one place - Maybe the SimpleEvent class itself- might help getting a better picture on what events are being tracked and gives a better starting point to whoever is looking at the part of code. |
Right - I'm not sure what pattern to follow, was hoping for review feedback on either what other projects do, or what seems best here. I should add some of this to the PR/commit description, but my basic thoughts were something like this:
As I worked then I came to this rough plan:
I don't love the idea of constants as enums or just in one place like SpeedTracer did - it doesn't help the JFR review work at all, it means a single jar that all other jars have to depend on which either just has the event class and all the constants in it, or a lot more besides (or... just one giant gwt-dev with everything, which is what I'm really trying to avoid). It does have the benefit of making messages consistent, but I'm not sure making them consistent is that important for the few times users will be looking at this? On the other hand, if we find that this is getting used (unlike SpeedTracer, apparently), we can revisit and refine further - more strongly typed events, more detail gathered. |
2 participants
Replaces deprecated SpeedTracer with custom FlightRecorder event types. These events are roughly modeled to fit the old SpeedTracer use cases, though some liberties were taken for legacy dev mode events. Most cases just use
SimpleEvent, providing a string name and the start/duration - sufficient for the old SpeedTracer use cases with any JFR event viewer.Added missing event recording to some compiler passes, and tried to simplify the API for passes to reduce necessary entrypoints, simplify return types. JS optimization passes now accurately record the changes they make, rather than 1 for "changes made" and 0 for "no changes. Both Java and JS optimization loops have been made consistent with each other, providing better metrics on what work is being done and better control on how much the compiler should even try to optimize (which incidentally should provide a workaround in the compiler itself for #9840).
Fixes #10007