InfoQ@补全分布式追踪的最后一块“短板”，在线代码级性能剖析( 二 ) 在本文中

文章图片
在上图中， d0-d10代表10次连续的内存栈快照，实际方法执行时间在d3-d4区间，结束时间在d8-d9之间。性能剖析无法告诉你方法的准确执行时间，但是他会估算出方法执行时间为d4-d8的4个快照采集间隔时间之和，这已经是非常的精确的时间估算了。
而这个过程因为不涉及代码埋点，所以自然性能消耗是稳定和可控的，也无需担心是否被埋点，是否是JDK方法等问题。同时，由于上层已经在分布式追踪之下，性能剖析方法可以明确地确定分析开始和结束时间，减少不必要的性能开销。
性能剖析可以很好的对线程的堆栈信息进行监控，主要有以下几点优势：
精确的问题定位，直接到代码方法和代码行；无需反复的增删埋点，大大减少了人力开发成本；不用承担过多埋点对目标系统和监控系统的压力和性能风险；按需使用，平时对系统无消耗，使用时的消耗稳定可能。 SkyWalking实践实例我们首先在ApacheSkyWalkingAPM中实现此技术方法，下面我们就以一个真实的例子来说明此方法的执行效果。
finalCountDownLatchcountDownLatch=newCountDownLatch(2);
threadPool.submit(newTask1(countDownLatch));
threadPool.submit(newTask2(countDownLatch));
try{
countDownLatch.await(500,TimeUnit.MILLISECONDS);
}catch(InterruptedExceptione){
}
这是我们故意加入的问题代码，我们使用CountDownLanth设置了两个任务完成后方法执行结束， Task1和Task2是两个执行时间不稳定的任务，所以主任务也会执行速度不稳定。但对于运维和监控团队来说，很难定位到这个方法片段。
针对于这种情况，我们看看性能剖析会怎样直接定位此问题。

文章图片
上图所示的就是我们在进行链路追踪时所看到的真实执行情况，其中我们可以看到在service/processWithThreadPool执行速度缓慢，这正是我们植入问题代码的方法。此时在这个调用中没有后续链路了，所以并没有更细致的原因，我们也不打算去review代码，从而增加新埋点。这时，我们可以对HelloService进行性能剖析，并执行只剖析响应速度大于500毫秒的请求。
注意，指定特定响应时间的剖析是保证剖析有效性的重要特性，如果方法在平均响应时间上已经出现问题，往往通过分布式链路可以快速定位，因为此时链路总时间长，新埋点带来的性能影响相对可控。但是方法性能抖动是不容易用新增埋点来解决的，而且往往只发生在生产环境。

文章图片
上图就是我们进行性能剖析后的真实结果图。从左到右分别表示：栈帧名称、该栈帧总计耗时（包含其下面所有自栈帧）、当前栈帧自身耗时和监控次数。我们可以在最后一行看到，线程卡在了sun.misc.Unsafe.park中了。如果你熟悉Java就可以知道此时进行了锁等待，我们继续按照树的结构向上推，便可以看到线程真正是卡在了CountDownLatch.await方法中。
方法局限性当然任何的方法都不是万能的，性能剖析也有一些局限性。
第一，对于高频反复执行的方法，如循环调用，可能会误报为缓慢方法。但这并不是大问题，因为如果反复执行的耗时较长，必然是系统需要关注的性能瓶颈。
第二，由于性能栈快照有一定的性能消耗，所以采集周期不宜过密，如SkyWalking实践中，不支持小于10ms的采集间隔。所以如果问题方法执行时间过小（比如在10毫秒内波动），此方法并不适用。我们也再此强调，方法论和工具的强大，始终不能代替程序员。