Linux排查JVM问题
背景
通常来说当我们的Java服务出现问题时,首先需要考虑的是这个进程是不是还在运行,然后再关注这个进程所占用的资源多少,CPU、内存的使用情况,从而定位到具体问题。因此,有必要对Linux服务器中的JVM异常排查进行下记录。
方法
1、查找Java进程id
ps -ef|grep java
当然,如果服务器上有多个Java进程,我们可以考虑使用top命令,然后查看cpu和内存使用率最高的进程情况
top -c #参数c表示列出命令的详细信息
此命令展示出的信息,各项含义可以参考:这篇文章
假设拿到的进程id 为 3907
2、jmap查看堆使用信息
jmap -heap 3907
拿到结果如下:
using thread-local object allocation. Mark Sweep Compact GC Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 1258291200 (1200.0MB) NewSize = 26542080 (25.3125MB) MaxNewSize = 419430400 (400.0MB) OldSize = 53149696 (50.6875MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 21807104 (20.796875MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 17592186044415 MB G1HeapRegionSize = 0 (0.0MB) Heap Usage: New Generation (Eden + 1 Survivor Space): capacity = 23986176 (22.875MB) used = 13869504 (13.22698974609375MB) free = 10116672 (9.64801025390625MB) 57.82290599385246% used Eden Space: capacity = 21364736 (20.375MB) used = 11248072 (10.726997375488281MB) free = 10116664 (9.648002624511719MB) 52.64783987969709% used From Space: capacity = 2621440 (2.5MB) used = 2621432 (2.4999923706054688MB) free = 8 (7.62939453125E-6MB) 99.99969482421875% used To Space: capacity = 2621440 (2.5MB) used = 0 (0.0MB) free = 2621440 (2.5MB) 0.0% used tenured generation: capacity = 53149696 (50.6875MB) used = 28450632 (27.13263702392578MB) free = 24699064 (23.55486297607422MB) 53.52924690293619% used 21354 interned Strings occupying 1919928 bytes.
3、通过查看gc统计信息来分析问题,如果gc次数比较多,那么发生内存泄漏的可能性就比较大了
jstat -gcutil 3907
得到信息如下:
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 100.00 0.00 97.85 53.53 94.62 92.74 76 0.857 2 0.227 1.083
其中各个参数的含义如下:
s0: 新生代survivor0的使用率
s1:s1的使用率
E: 新生代eden空间的使用率
O:老年代的使用率
M:元数据的空间使用率
YGC:新生代gc次数
YGCT:新生代GC总时长
FGC:full gc的次数
FGCT: full gc 的总时长
GCT: 总的gc时长
4、查看各个类所对应的实例对象所占用的内存:(分析内存使用飙高原因)
[root@localhost s]# jmap -histo 3907 num #instances #bytes class name ---------------------------------------------- 1: 67987 6238344 [C 2: 337475 5399600 com.boc.eureka.service.TestHeap$OOMExample 3: 12917 3820336 [I 4: 111712 3574784 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node 5: 14247 3379280 [Ljava.lang.Object; 6: 19022 1673936 java.lang.reflect.Method 7: 67576 1621824 java.lang.String 8: 46815 1498080 java.util.concurrent.ConcurrentHashMap$Node 9: 11140 1225912 java.lang.Class 10: 9775 1174376 [B 11: 18018 720720 java.util.LinkedHashMap$Entry 12: 8591 690872 [Ljava.util.HashMap$Node; 13: 214 519680 [Ljava.util.concurrent.ConcurrentHashMap$Node; 14: 8725 488600 java.util.LinkedHashMap 15: 13800 441600 java.util.HashMap$Node 16: 26304 420864 java.lang.Object 17: 17791 392920 [Ljava.lang.Class; 18: 5130 369360 java.lang.reflect.Field
... ...
5010: 1 16 sun.util.locale.provider.SPILocaleProviderAdapter
5011: 1 16 sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter
5012: 1 16 sun.util.resources.LocaleData
5013: 1 16 sun.util.resources.LocaleData$LocaleDataResourceBundleControl
从上面的结果可以看出:
num:表示编号, #instances表示实例数量,#bytes表示占用的内存字节数量,class name是对应的类名
一个类,一般也就16字节大小,而我们的基础数据类型,它的大小char: 2bytes,short:2bytes, int:4 bytes.long:8bytes
5、查看进程中线程使用情况(分析CPU的使用飙高原因)
top -Hp 3907 #其中参数H表示使用线程分析模式,p表示指定相关的进程id为3907
上述命令将列出进程下的各个线程的使用情况,我们根据结果,得到使用CPU多的线程id
top - 21:03:44 up 54 min, 3 users, load average: 0.17, 0.22, 0.39 Threads: 61 total, 2 running, 59 sleeping, 0 stopped, 0 zombie %Cpu(s): 1.0 us, 0.0 sy, 0.0 ni, 99.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 4912604 total, 2212304 free, 1247976 used, 1452324 buff/cache KiB Swap: 3354620 total, 3354620 free, 0 used. 3371908 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3662 root 20 0 3350296 224996 13676 R 0.7 4.6 0:37.39 TaskAcceptor-ta 3684 root 20 0 3350296 224996 13676 R 0.7 4.6 0:37.34 TaskAcceptor-12 3640 root 20 0 3350296 224996 13676 S 0.3 4.6 0:01.19 Catalina-utilit 3563 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.06 java 3564 root 20 0 3350296 224996 13676 S 0.0 4.6 0:38.20 java 3565 root 20 0 3350296 224996 13676 S 0.0 4.6 0:02.71 VM Thread 3566 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.05 Reference Handl 3567 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.06 Finalizer .... .... 3657 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.09 Eureka-Eviction 3658 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.01 Eureka-MeasureR 3659 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.00 ReplicaAwareIns 3660 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.01 Eureka-MeasureR 3661 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.05 Apache-HttpClie
我们选择id为3662的线程,查看是哪个类里面在运行任务
先将3662转为16进制,因为后面查看jstack输出的信息,线程id是16进制的
printf "%x\n" 3662
e4e
得到结果e4e
然后通过jstack查看e4e相关的信息
jstack -l
再查找e4e相关的信息
得到结果:
"TaskAcceptor-target_127.0.0.1" #21 daemon prio=5 os_prio=0 tid=0x00007f5d111de000 nid=0xe4e runnable [0x00007f5ce8597000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000cf9b82d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467) at com.netflix.eureka.util.batcher.AcceptorExecutor$AcceptorRunner.drainInputQueues(AcceptorExecutor.java:228) at com.netflix.eureka.util.batcher.AcceptorExecutor$AcceptorRunner.run(AcceptorExecutor.java:189) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - None
这样就能分析出是哪个类里面的哪个方法,在不断的占用CPU了。
其中:
tid, Java memory address of its internal Thread control structure.
nid, native thread id. 每一个nid对应于linux下的一个tid, 即lwp (light weight process, or thread)