Is Your Profiler Speaking the Same Language as You?

This session was given at JavaOne 2015

Profilers are absolute beasts. They might prove useful for pinpointing the performance issues in your Java applications, and with profilers, developers have the good fortune to be able to find the root cause of an issue at hand. However, it requires effort to actually comprehend the data collected by a profiler. Due to the inherent complexity of the data, you have to understand how it is collected—and thus understand how the profiler actually works. This presentation goes through the classic profiler features and answers questions such as What is a hotspot? What is the difference between sampling and instrumentation from the profiler’s point of view? What are the problems with either of those methods? What is the time budget of the application? And more.

Transcript

1. IS YOUR PROFILER SPEAKING THE SAME LANGUAGE AS YOU? SIMON MAPLE @SJMAPLE
2. ABOUT ME SIMON MAPLE @SJMAPLE
3. SIMON MAPLE @SJMAPLE VIRTUAL JUG FOUNDER LONDON JUG CO-ORGANISER JAVA CHAMPION JAVAONE ROCKSTAR SPEAKER REBELLABS AUTHOR ABOUT ME
4. 4 MONITORING TOOLS
5. PROFILERS 5
6. TESTING TOOLS 6
8. RebelLabs reports 8
9. 9 source: http://zeroturnaround.com/rebellabs/developer-productivity-report-2015-java-performance-survey-results/
10. 10 source: http://zeroturnaround.com/rebellabs/developer-productivity-report-2015-java-performance-survey-results/
11. 11 source: http://zeroturnaround.com/rebellabs/developer-productivity-report-2015-java-performance-survey-results/
12. APPLICATION PERFORMANCE 12
15. PROFILING CPU TRACING SAMPLING MEMORY USAGE ALLOCATION WHAT DOES PROFILING COVER?
16. PROFILING CPU TRACING SAMPLING MEMORY USAGE ALLOCATION WHAT DOES PROFILING COVER?
17. WHAT IS A SAMPLE?
18. THREAD DUMP: CTRL+BREAK ON WINDOWS KILL -3 PID ON *NIX "http-nio-8080-exec-1" #40 daemon prio=5 os_prio=31 tid=0x00007fd7057ed800 nid=0x7313 runnable java.lang.Thread.State: RUNNABLE at o.s.s.p.w.OwnerController.processFindForm(OwnerController.java:89) at s.r.NativeMethodAccessorImpl.invoke0(Native Method) at s.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at s.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at j.l.r.Method.invoke(Method.java:497) WHAT IS A SAMPLE?
21. SAMPLING INTERVAL: 20MS SAMPLE COUNT: 4
22. SAMPLING INTERVAL: 1MS SAMPLE COUNT: 100+
23. SAMPLING main() foo() bar() KeyserSöze()
24. 24 SAFEPOINTS
25. SAMPLING main() foo() bar() KeyserSöze()
26. SAFEPOINT BIAS SAFEPOINTS main() foo() bar() KeyserSöze()
27. SAFEPOINT BIAS SAFEPOINTS main() foo() bar() KeyserSöze()
28. CAN IT BE TAMED?
29. TAMING SAFEPOINT BIAS Java Mission Control Proprietary protocol Java 7u40 Honest Profiler JVMTI AsyncGetCallTrace https://github.com/RichardWarburton/honest-profiler
30. JAVA.UTIL IS HOT?
31. java.util is hot? :)
34. 34 TRACING (INSTRUMENTATION)
35. public  void  businessMethod()  {
    long  start  =  System.currentTimeMillis();   
    work();   
    Profiler.log(System.currentTimeMillis()-­‐start);   } TRACING
36. public  void  businessMethod()  {
    long  start  =  System.nanoTime();   
    work();   
    Profiler.log(System.nanoTime()-­‐start);
 } TRACING
37. public  void  businessMethod()  {
    Profiler.start(“businessMethod”);      try  {          work();      }  finally  {
        Profiler.log("businessMethod");
    }
 } TRACING
