JVM optimization
This is a note of jvm optimization of a production service.
Linux system tool
top
Use top to view process status:
$ top
top - 10:55:37 up 1234 days, 20:33, 1 user, load average: 26.61, 31.80, 35.25
Tasks: 485 total, 2 running, 483 sleeping, 0 stopped, 0 zombie
%Cpu(s): 82.8 us, 9.4 sy, 0.0 ni, 5.6 id, 0.0 wa, 0.0 hi, 2.2 si, 0.0 st
KiB Mem : 26359952+total, 10300115+free, 79046432 used, 81551928 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 17903020+avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
35253 work 20 0 27.3g 10.6g 11532 S 817.5 4.2 795248:54 java
38200 work 20 0 27.2g 10.4g 11480 S 774.6 4.1 782100:51 java
33196 work 20 0 27.2g 10.5g 11496 S 663.0 4.2 767660:17 java
38110 work 20 0 27.2g 10.4g 11496 S 368.3 4.2 717635:28 java
38489 work 20 0 27.2g 10.5g 11516 S 286.1 4.2 797625:38 java
198487 work 20 0 134384 18352 888 R 64.0 0.0 0:03.06 netstat
120786 work 20 0 21.7g 4.8g 7032 S 15.5 1.9 410952:23 java
120732 work 20 0 21.7g 4.8g 6996 S 11.2 1.9 346910:48 java
120726 work 20 0 21.7g 4.8g 6980 S 10.2 1.9 355160:19 java
120838 work 20 0 21.7g 4.9g 7244 S 5.6 1.9 407095:04 java
198488 work 20 0 113540 976 820 S 2.3 0.0 0:00.13 awk
197696 root 20 0 0 0 0 S 0.7 0.0 0:00.34 kworker/15:2
10 root 20 0 0 0 0 S 0.3 0.0 10342:55 rcu_sched
161 root 20 0 0 0 0 S 0.3 0.0 947:20.63 ksoftirqd/30
18515 root 20 0 573816 14272 2968 S 0.3 0.0 250:14.40 tuned
View a specific process:
$ top -Hp 35253
top - 10:58:20 up 1234 days, 20:35, 1 user, load average: 28.47, 31.40, 34.61
Threads: 968 total, 3 running, 965 sleeping, 0 stopped, 0 zombie
%Cpu(s): 57.2 us, 6.7 sy, 0.0 ni, 33.8 id, 0.0 wa, 0.0 hi, 2.3 si, 0.0 st
KiB Mem : 26359952+total, 10287185+free, 79023616 used, 81704048 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 17905331+avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
35309 work 20 0 27.3g 10.6g 11532 S 71.6 4.2 8159:47 G1 Conc#5
35306 work 20 0 27.3g 10.6g 11532 S 69.3 4.2 8159:23 G1 Conc#2
35308 work 20 0 27.3g 10.6g 11532 S 69.3 4.2 8160:05 G1 Conc#4
35307 work 20 0 27.3g 10.6g 11532 S 69.0 4.2 8160:03 G1 Conc#3
35257 work 20 0 27.3g 10.6g 11532 S 68.3 4.2 8160:12 G1 Conc#0
35305 work 20 0 27.3g 10.6g 11532 S 68.3 4.2 8159:48 G1 Conc#1
35375 work 20 0 27.3g 10.6g 11532 S 13.9 4.2 589:09.39 http-nio-0.0.0.
35469 work 20 0 27.3g 10.6g 11532 S 7.9 4.2 29171:28 http-nio-8442-P
35470 work 20 0 27.3g 10.6g 11532 S 6.3 4.2 27653:44 http-nio-8442-A
189160 work 20 0 27.3g 10.6g 11532 R 6.3 4.2 587:47.64 http-nio-0.0.0.
35457 work 20 0 27.3g 10.6g 11532 S 5.0 4.2 17071:54 http-nio-0.0.0.
35458 work 20 0 27.3g 10.6g 11532 S 4.0 4.2 14972:14 http-nio-0.0.0.
11726 work 20 0 27.3g 10.6g 11532 S 2.0 4.2 487:53.72 http-nio-0.0.0.
35348 work 20 0 27.3g 10.6g 11532 S 1.7 4.2 12352:21 pulsar-timer-5-
35288 work 20 0 27.3g 10.6g 11532 S 1.3 4.2 805:44.45 GC Thread#6
35304 work 20 0 27.3g 10.6g 11532 S 1.3 4.2 804:14.37 GC Thread#22
35284 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 806:37.70 GC Thread#2
35285 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 806:05.20 GC Thread#3
35286 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 805:39.92 GC Thread#4
35287 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 804:21.61 GC Thread#5
35290 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 806:57.15 GC Thread#8
35293 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 807:10.16 GC Thread#11
35294 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 804:48.06 GC Thread#12
35297 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 806:14.76 GC Thread#15
35299 work 20 0 27.3g 10.6g 11532 S 1.0 4.2 806:53.58 GC Thread#17
ps
Use ps:
$ ps -ef | grep java
work 33196 1 99 2023 ? 533-03:00:51 /home/work/dynamic-raft/jdk-11/bin/java -Xms8192m -Xmx8192m -Dspring.profiles.active=prod-x9 -Dserver.port=8081 -Dserver.httpsPort=8441 -Draft.id=10.19.24.7-6001 -Dmanagement.server.port=9441 -jar dynamic-service-1.1.1.jar
work 35253 1 99 2023 ? 552-06:53:20 /home/work/dynamic-raft/jdk-11/bin/java -Xms8192m -Xmx8192m -Dspring.profiles.active=prod-x9 -Dserver.port=8082 -Dserver.httpsPort=8442 -Draft.id=10.19.24.7-6002 -Dmanagement.server.port=9442 -jar dynamic-service-1.1.1.jar
...
Or use jps:
$ jps
35253 jar
38200 jar
201882 Jps
38489 jar
33196 jar
38110 jar
$ ps -mp 35253 -o THREAD,tid,time | sort -rn
work 5.7 19 - ep_pol - - 35469 20-06:12:44
work 5.4 19 - - - - 35470 19-04:54:46
work 3.3 19 - ep_pol - - 35457 11-20:32:40
work 2.9 19 - inet_c - - 35458 10-09:32:49
work 2.4 19 - futex_ - - 35348 8-13:52:37
work 155 - - - - - - 552-07:28:01
work 1.5 19 - futex_ - - 35309 5-16:02:00
work 1.5 19 - futex_ - - 35308 5-16:02:18
work 1.5 19 - futex_ - - 35307 5-16:02:17
work 1.5 19 - futex_ - - 35306 5-16:01:36
work 1.5 19 - futex_ - - 35305 5-16:02:02
work 1.5 19 - futex_ - - 35257 5-16:02:24
work 0.4 19 - futex_ - - 90755 1-07:46:12
work 0.4 19 - futex_ - - 73007 1-10:15:56
work 0.4 19 - futex_ - - 73006 1-10:16:16
work 0.4 19 - futex_ - - 73005 1-10:16:29
work 0.4 19 - futex_ - - 73004 1-10:14:13
work 0.4 19 - futex_ - - 73003 1-10:15:21
work 0.4 19 - futex_ - - 72981 1-10:17:19
work 0.4 19 - futex_ - - 72980 1-10:17:15
work 0.4 19 - futex_ - - 72974 1-10:18:23
Memory & GC analysis
Jinfo: View process startup detail
$ jinfo 35253
Java System Properties:
...
VM Flags:
-XX:CICompilerCount=15 -XX:ConcGCThreads=6 -XX:G1ConcRefinementThreads=23 -XX:G1HeapRegionSize=4194304 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=8589934592 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=8589934592 -XX:MaxNewSize=5150605312 -XX:MinHeapDeltaBytes=4194304 -XX:NonNMethodCodeHeapSize=8178940 -XX:NonProfiledCodeHeapSize=121739650 -XX:ProfiledCodeHeapSize=121739650 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC
VM Arguments:
jvm_args: -Xms8192m -Xmx8192m -Dspring.profiles.active=prod-x9 -Dserver.port=8082 -Dserver.httpsPort=8442 -Draft.id=10.19.24.7-6002 -Dmanagement.server.port=9442
java_command: dynamic-service-1.1.1.jar
java_class_path (initial): dynamic-service-1.1.1.jar
Launcher Type: SUN_STANDARD
JMap: View memory layout
$ jmap -histo:live 35253| head -n 10
num #instances #bytes class name (module)
-------------------------------------------------------
1: 38351692 1298970832 [B (java.base@11)
2: 37661022 903864528 java.lang.String (java.base@11)
3: 17207496 412979904 com.kingsoft.dw.dynamic.domain.dwevent.EventProperty
4: 3431252 221917408 [Ljava.lang.Object; (java.base@11)
5: 2207352 207421824 [Ljava.util.HashMap$Node; (java.base@11)
6: 5579222 133901328 java.lang.Long (java.base@11)
7: 2220304 124337024 java.util.LinkedHashMap (java.base@11)
8: 5670892 90734272 java.lang.Integer (java.base@11)
其中：
- [C is a char[]
- [S is a short[]
- [I is a int[]
- [B is a byte[]
- [[I is a int[][]
jstat: View GC status
$ jstat -gc 35253
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
0.0 49152.0 0.0 49152.0 393216.0 356352.0 7946240.0 3801500.2 146736.0 142788.5 17792.0 16210.4 595844 22573.208 3 5.341 22578.549
- S0C：第一个幸存区的大小，单位KB
- S1C：第二个幸存区的大小
- S0U：第一个幸存区的已使用大小
- S1U：第二个幸存区的已使用大小
- EC：伊甸园区的大小
- EU：伊甸园区的已使用大小
- OC：老年代大小
- OU：老年代已使用大小
- MC：方法区大小(元空间)
- MU：方法区使用大小
- CCSC:压缩类空间大小
- CCSU:压缩类空间已使用大小
- YGC：年轻代垃圾回收次数
- YGCT：年轻代垃圾回收消耗时间，单位s
- FGC：老年代垃圾回收次数
- FGCT：老年代垃圾回收消耗时间，单位s
- GCT：垃圾回收消耗总时间，单位s
$ jstat -gcutil 35253 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 13.98 78.28 97.30 91.11 595624 22540.714 3 5.341 22546.055
0.00 100.00 18.64 78.28 97.30 91.11 595624 22540.714 3 5.341 22546.055
0.00 100.00 8.98 78.88 97.30 91.11 595625 22540.837 3 5.341 22546.177
0.00 100.00 12.99 78.79 97.30 91.11 595625 22540.837 3 5.341 22546.177
0.00 100.00 17.63 78.79 97.30 91.11 595625 22540.837 3 5.341 22546.177
0.00 100.00 22.70 78.79 97.30 91.11 595625 22540.837 3 5.341 22546.177
0.00 100.00 35.69 78.79 97.30 91.11 595625 22540.837 3 5.341 22546.177
0.00 100.00 95.04 78.79 97.30 91.11 595626 22540.837 3 5.341 22546.177
0.00 100.00 5.90 71.19 97.30 91.11 595627 22541.470 3 5.341 22546.811
0.00 100.00 19.78 71.19 97.30 91.11 595627 22541.470 3 5.341 22546.811
0.00 100.00 59.97 70.23 97.30 91.11 595627 22541.470 3 5.341 22546.811
0.00 100.00 21.34 71.44 97.30 91.11 595628 22541.658 3 5.341 22546.998
0.00 100.00 39.07 71.37 97.30 91.11 595628 22541.658 3 5.341 22546.998
$ jstat -gccapacity 35253
NGCMN NGCMX NGC S0C S1C EC OGCMN OGCMX OGC OC MCMN MCMX MC CCSMN CCSMX CCSC YGC FGC CGC
0.0 8388608.0 2990080.0 0.0 65536.0 2924544.0 0.0 8388608.0 5398528.0 5398528.0 0.0 1177600.0 146736.0 0.0 1048576.0 17792.0 595869 3 494044
jstack：view thread detail
$ top -Hp 35253
203384 work 20 0 27.3g 10.6g 11560 S 16.7 4.2 583:47.11 http-nio-0.0.0.
$ printf "%x\n" 203384
31a78
$ jstack 35253 | grep 31a78 -A 100
"http-nio-0.0.0.0-8082-exec-259" #647 daemon prio=5 os_prio=0 cpu=35027157.90ms elapsed=30595411.19s tid=0x00007fe5741c3800 nid=0x31a78 waiting on condition [0x00007fe3eef9f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11/Native Method)
- parking to wait for <0x0000000620d00bb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11/AbstractQueuedSynchronizer.java:2123)
at java.util.concurrent.LinkedBlockingQueue.poll(java.base@11/LinkedBlockingQueue.java:458)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:128)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:33)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1113)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(java.base@11/Thread.java:834)
"http-nio-0.0.0.0-8082-exec-260" #648 daemon prio=5 os_prio=0 cpu=35198074.52ms elapsed=30595411.19s tid=0x00007fe5741c5800 nid=0x31a7a waiting on condition [0x00007fe3eee9e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11/Native Method)
- parking to wait for <0x0000000620d00bb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11/AbstractQueuedSynchronizer.java:2123)
at java.util.concurrent.LinkedBlockingQueue.poll(java.base@11/LinkedBlockingQueue.java:458)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:128)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:33)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1113)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(java.base@11/Thread.java:834)