一次用arthas定位akka的CPU占用过高的经历

          在一次线上环境中，出现过两个java进程的CPU一直在满负荷跑的情况，而且此时用户访问量非常少，理论上来说不应该出现这种情况。

          这两个进程的共同点就是启动的时间差不多，而且都用到了akka。然后尝试用arthas来定位这个问题。

          我们以其中的一个进程为例来进行分析。

 

一、找到CPU高的进程ID

top

二、启动arthas，进入该进程调试

这里，我们调试5176号进程

三、找到消耗CPU多的线程

dashboard

 

可以看到主要是id号为35的线程比较耗CPU，eps-scheduler是akka的一个定时器。

四、打印线程堆栈信息

thread 35(35是线程id)

[arthas@5176]$ thread 35 "eps-scheduler-1" Id=35 RUNNABLE at akka.actor.LightArrayRevolverScheduler$$anon$4.nextTick(LightArrayRevolverScheduler.scala:281) at akka.actor.LightArrayRevolverScheduler$$anon$4.run(LightArrayRevolverScheduler.scala:230) at java.lang.Thread.run(Thread.java:748) Affect(row-cnt:0) cost in 62 ms.

五、找到相应的代码

找到LightArrayRevolverScheduler这个类中的nextTick方法

@tailrec final def nextTick(): Unit = { val time = clock() val sleepTime = start + (tick * tickNanos) - time if (sleepTime > 0) { // check the queue before taking a nap checkQueue(time) waitNanos(sleepTime) } else { val bucket = tick & wheelMask val tasks = wheel(bucket) val putBack = new TaskQueue @tailrec def executeBucket(): Unit = tasks.pollNode() match { case null ⇒ () case node ⇒ val task = node.value if (!task.isCancelled) { if (task.ticks >= WheelSize) { task.ticks -= WheelSize putBack.addNode(node) } else task.executeTask() } executeBucket() } executeBucket() wheel(bucket) = putBack tick += 1 } stopped.get match { case null ⇒ nextTick() case p ⇒ assert(stopped.compareAndSet(p, Promise successful Nil), "Stop signal violated in LARS") p success clearAll() } }

代码是scala写的，不太懂。用arthas的反编译工具将它反编译一下

jad akka.actor.LightArrayRevolverScheduler

反编译后得到以下内容 ：

private final void nextTick() { Promise<scala.collection.immutable.Seq<TimerTask>> promise; do { long time = this.$outer.clock(); long sleepTime = this.$outer.akka$actor$LightArrayRevolverScheduler$$start() + (long)this.tick() * this.$outer.akka$actor$LightArrayRevolverScheduler$$tickNanos() - time; if (sleepTime > 0L) { this.checkQueue(time); this.$outer.waitNanos(sleepTime); continue; } int bucket = this.tick() & this.$outer.akka$actor$LightArrayRevolverScheduler$$wheelMask(); TaskQueue tasks = this.akka$actor$LightArrayRevolverScheduler$$anon$$wheel()[bucket]; TaskQueue putBack = new TaskQueue(); this.executeBucket$1(tasks, putBack); this.akka$actor$LightArrayRevolverScheduler$$anon$$wheel()[bucket] = putBack; this.tick_$eq(this.tick() + 1); } while ((promise = this.$outer.akka$actor$LightArrayRevolverScheduler$$stopped().get()) == null); Predef$.MODULE$.assert(this.$outer.akka$actor$LightArrayRevolverScheduler$$stopped().compareAndSet(promise, (Promise<scala.collection.immutable.Seq<TimerTask>>)Promise$.MODULE$.successful((Object)Nil$.MODULE$)), (Function0)new /* Unavailable Anonymous Inner Class!! */); promise.success(this.clearAll()); BoxedUnit boxedUnit = BoxedUnit.UNIT; }

 可以看到它是一个do while的循环方法，因为它本身就是一个定时器，有循环也很正常，问题是它循环调用的频率是否正常。

六、监控方法调用的频率

为了方便比较，我在局域网内也启动了一个一样的进程，然后分别监控他们的executeBucket方法和checkQueue方法的调用频率。测试方式是使用arthas的另一个功能monitor。

内网环境测试：

monitor -c 5 akka.actor.LightArrayRevolverScheduler$$anon$4 executeBucket$1

monitor -c 5 akka.actor.LightArrayRevolverScheduler$$anon$4 checkQueue

 

线上环境测试：

monitor -c 5 akka.actor.LightArrayRevolverScheduler$$anon$4 executeBucket$1

监控checkQueue的结果是它根本没有执行。

 

七、结论

       通过上面的调试结果，可以看出CPU过高的原因就是akka的定时器轮询的时候，休眠操作没有执行，导致空循环，每秒次数有80000多。 至于是什么导致没有执行休眠，还没有找到原因。

       一顿操作猛如虎，一看伤害二点五......