38. SYSTEM.NANOTIME SYSTEM.CURRENTTIMEMILLIS PARALLEL THREAD SLEEP-WAKEUP-UPDATE YIELD-WAKEUP-UPDATE BUSY-LOOP-UPDATE TIMING
39. class  Profiler  {   
    Loop  loop;
 
    public  static  void  start(String  method)  {
        long  now  =  loop.getTime();          …
    }  
40. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          public  final  long  getTime()  {
                return  time;
        }  
41. NANO SECONDS Reading memory is not free. It takes cycles = nanoseconds Each (software) layer is not free. JVM, JNI, OS, HW http://shipilev.net/blog/2014/nanotrusting-nanotime/ Nanotrusting the NanoTime
42. NANO SECONDS PUT INTO PERSPECTIVE GRANULARITY_NANOTIME: 26.300 +- 0.205 NS LATENCY_NANOTIME: 25.542 +- 0.024 NS GRANULARITY_NANOTIME: 29.322 +- 1.293 NS LATENCY_NANOTIME: 29.910 +- 1.626 NS GRANULARITY_NANOTIME: 371.419 +- 1.541 NS LATENCY_NANOTIME: 14.415 +- 0.389 NS LINUX SOLARIS WINDOWS http://shipilev.net/blog/2014/nanotrusting-nanotime/ Nanotrusting the NanoTime
43. SLEEP TIMER: TIME-SLICING & SCHEDULING MINIMUM SLEEP TIMES: Win8: 1.7 ms (1.0 ms using JNI + socket poll) Linux: 0.1 ms OS X: 0.05 ms VirtualBox + Linux: don’t ask :) Still uses 25-50% of CPU core YIELD? Windows scheduler skips yielded threads in case of CPU starvation
44. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          private  void  sleep()  {
            if  (!MiscUtil.isWindows())  {
                  Thread.yield();
            }
        }
45. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          private  void  sleep()  {
            if  (!MiscUtil.isWindows())  {
                  Thread.yield();
            }
        }
46. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          private  void  sleep()  {
            if  (!MiscUtil.isWindows())  {
                  Thread.yield();
            }
        }
47. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          private  void  sleep()  {
            if  (!MiscUtil.isWindows())  {
                  Thread.yield();
            }
        }
48. main() foo() bar() baz() TRACING
49. main() foo() bar() baz() 2 3 4 TRACING
50. main() foo() bar() baz() 2 3 5 boo() TRACING
53. PERFORMANCE PIPELINE
54. 54 source: http://zeroturnaround.com/rebellabs/developer-productivity-report-2015-java-performance-survey-results/
55. 55 1. Functionality 2. Quality 3. Performance 4. Security THE SOFTWARE MANTRA
56. 56 1. Functionality 2. Quality 3. Performance 4. Security THE SOFTWARE MANTRA
57. 57 1. Functionality - MAKE IT WORK 2. Quality 3. Performance 4. Security THE SOFTWARE MANTRA
58. 58 1. Functionality - MAKE IT WORK 2. Quality - MAKE IT WORK WELL 3. Performance 4. Security THE SOFTWARE MANTRA
59. 59 1. Functionality - MAKE IT WORK 2. Quality - MAKE IT WORK WELL 3. Performance - MAKE IT WORK FAST 4. Security THE SOFTWARE MANTRA
60. 60 1. Functionality - MAKE IT WORK 2. Quality - MAKE IT WORK WELL 3. Performance - MAKE IT WORK FAST 4. Security - ? ? ? ? ? ? ? ? THE SOFTWARE MANTRA
61. 61 1. Functionality - MAKE IT WORK 2. Quality - MAKE IT WORK WELL 3. Performance - MAKE IT WORK FAST 4. Security - MAKE IT WORK SECURELY THE SOFTWARE MANTRA
62. 62 1. Functionality - MAKE IT WORK 2. Quality - MAKE IT WORK WELL 3. Performance - MAKE IT WORK FAST 4. Security - MAKE IT WORK SECURELY THE SOFTWARE MANTRA
63. 63 TOP 5 PERFORMANCE ISSUES source: http://zeroturnaround.com/rebellabs/developer-productivity-report-2015-java-performance-survey-results/
65. 65 Reactive - Wait until an issue occurs, then resolve it as quickly as possible. Proactive - prevent POTENTIAL issues from EVER occurring. REACTIVE OR PROACTIVE?
66. 66 THE PIPELINE
67. INTRODUCING…
68. 68 FREE STUFF! 0t.ee/javaone-jr 0t.ee/javaone-xr