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[][]
Heap dump
jmap -dump:live,format=b,file=heapdump1.hprof 69829
jmap -dump:format=b,file=heapdump5.hprof 191110
gzip heapdump5.hprof
Jvisual vm :view dump
File -> Load file, ans select the heap dump.
Eclipse MAT
Need to set JVM heap size in MemoryAnalyzer.ini.
gc dump view
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：Survivor 0区的容量为0字节。 S1C：Survivor 1区的容量为49152字节（48KB）。 S0U：Survivor 0区的已使用容量为0字节。 S1U：Survivor 1区的已使用容量为49152字节（48KB）。 EC：Eden区的容量为393216字节（384KB）。 EU：Eden区的已使用容量为356352字节（348KB）。 OC：老年代总容量为7946240字节（7.5MB）。 OU：老年代的已使用容量为3801500.2字节（3.6MB）。 MC：元数据区的容量为146736字节（143KB）。 MU：元数据区的已使用容量为142788.5字节（139KB）。 CCSC：压缩类空间的容量为17792字节（17KB）。 CCSU：压缩类空间的已使用容量为16210.4字节（15.8KB）。 YGC：Young GC的次数为595844次。 YGCT：Young GC的总耗时为22573.208秒（22.5秒）。 FGC：Full GC的次数为3次。 FGCT：Full GC的总耗时为5.341秒。 GCT：所有GC的总耗时为22578.549秒（22.6秒）
$ 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
NGCMN：新生代最小容量（初始大小）为0字节。 NGCMX：新生代最大容量为8388608字节（8MB）。 NGC：新生代当前容量为2990080字节（2.99MB）。 S0C：Survivor 0区的容量为0字节。 S1C：Survivor 1区的容量为65536字节（64KB）。 EC：Eden区的容量为2924544字节（2.92MB）。 OGCMN：老年代最小容量为0字节。 OGCMX：老年代最大容量为8388608字节（8MB）。 OGC：老年代当前容量为5398528字节（5.4MB）。 OC：老年代总容量为5398528字节（5.4MB）。 MCMN：元数据区最小容量为0字节。 MCMX：元数据区最大容量为1177600字节（1.12MB）。 MC：元数据区当前容量为146736字节（143KB）。 CCSMN：压缩类空间最小容量为0字节。 CCSMX：压缩类空间最大容量为1048576字节（1MB）。 CCSC：压缩类空间当前容量为17792字节（17KB）。 YGC：Young GC的次数为595869次。 FGC：Full GC的次数为3次。 CGC：Concurrent GC的次数为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)
Arthas
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
[INFO] JAVA_HOME: /home/work/dynamic-raft/jdk-11
[INFO] arthas-boot version: 3.7.2
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 69829 dynamic-service-1.1.1.jar
[2]: 70741 dynamic-service-1.1.1.jar
[3]: 71576 dynamic-service-1.1.1.jar
[4]: 72283 dynamic-service-1.1.1.jar
[5]: 56605 dynamic-service-1.1.1.jar
1
[INFO] local lastest version: 3.6.6, remote lastest version: 3.7.2, try to download from remote.
[INFO] Start download arthas from remote server: https://arthas.aliyun.com/download/3.7.2?mirror=aliyun
...
pid 69829
time 2024-04-15 18:07:43
dashboard
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTE DAEMON
152 http-nio-8442-Acceptor main 5 RUNNABLE 7.59 0.379 6:56.209 false true
151 http-nio-8442-Poller main 5 RUNNABLE 7.4 0.369 6:33.953 false true
126 http-nio-0.0.0.0-8082-exec-88 main 5 TIMED_WAITI 7.37 0.368 0:45.993 false true
828 http-nio-0.0.0.0-8082-exec-123 main 5 TIMED_WAITI 7.26 0.363 0:2.225 false true
97 http-nio-0.0.0.0-8082-exec-59 main 5 TIMED_WAITI 7.2 0.359 0:45.055 false true
128 http-nio-0.0.0.0-8082-exec-90 main 5 TIMED_WAITI 6.61 0.330 0:46.394 false true
81 http-nio-0.0.0.0-8082-exec-43 main 5 TIMED_WAITI 5.96 0.297 0:49.908 false true
826 http-nio-0.0.0.0-8082-exec-122 main 5 TIMED_WAITI 5.95 0.297 0:2.606 false true
139 http-nio-0.0.0.0-8082-Poller main 5 RUNNABLE 3.02 0.151 2:37.252 false true
140 http-nio-0.0.0.0-8082-Acceptor main 5 RUNNABLE 2.72 0.135 2:28.349 false true
37 pulsar-timer-5-1 main 5 TIMED_WAITI 2.37 0.118 2:10.360 false false
Memory used total max usage GC
heap 7843M 12288M 12288M 63.83% gc.g1_young_generation.count 609
g1_eden_space 4064M 6624M -1 61.35% gc.g1_young_generation.time(ms) 69876
g1_old_gen 3731M 5616M 12288M 30.37% gc.g1_old_generation.count 0
g1_survivor_space 48M 48M -1 100.00% gc.g1_old_generation.time(ms) 0
nonheap 203M 220M -1 92.55%
codeheap_'non-nmethods' 1M 4M 7M 17.92%
metaspace 132M 136M -1 96.96%
codeheap_'profiled_nmethods' 32M 39M 116M 28.23%
compressed_class_space 15M 17M 1024M 1.55%
Runtime
os.name Linux
os.version 3.10.0-957.el7.x86_64
java.version 11
java.home /home/work/dynamic-raft/jdk-11
systemload.average 13.97
processors 32
timestamp/uptime Mon Apr 15 18:10:45 CST 2024/5774s
view class loader info
sc -d cn.hutool.extra.spring.SpringUtil
Affect(row-cnt:0) cost in 116 ms.
[arthas@69829]$ sc -d com.kingsoft.dw.dynamic.application.cache.InMemoryAppMetaDataStore
class-info com.kingsoft.dw.dynamic.application.cache.InMemoryAppMetaDataStore
code-source file:/home/work/dynamic-raft/dynamic-service-1.1.1.jar!/BOOT-INF/classes!/
name com.kingsoft.dw.dynamic.application.cache.InMemoryAppMetaDataStore
isInterface false
isAnnotation false
isEnum false
isAnonymousClass false
isArray false
isLocalClass false
isMemberClass false
isPrimitive false
isSynthetic false
simple-name InMemoryAppMetaDataStore
modifier public
annotation
interfaces com.kingsoft.dw.dynamic.application.cache.AppMetaDataStore
super-class +-java.lang.Object
class-loader +-org.springframework.boot.loader.LaunchedURLClassLoader@8bd1b6a
+-jdk.internal.loader.ClassLoaders$AppClassLoader@4b85612c
+-jdk.internal.loader.ClassLoaders$PlatformClassLoader@5bcab519
classLoaderHash 8bd1b6a