定位及修复apache skywalking性能问题 #论程序员，你曾遇到关于性能的那些事#

定位及修复apache skywalking性能问题 #论程序员，你曾遇到关于性能的那些事#

定位及修复apache skywalking性能问题 #论程序员，你曾遇到关于性能的那些事#

起因：在某个Java新项目希望引入好用的apm监控工具，对比了几款常见的框架后，选择了集成成本比较低的skywalking。

但是在压测的时候发生了很神奇的事情。应用会无缘无故卡顿导致压测效果不理想，排查了一遍代码认为不太可能是代码上使用锁导致。

排查：
1、JVM GC日志观察
打印GC日志

-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintJNIGCStalls
-XX:+PrintGCApplicationStoppedTime

-Xloggc:/dev/shm/gcdate +%Y%m%d%H%M%S.log

观察后发现并没有什么问题

2、JVM GC安全点
GC日志没问题，那么是否是神奇的安全点导致的呢？

-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1

观察后发现安全点也没有问题

3、是不是压测过程中，不断申请扩大内存导致

-XX:+AlwaysPreTouch 
参数打开后，在进程启动时，让JVM通过demand-zeroed方式一次分配指定内存

很遗憾，也不是这个原因导致，问题依旧

4、是不是代码中真的不当使用锁

使用工具进行ThreadDump，async-profiler生成火焰图分析

这次有了点突破，发现在kafka client线程中卡住了

#314 prio=5 os_prio=0 tid=0x00007f0e4402d050 nid=0x376b waiting on condition [0x00007f0c5c3c1000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
parking to wait for <0x000000060ae48f28> (a java.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject)atjava.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)atjava.util.concurrent.locks.AbstractQueuedSynchronizerConditionObject.await(AbstractQueuedSynchronizer.java:2163)
at org.apache.kafka.clients.producer.internals.BufferPool.allocate(BufferPool.java:134)
at org.apache.kafka.clients.producer.internals.RecordAccumulator.append(RecordAccumulator.java:210)
at org.apache.kafka.clients.producer.KafkaProducer.doSend
KaTeX parse error: Can't use function '$' in math mode at position 9: original$̲6nzgjrfj(KafkaP…
original$6nzgjrfjaccessorRPNOCpVz(KafkaProducer.java)
at org.apache.kafka.clients.producer.KafkaProducerauxiliaryqXyiMoQM.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)
at org.apache.kafka.clients.producer.KafkaProducer.doSend(KafkaProducer.java)

接下来查看kafka client(2.2.0)源码，有兴趣同学看一下源码：org.apache.kafka.clients.producer.internals.BufferPool#allocate。简单说一下，该方法中在kafka 发送消息的时候会检查一下BufferPool可不可以分配新的buffer。通过堆栈信息以及源码，我们猜测是BufferPool满了。

那如何验证我们的想法呢，在实际中我们使用了attach JVM技术修改class再观察

在BufferPool#allocate方法执行时，打印bufferPool关键信息
log.info("{}:{}",this.poolableSize, this.free.size());

再次压测打印如下
33554432:0
33554432:0
33554432:1
33554432:0
33554432:0

打印结果验证了上面的想法，bufferPool已经满了，没有free。在我们的压测场景中应该不至于会达到kafka client的发送瓶颈，因此进一步猜测是由于某种原因bufferPool的清理慢了，甚至被卡住。

让我们继续找释放的代码，跟到下面代码后，心中一震。

org.apache.kafka.clients.producer.internals.Sender#completeBatch()

if (batch.done(response.baseOffset, response.logAppendTime, null)) {
    maybeRemoveFromInflightBatches(batch);
    this.accumulator.deallocate(batch);
}

org.apache.kafka.clients.producer.internals.ProducerBatch#done

org.apache.kafka.clients.producer.internals.ProducerBatch#completeFutureAndFireCallbacks

可以看到，回收buffer的前提是运行完ProducerBatch.done函数，而在done函数中又会调用callback，某不是callback阻碍了生产消息buffer的回收。

