java启动慢_一个JAVA应用启动缓慢问题排查 --来自jdk securerandom 的问候

开发某个项目过程中，就需求，搭建了一套测试环境。很快完成！

后来代码中加入了许多新功能，会涉及到反复重启，然后就发现了启动特别慢。这给原本功能就不多的应用增添了许多的负担。

我决定改变这一切！找到启动缓慢的根源，加快启动速度！

思路展开:

1. 启动慢，先看日志，有没有什么异常？

2. 看下是不是gc 有问题，是否占用很长时间？

3. 日志卡住，是否是存在网络请求不通情况？

4. 抓包查看卡住的时候，应用都做什么？

5. 把线程堆栈打印出来，线程都在做什么？把内存dump 出来瞅瞅吧？

6. 实在不行，本地debug不行，换一台测试机试试？

7. 实在不行，远程debug吧？

8. 定位到点后，再来思考解决好的解决方案？

9. 除了解决这个问题，我们还能思考点什么？

让我按思路一个个来看解决过程！

1. 启动慢，先看日志，有没有什么异常？

这个基本上很快就有答案了，看日志，等待期间没有问题！

但是，我们往往会停留在这个阶段较长一段时间，因为我们总想通过其他方式，打印点什么出来！

所以，我们可以会改日志级别，try... catch... 等等一顿操作，然后，才说算了吧，我们想想别的招！我个人还是觉得这种思路是ok的！

2. 看下是不是gc 有问题，是否占用很长时间？

这里可能就会涉及，之前并没有打印gc日志，然后还得回去在启动参数里加上gc输出！姿势如下:

-Xloggc:/opt/logs/a_gc.log -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/logs/ -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -XX:+ParallelRefProcEnabled -XX:ErrorFile=/run/dump/hs_err_pid%p.lo3g -XX:HeapDumpPath=/run/dump

打开后，你看到的gc 日志可能是这样的。 你想从里面发现点什么，好像频繁没有 FullGC 之类的操作，然后又悻悻而归！

10.224: [GC concurrent-root-region-scan-start]10.249: [GC concurrent-root-region-scan-end, 0.0252691secs]10.249: [GC concurrent-mark-start]10.250: [GC concurrent-mark-end, 0.0005479secs]10.250: [GC remark 10.251: [Finalize Marking, 0.0001862 secs] 10.251: [GC ref-proc, 0.0026452 secs] 10.253: [Unloading, 0.0125200 secs], 0.0156381secs]

[Times: user=0.06 sys=0.00, real=0.02secs]10.266: [GC cleanup 33M->33M(1024M), 0.0012152secs]

[Times: user=0.00 sys=0.00, real=0.00secs]13.768: [GC pause (G1 Evacuation Pause) (young), 0.0411037secs]

[Parallel Time:34.5 ms, GC Workers: 4]

[GC Worker Start (ms): Min:13768.7, Avg: 13769.8, Max: 13773.1, Diff: 4.4]

[Ext Root Scanning (ms): Min:0.0, Avg: 1.8, Max: 4.1, Diff: 4.1, Sum: 7.3]

