Do you trust profilers? I once did too

Profilers are great tools in your toolbox, like debuggers, when solving problems with your Java application (I've been on a podcast on this topic recently). I'll tell you some of their problems and a technique to cope with them in this talk.

There are many open-source profilers, most notably JFR/JMC, and async-profiler, that help you to find and fix performance problems. But they are just software themself, interwoven with a reasonably large project, the OpenJDK (or OpenJ9, for that matter), and thus suffer from the same problems as the typical problems of application they are used to profile.

Transcript

1. Do you trust profilers? I once did too Johannes Bechberger The best JDKTM Krzysztof Ślusarski
2. Image by Yatheesh Gowda from Pixabay Nightmares of a profiler developer Johannes Bechberger’s gruesome tales on Java profiling APIs
5. Client Admin Server Question? Set Question JSON
6. Premature Optimization We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3%. A good programmer will not be lulled into complacency by such reasoning, he will be wise to look carefully at the critical code; but only after that code has been identified. — Donald Knuth “ Source: Jacob Appelbaum, Wikipedia
7. So the event came... ... and the server was overwhelmed
8. Premature Optimization We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3%. A good programmer will not be lulled into complacency by such reasoning, he will be wise to look carefully at the critical code; but only after that code has been identified. — Donald Knuth “ Source: Jacob Appelbaum, Wikipedia
9. Profilers to the rescue
11. Source: Abgedreht Karlsruhe
12. main serverLoop handleQuestionRequest currentQuestion isQuestionEnabled fun main() { ... serverLoop() } fun serverLoop() { while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } } fun handleQuestionRequest(req) { if (isQuestionEnabled()) { emit(currentQuestion().json) } else { emit({}) } } parseJSON parseJSON
14. main serverLoop handleQuestionRequest fun main() { ... serverLoop() } fun serverLoop() { while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } } fun handleQuestionRequest(req) { if (isQuestionEnabled()) { emit(currentQuestion().json) } else { emit({}) } }
15. Debugging Testing Profiling Toolbox
18. Who of you used a profiler?
20. What is profiling? A report on the amounts of time spent in each routine of a program, used to find and tune away the hot spots in it. — The Jargon File “
21. Different Profilers
22. Instrumenting Profilers Inserting instructions into the code automatically fun serverLoop() { logEntry(“serverLoop”) while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } logExit(“serverLoop”) } But JITs?
23. Sampling Profilers fun serverLoop() { while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } }
24. Profilers aren’t rocket science
25. So let’s write our own *ignoring safepoint bias * https://mostlynerdless.de
26. Main agentmain(args) premain(args) Profiler sample sleep Store start store
27. Main agentmain(args) premain(args)
28. Main Class java -javaagent:./target/tiny_profiler.jar=agentArgs ...
29. Normally public static void main(String[] args) { ... } public static void main(String args[]) { ... } void main() { ... }
30. Main Class java -javaagent:./target/tiny_profiler.jar=agentArgs ... public static void agentmain(String agentArgs) { premain(agentArgs); } JVM start later attach attach public static void premain(String agentArgs) { Main main = new Main(); main.run(new Options(agentArgs)); }
31. Main class private void run(Options options) { Thread t = new Thread( Profiler.newInstance(options)); t.setDaemon(true); t.setName("Profiler"); t.start(); } public class Options { Duration interval; Optional<Path> flamePath; boolean printMethodTable; }
32. Profiler sample sleep
33. Profiler public static Profiler newInstance(Options options) { Profiler profiler = new Profiler(options); Runtime.getRuntime() .addShutdownHook( new Thread(profiler::onEnd)); return profiler; }
34. Profiler private void sample() { Thread.getAllStackTraces() .forEach( (thread, st) -> { if (thread.isDaemon()) { return; } store.addSample(st); } }); }
35. StackTraceElement class StackTraceElement { Class<?> declaringClassObject; String classLoaderName; String moduleName; String moduleVersion; String declaringClass; String methodName; String fileName; int lineNumber; }
36. Store
37. Store class Store { Optional<Path> flamePath; Map<String, Long> methodOnTopSampleCount; Map<String, Long> methodSampleCount; long totalSampleCount = 0; Node rootNode = new Node("root"); void addSample(StackTraceElement[] st) void printMethodTable() void storeFlameGraphIfNeeded() }
38. Flamegraphs would be great main serverLoop handleQuestionRequest currentQuestion isQuestionEnabled parseJSON parseJSON
39. Turning traces into flamegraphs parseJSON currentQuestion handleQR serverLoop main private static class Node { final String method; final Map<String, Node> children; long samples = 0; void addTrace(List<String> trace) }
40. Turning traces into flamegraphs parseJSON currentQuestion handleQR serverLoop main main serverLoop handleQR currentQuestion parseJSON 1 1 1 1 1
41. Flamegraphs would be great main serverLoop handleQuestionRequest currentQuestion isQuestionEnabled parseJSON parseJSON
42. Turning traces into flamegraphs parseJSON currentQuestion handleQR serverLoop main main serverLoop handleQR currentQuestion parseJSON 2 2 2 2 2
43. Flamegraphs would be great main serverLoop handleQuestionRequest currentQuestion isQuestionEnabled parseJSON parseJSON
44. Turning traces into flamegraphs currentQuestion handleQR serverLoop main main serverLoop handleQR currentQuestion parseJSON 3 3 3 3 2
45. Flamegraphs would be great main serverLoop handleQuestionRequest currentQuestion isQuestionEnabled parseJSON parseJSON
46. Turning traces into flamegraphs isQuestionEnabled handleQR serverLoop main main serverLoop handleQR currentQuestion parseJSON 4 4 4 3 2 parseJSON isQuestionEnabled parseJSON 1 1
47. Turning traces into flamegraphs main serverLoop handleQR currentQuestion parseJSON 4 4 4 3 2 isQuestionEnabled parseJSON 1 1 main serverLoop handleQuestionRequest currentQuestion isQEnabled parseJSON parseJSON
48. With the power of d3-flame-graph
49. Reality
50. Java/JDK Mission Control Application Performance Monitors, ... Sampling Profiler External VisualVM Netbeans async-profiler Sync Async Forte Analyzer Built-In Java/JDK Flight Recorder 2016 1991 ASGCT 2002 2012 2018 Open Source 2010
51. Obtaining a profile
52. Async Profiler java \ -agentpath:libasyncProfiler.so=start,\ event=cpu,\ file=flame.html,flamegraph \ arguments Download from GitHub
53. JDK Flight Recorder (JFR) java \ -XX:+UnlockDiagnosticVMOptions \ -XX:+DebugNonSafepoints \ -XX:+FlightRecorder \ -XX:StartFlightRecording=filename=file.jfr \ arguments Already included in your JDK 8+
54. Don’t trust them
56. Safepoint fun serverLoop() { while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } } Safepoint requested? Safepoint requested? Safepoint requested? Safepoint requested? Safepoint requested? Yes Stop!
57. Safepoint
58. Please stop, please, when you’re ready. Stop! using Safepoints fully asynchronous Safepoint bias
59. Please stop, please, when you’re ready. Stop! Thread 1 using Safepoints fully asynchronous Safepoint bias with multiple threads
60. AsyncGetCallTrace
61. write writeBytes FileOutputStream::write BufferedOutputStream::flushBuffer BufferedOutputStream::implFlush BufferedOutputStream::flush PrintStream::implWrite PrintStream::write ... PrintStream::println BasicSample::waitForever BasicSample::main JavaCalls::call_helper jni_invoke_static ... _pthread_start ucontext frames num_frames 16 ASGCT_CallTrace Stack walking C/C++ frames Java frames Stack lineno (BCI) 25 method_id &FileOutputStr eam::write ...
62. Tests in the OpenJDK?
64. But its a good one?
65. public class ASGCTBaseTest { // ... public static void main(String[] args) { if (!check()) { throw ...; } } private static native boolean check(); } https://github.com/openjdk/jdk/blob/7d25bf7722f6fbe3633dc718adf6f755e354adb9/test/hotspot/jtreg/serviceability/AsyncGetCallTrace/MyPackage/ASGCTBaseTest.java checked just this method
66. Take profiles with a grain of salt
67. Profilers have bugs, e.g. JDK-8302320 public class Main { public static void main(String[] args) ... { Class<?> klass = Main.class; Method mainMethod = klass.getMethod("test"); mainMethod.invoke(null); } static void test() { javaLoop(); } static void javaLoop() { /* endless loop */ } } missing Flamegraph
68. But surely OpenJ9 is better?
69. 0 Tests for AsyncGetCallTrace
70. Or GetStackTrace?
72. Safepoint biased is bad
73. @Benchmark public void blameSetResult() { byte b = 0; for (int i = 0; i < size; i++) { b += buffer[i]; } setResult(b); /* LINE 38 */ } private void setResult(byte b) { setResult(b == 1); /* LINE 90 */ } @CompilerControl(CompilerControl.Mode.DONT_INLINE) private void setResult(boolean b) { result = b; } http://psy-lob-saw.blogspot.com/2016/02/why-most-sampling-java-profilers-are.html
74. Profilers are just software
75. Tests could better > 1
76. Performance and accuracy could be better
77. Could be safer* *crashes are rare in practice
78. Not designed with safety in mind AGCT is a legacy mechanism that was created for one single unsupported purpose – David Holmes I should add that the CrashProtection mechanism was mainly put in place as a result of having to deliver JFR from JRockit into Hotspot under a deadline, upholding feature-parity. The stack walking code was in really bad shape back then. – Markus Grönlund “ “
79. TDD Test Driven Development
80. TDD
81. RDD Rage Driven Development
82. More Tests
85. Testing Approaches
86. Layered Oracle Instrumentation based traces GetStackTrace ASGCT at safe point AsyncGetCallTrace checks fun serverLoop() { logEntry(“serverLoop”) while (true) { req = ... if (req.isQuestionRequest) handleQuestionRequest(req) ... } logExit(“serverLoop”) }
87. Fuzzing for safety memory AsyncGetCallTrace(..., frame = •, ...)
88. Experimentation technique
89. Profiling Loop Model Hypothesis Evaluation
90. Profilers are great But don’t trust them too much
91. @parttimen3rd on Twitter parttimenerd on GitHub mostlynerdless.de @SweetSapMachine sapmachine.io