继续跟踪callback代码发现只是打印一条日志，难道服务器磁盘IO负载太高？使用dstat -tampl观察，发现负载比较低。

5、继续观察线程栈，火焰图
kafka 发送的bufferPool无法回收，那可能是其他什么导致的呢，继续观察栈，火焰图，有了新的发现，少量kafka发送线程卡在skywalking。

at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:82)
at com.bigo.eco.common.kafka.sender.KafkaEmptyCallback.onCompletion(KafkaEmptyCallback.java:-1)
at org.apache.kafka.clients.producer.KafkaProducerInterceptorCallback.onCompletionoriginalqobEMB62(KafkaProducer.java:1304)atorg.apache.kafka.clients.producer.KafkaProducerInterceptorCallback.onCompletionoriginalqobEMB62accessorKxcVlwF4(KafkaProducer.java:-1)
at org.apache.kafka.clients.producer.KafkaProducerInterceptorCallbackauxiliarySW3k8KDv.call(null:−1)atorg.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)atorg.apache.kafka.clients.producer.KafkaProducerInterceptorCallback.onCompletion(KafkaProducer.java:-1)
at org.apache.kafka.clients.producer.internals.ProducerBatch.completeFutureAndFireCallbacks(ProducerBatch.java:227)
at org.apache.kafka.clients.producer.internals.ProducerBatch.done(ProducerBatch.java:196)
at org.apache.kafka.clients.producer.internals.Sender.completeBatch(Sender.java:677)
at org.apache.kafka.clients.producer.internals.Sender.completeBatch(Sender.java:649)
at org.apache.kafka.clients.producer.internals.Sender.handleProduceResponse(Sender.java:557)
at org.apache.kafka.clients.producer.internals.Sender.access$100(Sender.java:74)
at org.apache.kafka.clients.producer.internals.Sender$1.onComplete(Sender.java:786)
at org.apache.kafka.clients.ClientResponse.onComplete(ClientResponse.java:109)
at org.apache.kafka.clients.NetworkClient.completeResponses(NetworkClient.java:557)
at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:549)
at org.apache.kafka.clients.producer.internals.Sender.run(Sender.java:311)
at org.apache.kafka.clients.producer.internals.Sender.run(Sender.java:235)
at java.lang.Thread.run(Thread.java:748)

同事在github联系skywalking作者后，作者答复应该不关事，建议我们再看看kafka。

6、确认是skywalking问题

虽然skywalking作者认为应该不是skywalking的原因，但排查一轮代码跟依赖后，感觉还是比较可能是skywalking agent，之后我们先把agent去掉，发现压测效果瞬间有了大幅提升，现在我们知道是skywalking 引起的，深入排查也就有了明确方向。

观察到skywalking会打印日志，是不是日志打印太多，虽然前面已经看过io负载，但保留一丝可能性，把skywalking日志配置输出到dev/shm，发现果然不是这个原因，哈哈

skywalking.log

观察skywalking.log日志发现时不时出现2ms的卡顿，频率虽不固定，但是停顿时长很一致，跟作者沟通后了解到使用了自己实现的日志输出类。

最终我们找到了skywalking写日志的操作类，发现skywalking的日志实现是先进队列，异步写，当队列满的时候会阻塞2ms。
查看FileWriter构造函数发现使用了1024大小的队列，每秒flush一次

org.apache.skywalking.apm.agent.core.logging.core.FileWriter#write
try {
    logBuffer.offer(message, 2, TimeUnit.MILLISECONDS);
} catch (InterruptedException e) {
    e.printStackTrace();
}

private FileWriter() {
    logBuffer = new ArrayBlockingQueue(1024);

Executors
            .newSingleThreadScheduledExecutor(new DefaultNamedThreadFactory("LogFileWriter"))
            .scheduleAtFixedRate(... 0, 1, TimeUnit.SECONDS);
}

问题最终找到平时skywalking日志量是很少的，而在我们单实例压测到 QPS 破万后，它的量就会相应的大一些，从而出现日志打印队列满了的情况，阻塞2ms。

解决：定位到问题后有同事提了fix方案