[Update RS (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

[Processed Buffers: Min:0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]

[Scan RS (ms): Min:0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]

[Code Root Scanning (ms): Min:0.0, Avg: 3.1, Max: 8.8, Diff: 8.8, Sum: 12.5]

[Object Copy (ms): Min:21.1, Avg: 28.0, Max: 30.5, Diff: 9.4, Sum: 111.9]

[Termination (ms): Min:0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]

[Termination Attempts: Min:1, Avg: 12.2, Max: 22, Diff: 21, Sum: 49]

[GC Worker Other (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]

[GC Worker Total (ms): Min:29.9, Avg: 33.2, Max: 34.3, Diff: 4.4, Sum: 132.6]

[GC Worker End (ms): Min:13803.0, Avg: 13803.0, Max: 13803.0, Diff: 0.0]

[Code Root Fixup:0.4ms]

[Code Root Purge:0.0ms]

[Clear CT:0.2ms]

[Other:5.9ms]

[Choose CSet:0.0ms]

[Ref Proc:4.6ms]

[Ref Enq:0.1ms]

[Redirty Cards:0.1ms]

[Humongous Register:0.1ms]

[Humongous Reclaim:0.0ms]

[Free CSet:0.9ms]

[Eden:544.0M(544.0M)->0.0B(573.0M) Survivors: 31.0M->41.0M Heap: 575.0M(1024.0M)->41.0M(1024.0M)]

[Times: user=0.13 sys=0.02, real=0.04secs]17.178: [GC pause (G1 Evacuation Pause) (young), 0.0648366secs]

[Parallel Time:59.7 ms, GC Workers: 4]

[GC Worker Start (ms): Min:17177.7, Avg: 17181.1, Max: 17184.4, Diff: 6.6]

[Ext Root Scanning (ms): Min:0.0, Avg: 3.9, Max: 12.7, Diff: 12.7, Sum: 15.6]

[Update RS (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

[Processed Buffers: Min:0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]

[Scan RS (ms): Min:0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.6]

[Code Root Scanning (ms): Min:0.0, Avg: 6.5, Max: 19.4, Diff: 19.4, Sum: 26.0]

[Object Copy (ms): Min:34.9, Avg: 45.5, Max: 51.2, Diff: 16.3, Sum: 182.1]

[Termination (ms): Min:0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]

[Termination Attempts: Min:1, Avg: 16.5, Max: 24, Diff: 23, Sum: 66]

[GC Worker Other (ms): Min:0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]

[GC Worker Total (ms): Min:52.9, Avg: 56.2, Max: 59.5, Diff: 6.6, Sum: 224.8]

[GC Worker End (ms): Min:17237.3, Avg: 17237.3, Max: 17237.3, Diff: 0.0]

[Code Root Fixup:0.5ms]20.648: [GC pause (G1 Evacuation Pause) (young), 0.0653569secs]

[Parallel Time:55.9 ms, GC Workers: 4]

[GC Worker Start (ms): Min:20648.5, Avg: 20650.4, Max: 20652.3, Diff: 3.7]

[Ext Root Scanning (ms): Min:0.1, Avg: 2.9, Max: 9.4, Diff: 9.4, Sum: 11.7]

[Update RS (ms): Min:0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 0.7]

[Processed Buffers: Min:0, Avg: 2.5, Max: 7, Diff: 7, Sum: 10]

[Scan RS (ms): Min:0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 1.3]

[Code Root Scanning (ms): Min:0.0, Avg: 3.2, Max: 10.8, Diff: 10.8, Sum: 12.9]

[Object Copy (ms): Min:39.4, Avg: 46.4, Max: 52.1, Diff: 12.8, Sum: 185.5]

[Termination (ms): Min:0.0, Avg: 0.9, Max: 1.5, Diff: 1.5, Sum: 3.7]

[Termination Attempts: Min:1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]

[GC Worker Other (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

[GC Worker Total (ms): Min:52.1, Avg: 54.0, Max: 55.8, Diff: 3.7, Sum: 215.8]

[GC Worker End (ms): Min:20704.4, Avg: 20704.4, Max: 20704.4, Diff: 0.0]

[Code Root Fixup:0.2ms]

[Code Root Purge:0.0ms]

[Clear CT:0.1ms]

[Other:9.2ms]

[Choose CSet:0.0ms]

[Ref Proc:8.5ms]

[Ref Enq:0.0ms]

[Redirty Cards:0.2ms]

[Humongous Register:0.1ms]

[Humongous Reclaim:0.0ms]

[Free CSet:0.2ms]

[Eden:38.0M(8192.0K)->0.0B(610.0M) Survivors: 43.0M->4096.0K Heap: 83.3M(1024.0M)->54.4M(1024.0M)]

[Times: user=0.24 sys=0.02, real=0.06secs]2826.037: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0101504secs]

[Parallel Time:7.1 ms, GC Workers: 4]

[GC Worker Start (ms): Min:2826037.4, Avg: 2826037.5, Max: 2826037.5, Diff: 0.1]

[Ext Root Scanning (ms): Min:1.7, Avg: 2.0, Max: 2.2, Diff: 0.5, Sum: 7.8]

[Update RS (ms): Min:0.9, Avg: 1.0, Max: 1.0, Diff: 0.1, Sum: 3.8]

[Processed Buffers: Min:7, Avg: 14.2, Max: 25, Diff: 18, Sum: 57]

[Scan RS (ms): Min:0.3, Avg: 0.7, Max: 0.9, Diff: 0.6, Sum: 2.8]

[Code Root Scanning (ms): Min:0.2, Avg: 0.4, Max: 0.8, Diff: 0.6, Sum: 1.5]

[Object Copy (ms): Min:2.7, Avg: 2.9, Max: 3.2, Diff: 0.5, Sum: 11.7]

[Termination (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

[Termination Attempts: Min:1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]

[GC Worker Other (ms): Min:0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]

[GC Worker Total (ms): Min:6.9, Avg: 7.0, Max: 7.0, Diff: 0.1, Sum: 27.8]

[GC Worker End (ms): Min:2826044.4, Avg: 2826044.4, Max: 2826044.4, Diff: 0.0]

[Code Root Fixup:0.0ms]

[Code Root Purge:0.0ms]

[Clear CT:0.1ms]

[Other:2.9ms]

[Choose CSet:0.0ms]

[Ref Proc:1.6ms]

[Ref Enq:0.1ms]

[Redirty Cards:0.0ms]

[Humongous Register:0.0ms]

[Humongous Reclaim:0.0ms]

[Free CSet:0.5ms]

[Eden:354.0M(438.0M)->0.0B(603.0M) Survivors: 4096.0K->11.0M Heap: 408.3M(1024.0M)->61.4M(1024.0M)]

[Times: user=0.03 sys=0.00, real=0.01secs]2826.047: [GC concurrent-root-region-scan-start]2826.054: [GC concurrent-root-region-scan-end, 0.0066742s