【最佳实践】FE CPU 异常分析实践

Viewed 74

背景

Doris集群的角色分为FE和BE。在存储层面FE负责存储和维护集群的元数据。在计算方面FE负责接收和解析用户的查询请求,规划查询计划,调度查询结果。BE负责数据的主要存储和计算,以及根据FE生成的物理执行计划,然后进行分布式查询。

因此对于Doris来说其实主要的内存和CPU的使用主要集中在BE,但是实际运行环境中偶尔也会出现有的同学线上FE环境出现CPU使用过高的问题。并且这种情况可能只出现在线上特点的环境上,想要线下复现难度很大,这个是时候就需要我们通过对线上FE进程的CPU使用情况进行分析和定位问题,同时也适用于FE执行慢或者卡住等问题的排查。

因为FE是基于Java编写的,那么问题就变为如何对FE的JVM进程的CPU使用进行分析的问题。JVM内存分析工具比较多,这里介绍最常用jstack的使用方式。

基于jstack进行FE线程分析

jstack是堆栈跟踪工具,一般用于查看某个进程内线程的情况。比较典型的应用是分析占用CPU时间最多的代码块,具体步骤如下。

  1. 进行进程号查询,执行ps -ef|grep FE 或者直接jps 命令查看该FE应用进程号,可以看到结果为4108340。

  2. 执行“top -Hp 4108340” 打开TOP视图,然后在线程视图中按 P 键,按照 CPU 使用率降序排列线程,找出 CPU 占用率高的线程。我们以4112817号线程测试。

  3. 中的线程 ID 是以十进制显示的,而 Java 中的线程 ID 是以十六进制显示的。你可以使用 printf 命令将线程 ID 转换为十六进制。

[liyuanyuan@VM-10-6-centos ~]$ printf "%x\n" 4112817
  1. 使用jstack定位问题,执行“ jstack 4108340 |grep 3ec1b1 -A 27”命令过滤出进程4108340上线程3ec1b1中的线程调用栈情况,这样便快能定位到占用CPU时间最长的代码块。(附图是测试,无实际问题)

  2. 如果线上分析时间有限,也可以通过jstack 4108340 > fe.jstack.log命令将进程号为4108340的FE进程的栈信息保存起来后续分析。
    jstack 4108340 > fe.jstack.log

2 Answers

有遇到FE CPU异常可以先按照这个思路去排查下,或者收集下 jstack 给到社区同学

我的fe cpu超过60%,能看出哪里的问题吗

jstack的结果如下:jstack 31657 |grep -A 50 7bee

jstack 31657 |grep -A 50 7bee
"replayer" #92 daemon prio=5 os_prio=0 tid=0x00007fa65c005000 nid=0x7bee runnable [0x00007fa60affa000]
java.lang.Thread.State: RUNNABLE
at com.sleepycat.je.dbi.DiskOrderedScanner.processBINInternal(DiskOrderedScanner.java:1945)
at com.sleepycat.je.dbi.DiskOrderedScanner.accumulateBINs(DiskOrderedScanner.java:1169)
at com.sleepycat.je.dbi.DiskOrderedScanner.scanSerial(DiskOrderedScanner.java:758)
at com.sleepycat.je.dbi.DiskOrderedScanner.scan(DiskOrderedScanner.java:708)
at com.sleepycat.je.dbi.DatabaseImpl.count(DatabaseImpl.java:1510)
at com.sleepycat.je.Database.count(Database.java:2042)
at org.apache.doris.journal.bdbje.BDBJEJournal.getMaxJournalIdInternal(BDBJEJournal.java:414)
at org.apache.doris.journal.bdbje.BDBJEJournal.getMaxJournalId(BDBJEJournal.java:379)
at org.apache.doris.persist.EditLog.getMaxJournalId(EditLog.java:136)
at org.apache.doris.catalog.Env.getMaxJournalId(Env.java:4257)
at org.apache.doris.catalog.Env.replayJournal(Env.java:2821)

  • locked <0x00000005c5801ca0> (a org.apache.doris.catalog.Env)
    at org.apache.doris.catalog.Env$4.runOneCycle(Env.java:2622)
    at org.apache.doris.common.util.Daemon.run(Daemon.java:119)

"Thread-38" #50 daemon prio=5 os_prio=0 tid=0x00007fa6c0b53800 nid=0x7bed waiting on condition [0x00007fa60b3fb000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.doris.common.util.Daemon.run(Daemon.java:125)

"Automatic Analyzer" #43 daemon prio=5 os_prio=0 tid=0x00007fa6c0b52800 nid=0x7bec waiting on condition [0x00007fa60b7fc000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.doris.common.util.Daemon.run(Daemon.java:125)

"Statistics Table Cleaner" #41 daemon prio=5 os_prio=0 tid=0x00007fa6c1cf1000 nid=0x7beb waiting on condition [0x00007fa60bbfd000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.doris.common.util.Daemon.run(Daemon.java:125)

"stateListener" #90 daemon prio=5 os_prio=0 tid=0x00007fa6c1cf0000 nid=0x7bea waiting on condition [0x00007fa60bffe000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

  • parking to wait for <0x00000005c5b11c08> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492)
    at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680)
    at org.apache.doris.catalog.Env$5.runOneCycle(Env.java:2715)
  • locked <0x00000005c3203ff0> (a org.apache.doris.catalog.Env$5)
    at org.apache.doris.common.util.Daemon.run(Daemon.java:119)

"ReplayThread" #87 daemon prio=5 os_prio=0 tid=0x00007fa648825000 nid=0x7be9 waiting on condition [0x00007fa614df2000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

  • parking to wait for <0x00000005c3204328> (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.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)