SJK - Essential tool for Java plumber

Transcript

1. SJK – Essential Tool for Java Plumber Alexey Ragozin alexey.ragozin@gmail.com
2. We’ve got a problem Something in wrong with Java application SSH to server [appuser@server]# top
3. What next? Command line tools from JDK jps – list Java processes jmap – heap dumps and class histograms jstack – thread dumps jstat – various metrics jinfo – JVM config and sys props access jcmd – some of above in single tool jhsdb – core dump diagnostics (Java 9 and above)
4. What I want? • CPU usage per Java thread • GC events The information is available in JMX since Java 6!
5. Mission Control Thread monitor in Mission Control
6. Inception of SJK ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
7. Inception of SJK > java –jar sjk.jar gc -p 12345 Collecting GC stats ... [GC: PS Scavenge#1235 time: 3ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k] PS Survivor Space: 307 1k-2847k->224k[max:3072k] PS Old Gen: 42657k+440k->43097k[max:349696k] Metaspace: 27703k+0k->27703k PS Eden Space : 164352k-164352k->0k[max:166400k]] [GC: PS Scavenge#1236 time: 7ms interval: 168ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,rate:0. 00kb/s] PS Survivor Space: 224k+1969k->2193k[max:5120k,rate:11722.47kb/s] PS Old Gen: 43097k+128k->43225k[max:349 696k,rate:762.09kb/s] Metaspace: 27718k+0k->27718k[rate:0.00kb/s] PS Eden Space: 164352k-164352k->0k[max:164352k, rate:-978285.71kb/s]] [GC: PS Scavenge#1237 time: 24ms interval: 293ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,rate:0 .00kb/s] PS Survivor Space: 2193k-895k->1297k[max:5120k,rate:-3056.71kb/s] PS Old Gen: 43225k+1832k->45057k[max:3 49696k,rate:6252.61kb/s] Metaspace: 27761k+0k->27761k[rate:0.00kb/s] PS Eden Space: 164352k-164352k->0k[max:16435 2k,rate:-560928.33kb/s]] [GC: PS Scavenge#1238 time: 15ms interval: 519ms mem: Compressed Class Space: 3579k+0k->3579k[max:1048576k,rate:0 .00kb/s] PS Survivor Space: 1297k-113k->1184k[max:1536k,rate:-219.07kb/s] PS Old Gen: 45057k+1032k->46089k[max:34 9696k,rate:1988.62kb/s] Metaspace: 27769k+0k->27769k[rate:0.00kb/s] PS Eden Space: 164352k-164352k->0k[max:168448 k,rate:-316670.52kb/s]] Total PS Scavenge[ collections: 59 | avg: 0.0082 secs | total: 0.5 secs ]PS MarkSweep[ collections: 0 | avg: NaN secs | total: 0.0 secs ] gc
8. ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
9. ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
10. ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
11. ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
12. ttop ttop > java –jar sjk.jar ttop -p 12345 2016-11-07T00:09:50.091+0400 Process summary process cpu=268.35% application cpu=244.42% (user=222.50% sys=21.93%) other: cpu=23.93% GC time=6.28% (young=1.62%, old=4.66%) heap allocation rate 1218mb/s safe point rate: 1.5 (events/s) avg. safe point pause: 43.24ms safe point sync time: 0.03% processing time: 6.39% (wallclock time) [000056] user=17.45% sys= 0.62% alloc= 106mb/s - hz._hzInstance_2_dev.generic-operation.thread-0 [000094] user=17.76% sys= 0.31% alloc= 113mb/s - hz._hzInstance_3_dev.generic-operation.thread-1 [000093] user=16.83% sys= 0.00% alloc= 111mb/s - hz._hzInstance_3_dev.generic-operation.thread-0 [000020] user=16.06% sys= 0.15% alloc= 108mb/s - hz._hzInstance_1_dev.generic-operation.thread-0 [000021] user=15.44% sys= 0.15% alloc= 110mb/s - hz._hzInstance_1_dev.generic-operation.thread-1 [000057] user=14.36% sys= 0.00% alloc= 110mb/s - hz._hzInstance_2_dev.generic-operation.thread-1 [000105] user=13.59% sys= 0.00% alloc= 72mb/s - hz._hzInstance_3_dev.cached.thread-1 [000079] user=13.43% sys= 0.15% alloc= 67mb/s - hz._hzInstance_2_dev.cached.thread-3 [000042] user=10.96% sys= 0.62% alloc= 65mb/s - hz._hzInstance_1_dev.cached.thread-2 [000174] user=10.65% sys= 0.31% alloc= 66mb/s - hz._hzInstance_3_dev.cached.thread-7 [000123] user= 8.96% sys= 0.00% alloc= 55mb/s - hz._hzInstance_4_dev.response [000129] user= 7.72% sys= 0.31% alloc= 21mb/s - hz._hzInstance_4_dev.generic-operation.thread-0 [000168] user= 6.95% sys= 0.62% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-6 [000178] user= 7.57% sys= 0.00% alloc= 32mb/s - hz._hzInstance_2_dev.cached.thread-9 [000166] user= 6.48% sys= 0.46% alloc= 33mb/s - hz._hzInstance_1_dev.cached.thread-5 [000130] user= 6.02% sys= 0.62% alloc= 20mb/s - hz._hzInstance_4_dev.generic-operation.thread-1
13. ttop ttop > java –jar sjk.jar ttop -p 12345 -c 2018-06-19T16:10:50.510+0300 Process summary process cpu=220.80% application cpu=206.79% (user=187.90% sys=18.88%) other: cpu=14.01% thread count: 166 GC time=3.41% (young=3.41%, old=0.00%) heap allocation rate 878mb/s safe point rate: 5.6 (events/s) avg. safe point pause: 6.76ms safe point sync time: 0.07% processing time: 3.75% (wallclock time) [000058] user=14.48% sys= 0.16% wait=50.84/s(84.10%) block= 0.20/s( 0.00%) alloc= 80mb/s - hz._hzInstance_2_dev.gene [000057] user=14.32% sys= 0.16% wait=51.55/s(84.03%) block= 0.20/s( 0.00%) alloc= 76mb/s - hz._hzInstance_2_dev.gene [000022] user=13.69% sys= 0.31% wait=51.95/s(83.96%) block= 0/s( 0.00%) alloc= 80mb/s - hz._hzInstance_1_dev.gene [000128] user=13.53% sys= 0.00% wait= 1.21/s(85.41%) block= 0/s( 0.00%) alloc= 56mb/s - hz._hzInstance_4_dev.resp [000095] user=13.38% sys= 0.00% wait=51.05/s(84.36%) block= 0/s( 0.00%) alloc= 77mb/s - hz._hzInstance_3_dev.gene [000182] user=12.75% sys= 0.63% wait=171.0/s(85.89%) block= 0.10/s( 0.05%) alloc= 61mb/s - hz._hzInstance_3_dev.cach [000021] user=12.28% sys= 0.00% wait=51.35/s(84.00%) block= 0.20/s( 0.00%) alloc= 76mb/s - hz._hzInstance_1_dev.gene [000187] user=11.49% sys= 0.16% wait=143.0/s(87.12%) block= 0/s( 0.00%) alloc= 50mb/s - hz._hzInstance_2_dev.cach [000094] user=11.17% sys= 0.16% wait=52.66/s(84.55%) block= 0.30/s( 0.10%) alloc= 78mb/s - hz._hzInstance_3_dev.gene [000167] user=10.39% sys= 0.00% wait=153.0/s(88.15%) block= 0/s( 0.00%) alloc= 45mb/s - hz._hzInstance_1_dev.cach [000186] user= 7.24% sys= 0.31% wait=126.5/s(91.44%) block= 0/s( 0.00%) alloc= 33mb/s - hz._hzInstance_1_dev.cach [000116] user= 7.08% sys= 0.16% wait=88.57/s(91.20%) block= 0.10/s( 0.00%) alloc= 34mb/s - hz._hzInstance_3_dev.cach [000135] user= 6.61% sys= 0.47% wait=184.9/s(92.36%) block= 0/s( 0.00%) alloc= 15mb/s - hz._hzInstance_4_dev.gene [000189] user= 7.08% sys= 0.00% wait=113.9/s(91.53%) block= 0/s( 0.00%) alloc= 34mb/s - hz._hzInstance_2_dev.cach [000134] user= 5.98% sys= 0.31% wait=193.1/s(93.39%) block= 0/s( 0.00%) alloc= 14mb/s - hz._hzInstance_4_dev.gene
14. All of SJK tools  ttop  gc  jps  hh  mprx  mx  mxdump Sampling profiler  stcap  stcpy  ssa  flame single executable jar (< 1Mib) https://github.com/aragozin/jvm-tools
15. Heap Histogram (hh) > java –jar sjk.jar hh -p 12345 –dead –n 20 # Instances Bytes Type 1: 2923126 119248376 [C 2: 127292 75552608 [B 3: 2367217 56813208 java.lang.String 4: 464272 14856704 java.util.concurrent.ConcurrentHashMap$Node 5: 589853 14156472 info.ragozin.perflab.hazelagg.SliceKey 6: 111178 11562512 java.io.ObjectStreamClass 7: 162932 7820736 java.util.HashMap 8: 325582 7813968 java.lang.StringBuilder 9: 176100 6365688 [Ljava.lang.Object; 10: 98217 6288752 [I 11: 297 5708880 [Ljava.util.concurrent.ConcurrentHashMap$Node; 12: 127056 5082240 java.io.ObjectStreamField 13: 153958 4926656 java.util.HashMap$Node 14: 153933 4925856 com.hazelcast.util.ConcurrentReferenceHashMap$HashEntry 15: 127427 4077664 com.hazelcast.nio.Address 16: 167599 4022376 java.lang.Long 17: 167153 4011672 java.util.ArrayList 18: 81016 3240640 java.math.BigDecimal 19: 80805 3232200 java.util.Collections$SingletonMap 20: 127426 3058224 info.ragozin.perflab.hazelagg.PositionAggregation$CFactory$1 Total 9473688 392379120
16. Heap Histogram (hh) sjk hh = jmap -histo sjk hh --live = jmap -histo:live sjk hh --dead => diff(jmap -histo, jmap -histo:live) sjk hh --deadYoung => Full GC, wait 10 seconds, hh --dead
17. SJK as profiler Capture data Apply filter criteria Visualize Meditate Iterate
18. Thread sampling Task.run() wait() process() getBody() read() parse() handle() load() read() Time encode() wait() process() getBody() read() parse() handle() load() read() encode() wait() process() getBody() read() parse() handle() encode() 10 Task.run 7 3 process() 4 handle() 3 encode() 2 ... 1 ... 1 load() geBody() 2 1 read() parse() 1 3 wait() ...
19. Capture sampling data  sjk stcap – JMX based sampler  VisualVM snapshots  Flight Recorder files  jstack thread dumps
20. Filter samples By thread name -tn ‘.*worker.*’ By timestamp -tr 10:00:00-14:59:59 By stack trace -tf **.jdbc -tf **!**.Unsafe.park https://github.com/aragozin/jvm-tools/blob/master/sjk-core/src/main/resources/org/gridkit/jvmtool/cmd/ssa-help.md
21. Visualize  ssa --print  ssa --histo  ssa --thread-info  ssa --flame (SVG) or flame (HTML)  ssa --categorize
22. ssa --thread-ino > java –jar sjk.jar ssa –f dump.sjk –thread-info Name Count On CPU Alloc RUNNABLE Native main 812 0.0% 4381/s 0.0% 100.0% Reference Handler 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.response 812 1.0% 2917k/s 2.5% 99.8% hz._hzInstance_1_dev.partition-o 812 0.0% 419/s 0.1% 100.0% hz._hzInstance_1_dev.partition-o 812 0.0% 455/s 0.0% 100.0% hz._hzInstance_1_dev.priority-ge 812 0.0% 54/s 0.0% 100.0% hz._hzInstance_1_dev.generic-ope 812 8.1% 46m/s 14.2% 97.9% hz._hzInstance_1_dev.generic-ope 812 8.3% 44m/s 12.1% 98.2% hz._hzInstance_1_dev.SlowOperati 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.event-1 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.event-2 812 0.0% 0/s 0.0% 100.0% hz._hzInstance_1_dev.wait-notify 812 0.0% 88/s 0.0% 100.0% hz._hzInstance_1_dev.migration 812 0.0% 25/s 0.0% 100.0% pool-1-thread-1 812 0.0% 117/s 0.0% 100.0% pool-1-thread-2 812 0.0% 34/s 0.0% 100.0% hz._hzInstance_1_dev.InvocationM 812 0.0% 172/s 0.4% 99.6% hz._hzInstance_1_dev.cached.thre 812 2.5% 11m/s 5.2% 95.6% hz._hzInstance_1_dev.cached.thre 812 4.6% 22m/s 7.1% 94.0% hz._hzInstance_1_dev.IO.thread-i 812 0.3% 1266k/s 100.0% 99.9% hz._hzInstance_1_dev.IO.thread-i 812 0.5% 1240k/s 100.0% 100.0% hz._hzInstance_1_dev.IO.thread-o 812 0.9% 2859/s 100.0% 100.0% hz._hzInstance_1_dev.IO.thread-o 812 1.0% 2744/s 100.0% 100.0%
23. ssa --thread-ino java –jar sjk.jar ssa –f dump.sjk –thread-info -si NAME COUNT CPU SYS ALLOC S:WAITING S:TIMED_WAITING Serialization=**.Object*Stream Name Count On CPU System Alloc WAITING TIMED_WAITING Serialization main 812 0.0% 0.0% 4381/s 0.2% 99.8% 0.0% Reference Handler 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% Finalizer 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.scheduled 812 0.0% 0.0% 1104/s 0.0% 99.9% 0.0% hz._hzInstance_1_dev.response 812 1.0% 0.1% 2917k/s 97.5% 0.0% 0.5% hz._hzInstance_1_dev.partition-o 812 0.0% 0.0% 419/s 99.9% 0.0% 0.0% hz._hzInstance_1_dev.priority-ge 812 0.0% 0.0% 54/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.generic-ope 812 8.1% 0.1% 46m/s 85.8% 0.0% 13.7% hz._hzInstance_1_dev.generic-ope 812 8.3% 0.1% 44m/s 87.9% 0.0% 10.7% hz._hzInstance_1_dev.SlowOperati 812 0.0% 0.0% 0/s 0.0% 100.0% 0.0% hz._hzInstance_1_dev.event-1 812 0.0% 0.0% 0/s 100.0% 0.0% 0.0% hz._hzInstance_1_dev.wait-notify 812 0.0% 0.0% 88/s 0.0% 100.0% 0.0% hz._hzInstance_1_dev.migration 812 0.0% 0.0% 25/s 0.0% 100.0% 0.0% pool-1-thread-1 812 0.0% 0.0% 117/s 3.8% 96.2% 0.0% pool-1-thread-2 812 0.0% 0.0% 34/s 96.2% 3.8% 0.0% hz._hzInstance_1_dev.InvocationM 812 0.0% 0.0% 172/s 0.0% 99.6% 0.0% hz._hzInstance_1_dev.cached.thre 812 2.5% 0.1% 11m/s 18.7% 76.1% 2.2% hz._hzInstance_1_dev.cached.thre 812 4.6% 0.1% 22m/s 25.5% 67.4% 3.7% hz._hzInstance_1_dev.IO.thread-i 812 0.1% 0.1% 105k/s 0.0% 0.0% 0.0% hz._hzInstance_1_dev.IO.thread-o 812 0.9% 0.7% 2859/s 0.0% 0.0% 0.0% hz._hzInstance_2_dev.scheduled 812 0.1% 0.0% 1169/s 0.0% 99.9% 0.0% hz._hzInstance_2_dev.response 812 0.9% 0.0% 2976k/s 97.2% 0.0% 2.7% hz._hzInstance_2_dev.partition-o 812 0.0% 0.0% 461/s 100.0% 0.0% 0.0% hz._hzInstance_2_dev.partition-o 812 0.1% 0.0% 394/s 100.0% 0.0% 0.0%
24. flame Flame graph visualization
25. ssa --flame Flame graph visualization
26. Another flame graph JBoss + Seam + Hibernate
27. Framework oriented analyzis Command sjk ssa -f tracedump.std --categorize -tf **.CoyoteAdapter.service -nc JDBC=**.jdbc Hibernate=org.hibernate "Facelets compile=com.sun.faces.facelets.compiler.Compiler.compile" "Seam bijection=org.jboss.seam.**.aroundInvoke/!**.proceed" JSF.execute=com.sun.faces.lifecycle.LifecycleImpl.execute JSF.render=com.sun.faces.lifecycle.LifecycleImpl.render Other=** Report Total samples 2732050 100.00% JDBC 405439 14.84% Hibernate 802932 29.39% Facelets compile 395784 14.49% Seam bijection 385491 14.11% JSF.execute 290355 10.63% JSF.render 297868 10.90% Other 154181 5.64% 0.00% 10.00% 20.00% 30.00% 40.00% 50.00% 60.00% 70.00% 80.00% 90.00% 100.00% Time Other JSF.render JSF.execute Seam bijection Facelets compile Hibernate JDBC Excel
28. Sample trimming > java –jar sjk.jar ssa -f jboss-10k.std -tt org.hibernate --histo 3064 69% 3064 1 0% org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:264) 2891 65% 2891 0 0% org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1204) 2790 62% 2790 0 0% org.hibernate.internal.SessionImpl.list(SessionImpl.java:1261) 2534 57% 2534 0 0% org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEv 2014 45% 2014 0 0% org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(Ab 1957 44% 1957 1 0% org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushing 1419 32% 1419 2 0% org.hibernate.event.internal.AbstractVisitor.processEntityPropertyValues(AbstractVisitor. 1235 27% 1235 0 0% oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249) 1230 27% 1230 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:249) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:390) 1229 27% 1229 0 0% oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper 1229 27% 1229 0 0% oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:426) 1229 27% 1229 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:171) 1229 27% 1229 0 0% oracle.net.ns.NetInputStream.read(NetInputStream.java:89) 1227 27% 1227 0 0% oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:215) 1225 27% 1225 0 0% oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:566) 1205 27% 1205 0 0% oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:58) 1203 27% 1203 0 0% java.net.SocketInputStream.read(SocketInputStream.java:152) 1203 27% 1203 0 0% java.net.SocketInputStream.read(SocketInputStream.java:122) 1203 27% 1203 0 0% oracle.net.ns.DataPacket.receive(DataPacket.java:105) 1203 27% 1203 1203 27% java.net.SocketInputStream.socketRead0(Native Method) 1203 27% 1203 0 0% oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305) 1203 27% 1203 0 0% oracle.net.ns.Packet.receive(Packet.java:311)
29. Hidden features Custom built sjk  Add commands  Reuse JMX and other utility code sjk as a library  Self sampler  Storing arbitrary events in binary dump  Available though Maven central org.gridkit.jvmtool:sjk-core
30. Hidden features Custom built sjk  Add commands  Reuse JMX and other utility code sjk as a library  Self sampler  Storing arbitrary events in binary dump  Available though Maven central org.gridkit.jvmtool:sjk-core
31. Heap analyzer library  Maven artifact: org.gridkit.jvmtool:hprof-heap  Tested with 150 GiB heap dump  No index files of disk  Based on NetBeans profiler code  Access objects from dump via API  Can work with compressed heap dumps  Can be used for testing (e.g. memory leaks) https://github.com/aragozin/heapunit
32. Thank you Алексей Рагозин alexey.ragozin@gmail.com https://blog.ragozin.info https://training.ragozin.info