Con-FESS 2015 - Is Your Profiler Speaking To You?

Transcript

1. Is your profiler speaking to you? Anton Arhipov
2. @antonarhipov Anton Arhipov
5. Batch / ETL Input: ~10k rows Output: ~20M rows j.u.Date / j.u.Calendar Java 1.4 HP-UX Initial execution time: 25 hours :-( After optimizations: 10 hours After redesign: 30 minutes :-) 2005 My Story
6. That moment when you look smart, but feel stupid
7. https://twitter.com/shipilev/status/578193813946134529
8. A B C D E Performance Code complexity
9. Improving Optimizing Last 5% Last 1% A B C D E
10. Profiling CPU Tracing Sampling Memory Usage Allocation We are only talking about this part today
11. JVM has ability to produce thread dump: Press 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) Sampling
12. Sampling interval : 20 ms Sample count: 4
13. Sampling interval : 1 ms Sample count: 100+
14. Sampling main() foo() bar() baz() never captured :(
15. Safepoint bias Safepoints main() foo() bar() baz()
16. Safepoint bias Safepoints main() foo() bar() baz()
17. Taming safepoint bias Java Mission Control Proprietary protocol Java 7u40 Honest Profiler https://github.com/RichardWarburton/honest-profiler AsyncGetCallTrace JVMTI NB! not documented
18. java.util is hot? :)
19. java.util is hot? :)
20. public  void  businessMethod()  {
    long  start  =  System.currentTimeMillis();
    work();
    Profiler.log(System.currentTimeMillis()-­‐start);   } Tracing (Instrumentation)
21. Tracing public  void  businessMethod()  {
    long  start  =  System.nanoTime();
    work();
    Profiler.log(System.nanoTime()-­‐start);
 }
22. Tracing public  void  businessMethod()  {
    Profiler.start(“businessMethod");      try  {
        work();
    }  finally  {
        Profiler.log("businessMethod");
    }
 }
23. System.nanoTime System.currentTimeMillis Parallel thread updating easily accessible memory location sleep-wakup-update yield-wakup-update busy-loop-update
24. class  Profiler  {   
    Loop  loop;
 
    public  static  void  start(String  method)  {
        long  now  =  loop.getTime();          …
    }  
25. public  class  Loop  implements  Runnable  {
        private  volatile  long  time;
        public  void  run()  {
                while  (running)  {
                        time  =  System.nanoTime();
                        sleep();
                }
        }          public  final  long  getTime()  {
                return  time;
        }   Busy Loop
26. Nano seconds put into perspective 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
27. Nano seconds put into perspective http://shipilev.net/blog/2014/nanotrusting-nanotime/ Nanotrusting the NanoTime 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
28. 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
29. 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();
            }
        } Busy Loop
30. 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();
            }
        } Busy Loop
31. Busy Loop 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();
            }
        }
32. 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();
            }
        } Busy Loop
33. main() foo() bar() baz() Tracing relatively higher overhead for fast methods :(
34. Tracing main() foo() bar() baz() 2 3 4
35. Tracing main() foo() bar() baz() 2 3 5 boo() Balance shift due to tracing overhead
39. Database access Web Services RMI Various application layers 3rd-party components HTTP session Exceptions Caches File system access View rendering Serialization GC What else? What are your building blocks?
40. Questions you should be asking …….. …….. …….. ……..
41. Questions you should be asking Where was most of the time spent? How many SQL queries were executed? How much time did the external calls take? What’s my HTTP session state? Is caching working properly? Is there any excessive work done by the app?
42. Most improvement gained here! This is where we should focus first! A B C D E