背景
k8s生产环境的,一个node CPU使用率特别高。通过top调查发现是一个tomcat pod导致的cpu使用率飙高,平均在200%。然后服务启动不成功,会不断重启。直到现在没有找到具体的原因,起了三个pod,另外两个tomcat pod是正常的,只有这一个有异常。因为自己对java不是很熟,通过这一次debug,熟悉了一下java性能调优的工具。虽然没有得出最终结论,还是有必要记录一下调试过程。
查询pid对应的容器id
通常出现cpu过高的问题时,我们会使用top命令查看具体时哪个进程对cpu资源占用过高。在kubernetes环境中,服务通常都是运行在容器内的。但是top命令查看的pid进程id。所以需要根据pid查询到对应的容器id。是用命令如下:
docker ps -q | xargs docker inspect --format '{{.State.Pid}}, {{.Id }}, {{.Name}}'|grep { pid }
输出如下图:
docker ps -q | xargs docker inspect --format '{{.State.Pid}}, {{.Id }}, {{.Name}}'|grep 29663
31499, 6705d335f4e520a49d795d9fd398a3aa602d7d56278bd75755b58b4887b4df6f, /k8s_POD_prometheus-k8s-system-0_kubesphere-monitoring-system_865e47a6-8112-4878-8dbb-557756b588d3_2
第一列为pid进程id,第二列为容器id,第三列为容器名。
获取java进程堆栈信息
查询到哪个容器占用cpu过高后,执行docker exec -it 命令进入容器。在容器内执行ps -ef查看java服务进程号,一般pid都是1。执行jstack -l pid,收集java堆栈信息。
jstack -l 1
2022-03-15 10:09:40
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.91-b14 mixed mode):
"Attach Listener" #28 daemon prio=9 os_prio=0 tid=0x00007ff79c001000 nid=0x5a waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Log4j2-TF-6-AsyncLoggerConfig--2" #26 daemon prio=5 os_prio=0 tid=0x00007ff821d9e800 nid=0x38 runnable [0x00007ff7b0597000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000067708fa90> (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 com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitStrategy.java:38)
at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:159)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
at java.lang.Thread.run(Thread.java:745)
"Log4j2-TF-5-Scheduled-1" #25 daemon prio=5 os_prio=0 tid=0x00007ff821d8d800 nid=0x37 waiting on condition [0x00007ff7b0698000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000676fb16d0> (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.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"NioBlockingSelector.BlockPoller-2" #24 daemon prio=5 os_prio=0 tid=0x00007ff8204b4000 nid=0x2f runnable [0x00007ff7b194e000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000003d35c5528> (a sun.nio.ch.Util$2)
- locked <0x00000003d35c5518> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000003d35c53e0> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:298)
……………………………………………………………………
堆栈信息分析
打开https://fastthread.io/,页面上选择堆栈信息为RAW。将上一步得到的堆栈信息,copy到输入框内,点击Analyze。就可以可视化分析java调用栈信息