[JAVA] Try to make a timeline report of method execution time using JFR API
Introduction
Are you using Java 11? What I like most about this version is that the JFR API has been opened / standardized. So, "[Micro benchmark made with JFR API](https://qiita.com/koduki/items/6e8fbcbafdcc2f743f56#%E3%82%AB%E3%82%B9%E3%82%BF%E3%83%A0%" Custom events like the article "E3% 82% A4% E3% 83% 99% E3% 83% B3% E3% 83% 88% E3% 81% AE% E4% BD% 9C% E6% 88% 90)" You can also easily make.
By the way, have you ever thought about this? "JFR is convenient but different from the information you want to see" "Because it is a binary file, it cannot be linked with Kibana or existing tools" "etc"
I was wondering! It would be convenient if I could check the contents of JFR without using JMC by myself. So let's actually do it. Based on the sampling of the method that can be obtained by JFR, I would like to make the method execution state HTML like APM, which is common.
The source code used this time is below. https://github.com/koduki/jfr-viewer
Try loading JFR
First, let's load the existing JFR. Here, test.jfr is the existing JFR.
As a caveat, it seems that JFR recorded in Java 9 or later is required to read with JFR API.
It's unavoidable because the API has changed, but it's a little annoying. I have to change the production environment to Java 11 as soon as possible!
Going back, use RecordingFile # readAllEvents to read.
There are other methods, but this method is recommended because the return value is List and it is easy to handle with Stream API.
RecordingFile.readAllEvents(path).stream()
Next, we will filter by event name etc. This time, .ExecutionSample corresponds to it.
You can easily find out what the name is by using JMC's Event Browser.
Path path = Paths.get("test.jfr");
RecordingFile.readAllEvents(path).stream()
.filter((e) -> e.getEventType().getName().endsWith(".ExecutionSample"))
Aggregate methods from stack trace
In the following, the stack trace is acquired from the ExecutionSample event and converted into the following data structure.
+Method name 1
-Acquisition time 1
-Acquisition time 2
+Method name 2
-Acquisition time 1
-Acquisition time 2
- ...
Actually, the method call order should be graphed properly, but this time I skipped and kept the stack trace order, making it feel like the parent method is on the top. So it may seem like there is a bug that makes it strange if the same method is called in different hierarchies, but it's by design. If it's a specification, it's a specification!
You can also change the type of method you want to get by playing with ʻaddMthods`. This time I'm trying to play the JFR API, but for example, it may be possible to check by the package name and only verify your own code.
static Tuple2<LinkedHashMap<String, Set<Instant>>, List<Instant>> readMethod(Path path) throws IOException {
var times = new ArrayList<Instant>();
var methods = new LinkedHashMap<String, Set<Instant>>();
RecordingFile.readAllEvents(path).stream()
.filter((e) -> e.getEventType().getName().endsWith(".ExecutionSample"))
.forEach((event) -> {
RecordedStackTrace stacktrace = event.getStackTrace();
if (stacktrace != null) {
times.add(event.getStartTime());
addMthods(methods, stacktrace, event);
}
});
return $(methods, times);
}
static void addMthods(LinkedHashMap<String, Set<Instant>> methods, RecordedStackTrace stacktrace, RecordedEvent event) {
stacktrace.getFrames().stream()
.filter(x -> x.isJavaFrame())
.filter(x -> !x.getMethod().getType().getName().startsWith("jdk.jfr."))
.collect(Collectors.toCollection(ArrayDeque::new))
.descendingIterator()
.forEachRemaining(x -> {
RecordedMethod method = x.getMethod();
String key = method.getType().getName() + "#" + method.getName();
Set<Instant> span = methods.getOrDefault(key, new HashSet<>());
span.add(event.getStartTime());
methods.put(key, span);
});
}
Convert to timeline
Now that we have analyzed JFR, it's OK if we convert it to HTML. From this point on, JFR has become completely irrelevant, and I think the optimal solution is to use CSV as it is and use it as a tool that feels good, but this time it was a pain to create an environment and I wrote it as a trial.
First, convert the data structure as follows.
- [Method name 1, [Start time,ending time]]
- [Method name 2, [Start time,ending time]]
- [Method name 3, [Start time,ending time]]
- [Method name 4, [Start time,ending time]]
However, in the standard profile, the method sample does not show the method end time. There is only time to get the stack trace. Therefore, it is assumed that "methods that exist in consecutive acquisition times are still being executed". This definition is not always correct, but I think it is a fairly usable index for batch delay analysis.
Convert with the following method.
static List<Tuple2<String, List<Tuple2<Instant, Instant>>>> parseSpan(LinkedHashMap<String, Set<Instant>> methods, List<Instant> times) {
var span = new ArrayList<Tuple2<String, List<Tuple2<Instant, Instant>>>>();
for (Entry<String, Set<Instant>> m : methods.entrySet()) {
var key = m.getKey();
var value = m.getValue();
var xs = new ArrayList<Tuple2<Instant, Instant>>();
Instant start = null;
Instant last = null;
for (Instant t : times) {
if (value.contains(t)) {
if (start == null) {
start = t;
}
last = t;
} else {
if (last != null) {
xs.add($(start, last));
}
start = null;
last = null;
}
}
span.add($(key, xs));
}
return span;
}
Report to HTML
Now, let's display the parsed value in HTML on the timeline. I tried using vis.js to make it a timeline.
static void report(List<Tuple2<String, List<Tuple2<Instant, Instant>>>> spans, Path path) throws IOException {
var names = spans.stream().map(xs -> xs._1()).distinct().collect(Collectors.toList());
var htmlNames = names.stream().map(x -> String.format("\"%s\"", x)).collect(Collectors.toList());
var htmlItems = new ArrayList<String>();
int index = 0;
for (int i = 0; i < spans.size(); i++) {
var s = spans.get(i);
String msg = "{ id: %d, group: %d, content: \"\", start: \"%s\", end: \"%s\" }";
for (int j = 0; j < s._2().size(); j++) {
var x = s._2().get(j);
htmlItems.add(String.format(msg, index++, names.indexOf(s._1()), x._1(), x._2()));
}
}
var html = "<!DOCTYPE html>\n"
+ "<html>\n"
+ " <head>\n"
+ " <title>Timeline</title>\n"
+ "\n"
+ " <style type=\"text/css\">\n"
+ " body,\n"
+ " html {\n"
+ " font-family: sans-serif;\n"
+ " }\n"
+ " </style>\n"
+ "\n"
+ " <script src=\"http://visjs.org/dist/vis.js\"></script>\n"
+ " <link\n"
+ " href=\"http://visjs.org/dist/vis-timeline-graph2d.min.css\"\n"
+ " rel=\"stylesheet\"\n"
+ " type=\"text/css\"\n"
+ " />\n"
+ " </head>\n"
+ " <body>\n"
+ " <p>\n"
+ " A Simple Timeline\n"
+ " </p>\n"
+ "\n"
+ " <div id=\"visualization\"></div>\n"
+ "\n"
+ " <script type=\"text/javascript\">\n"
+ " // DOM element where the Timeline will be attached\n"
+ " var container = document.getElementById(\"visualization\");\n"
+ "\n"
+ " // create a data set with groups\n"
+ " var names = [" + String.join(",", htmlNames) + "];\n"
+ " var groups = new vis.DataSet();\n"
+ " for (var g = 0; g < names.length; g++) {\n"
+ " groups.add({ id: g, content: names[g] });\n"
+ " }\n"
+ "\n"
+ " \n"
+ " // Create a DataSet (allows two way data-binding)\n"
+ " var items = new vis.DataSet([" + String.join(",", htmlItems) + "]);\n"
+ "\n"
+ " // Configuration for the Timeline\n"
+ " function customOrder(a, b) {\n"
+ " // order by id\n"
+ " return a.id - b.id;\n"
+ " }\n"
+ "\n"
+ " // Configuration for the Timeline\n"
+ " var options = {\n"
+ " order: customOrder,\n"
+ " editable: true,\n"
+ " margin: { item: 0 }\n"
+ " };\n"
+ "\n"
+ " // Create a Timeline\n"
+ " var timeline = new vis.Timeline(container);\n"
+ " timeline.setOptions(options);\n"
+ " timeline.setGroups(groups);\n"
+ " timeline.setItems(items);\n"
+ " </script>\n"
+ " </body>\n"
+ "</html>";
Files.writeString(path, html);
}
Finally, execute from the main as shown below to complete.
public static void main(String[] args) throws IOException {
var methods = readMethod(Paths.get("test.jfr"));
report(parseSpan(methods._1(), methods._2()), Paths.get("target/test.html"));
}
Click here for the generated HTML. It feels like that!
Summary
I created a timeline report using the JFR API. I feel that if you devise a more UI and drill down, you can make something useful. Alternatively, it may be possible to analyze with fluentd or logstash at any time and send profiler information to Kibana etc., or devise a custom API to support OpenTracing.
It has a built-in low-load profiler, and it's a dream to say that you can play with it freely!
In addition, since I wrote the sample code quite roughly, I feel like I'm doing inefficient things, but I don't care about that. Also, local type inference is convenient after all. It is a great help for cases that use tuples like this time.
Then next year will be Happy Hacking!
Recommended Posts