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

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

3年前
934445

起因:在某个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方案

点赞收藏
分类:标签:
Mr.g
请先登录,查看4条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步
5
4