应用系统瓶颈排查和分析的思考-Arthas 实战

作者 | 一啦米

【Arthas 官方社区正在举行征文活动，参加即有奖品拿~ 点击投稿 】

背景

业务应用系统接入流程引擎来处理业务应用的流程执行，流程引擎提供多线程高性能异步化来执行流程元素的执行，但是如何设置流程引擎的线程池线程数执行，以及执行线程数和任务数，应用机器资源使用情况之间的关系如何，目前只能通过接入方的人工经验评估，比较粗泛评估，参数的合理性也很难直观的评估，现通过现有的应用系统默认的参数配置进行问题说明。

性能监控

查看 CPU 核数

应用机器的配置是 2 核 CPU 配置：

查看应用机器的负载情况

应用程序的近 15 分钟内的负载严重的超载(平均超出 CPU 执行的 10 倍之多)，应用程序对应的 CPU 和 MEM 的利用率都很高，按照本次单机模拟线上的流量（QPS：10) 不至于出现如此的负载情况吧。

查看应用机器的综合统计

CPU 运行队列中也严重的堵筛(Procs列中指标），应用的 CPU 有效利用率其实并不算太高（US+SY),但是系统出现了严重的 CS(上下文切换)，配合 BI，BO 执行，也间接反馈出一些端倪，具体反馈到应用程序中，还需要进一步分析。

查看应用服务(PID=512)的进程 CPU 执行情况

查看应用机器的磁盘 IO 使用情况

应用系统的线程统计概要

应用系统中居然有如此多的线程(1285),应用系统接入流程 SDK 中的线程池数据设置也不会超过80个线程，为何有如何大的偏差，考虑到应用系统中还存在 RPC，kafka 等相关的技术栈，对于应用系统的线程分布还需要进一步的分析。

应用系统执行 dashboard

GC 回收线程监控统计

应用系统线程执行栈的统计

阻塞线程 ThreadDump 信息

org.apache.log4j.spi.RootLogger is blocking 379 threads.

Pigeon-Server-Request-Processor-46-thread-318

Stack Trace is:

java.lang.Thread.State: RUNNABLE

at java.lang.Throwable.printStackTrace(Throwable.java:665)

- locked <0x000000075332fde8> (a java.io.PrintWriter)

at java.lang.Throwable.printStackTrace(Throwable.java:721)

at org.apache.log4j.DefaultThrowableRenderer.render(DefaultThrowableRenderer.java:60)

at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:87)

- locked <0x000000074ae96550> (a org.apache.log4j.spi.ThrowableInformation)

at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)

at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)

at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)

at com.dianping.combiz.misc.ExtendedConsoleAppender.append(ExtendedConsoleAppender.java:82)

at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)

- eliminated <0x000000075f880030> (a com.dianping.combiz.misc.ExtendedConsoleAppender)

at com.dianping.combiz.misc.ExtendedConsoleAppender.doAppend(ExtendedConsoleAppender.java:75)

- locked <0x000000075f880030> (a com.dianping.combiz.misc.ExtendedConsoleAppender)

at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)

at org.apache.log4j.Category.callAppenders(Category.java:206)<br />- locked <0x000000075ed2bd58> (a org.apache.log4j.spi.RootLogger)<br />at org.apache.log4j.Category.forcedLog(Category.java:391)<br />at org.apache.log4j.Category.log(Category.java:856)

at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:576)

at com.meituan.mafka.client.producer.DefaultProducerProcessor.doSend(DefaultProducerProcessor.java:832)

at com.meituan.mafka.client.producer.DefaultProducerProcessor.sendMessage(DefaultProducerProcessor.java:603)

at com.meituan.mafka.client.producer.DefaultProducerProcessor.sendMessage(DefaultProducerProcessor.java:584)

at com.meituan.mafka.client.producer.DefaultProducerProcessor.sendMessage(DefaultProducerProcessor.java:567)

at com.meituan.mafka.client.producer.DefaultProducerProcessor.sendMessage(DefaultProducerProcessor.java:562)

at com.dianping.poi.flowcenter.mq.WorkflowEventMQProducer.sendSyncMessage(WorkflowEventMQProducer.java:98)

at com.dianping.poi.flowcenter.WorkflowEngine.createFlowInstance(WorkflowEngine.java:642)

at com.dianping.poi.flowcenter.WorkflowEngine.startWorkflow0(WorkflowEngine.java:560)

at com.dianping.poi.flowcenter.WorkflowEngine.startWorkflow(WorkflowEngine.java:504)

at com.dianping.poi.mainflow.clearengine.engine.create.impl.CreateWorkflowServiceImpl.createWorkflow(CreateWorkflowServiceImpl.java:66)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:277)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:183)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:176)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness$$FastClassBySpringCGLIB$$f3bb47a4.invoke(<generated>)

at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)

at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)

at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness$$EnhancerBySpringCGLIB$$e721a2aa.createWorkflow(<generated>)

at com.dianping.poi.mainflow.update.biz.business.MainUpdateFlowBusiness.update(MainUpdateFlowBusiness.java:220)

at com.dianping.poi.mainflow.update.biz.business.MainUpdateFlowBusiness.update(MainUpdateFlowBusiness.java:179)

at com.dianping.poi.mainflow.feedback.biz.serviceImpl.FeedbackForPoiServiceImpl.dpFeedbackBase(FeedbackForPoiServiceImpl.java:1233)

at com.dianping.poi.mainflow.feedback.biz.serviceImpl.FeedbackForPoiServiceImpl.dpTerminalFeedback(FeedbackForPoiServiceImpl.java:486)

at sun.reflect.GeneratedMethodAccessor144.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:497)

at com.dianping.pigeon.remoting.provider.service.method.ServiceMethod.invoke(ServiceMethod.java:193)

at com.dianping.pigeon.remoting.provider.process.filter.BusinessProcessFilter.invoke(BusinessProcessFilter.java:79)

at com.dianping.pigeon.remoting.provider.process.filter.BusinessProcessFilter.invoke(BusinessProcessFilter.java:34)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.GatewayProcessFilter.invoke(GatewayProcessFilter.java:242)

at com.dianping.pigeon.remoting.provider.process.filter.GatewayProcessFilter.invoke(GatewayProcessFilter.java:51)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.SecurityFilter.invoke(SecurityFilter.java:31)

at com.dianping.pigeon.remoting.provider.process.filter.SecurityFilter.invoke(SecurityFilter.java:15)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.GenericProcessFilter.invoke(GenericProcessFilter.java:41)

at com.dianping.pigeon.remoting.provider.process.filter.GenericProcessFilter.invoke(GenericProcessFilter.java:24)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.ExceptionProcessFilter.invoke(ExceptionProcessFilter.java:44)

at com.dianping.pigeon.remoting.provider.process.filter.ExceptionProcessFilter.invoke(ExceptionProcessFilter.java:27)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.ContextTransferProcessFilter.invoke(ContextTransferProcessFilter.java:43)

at com.dianping.pigeon.remoting.provider.process.filter.ContextTransferProcessFilter.invoke(ContextTransferProcessFilter.java:28)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.WriteResponseProcessFilter.invoke(WriteResponseProcessFilter.java:36)

at com.dianping.pigeon.remoting.provider.process.filter.WriteResponseProcessFilter.invoke(WriteResponseProcessFilter.java:26)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.TrafficRecordFilter.invoke(TrafficRecordFilter.java:34)

at com.dianping.pigeon.remoting.provider.process.filter.TrafficRecordFilter.invoke(TrafficRecordFilter.java:14)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.InnerTracerFilter.invoke(InnerTracerFilter.java:29)

at com.dianping.pigeon.remoting.provider.process.filter.InnerTracerFilter.invoke(InnerTracerFilter.java:15)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.MonitorProcessFilter.invoke(MonitorProcessFilter.java:101)

at com.dianping.pigeon.remoting.provider.process.filter.MonitorProcessFilter.invoke(MonitorProcessFilter.java:35)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.TracerFilter.invoke(TracerFilter.java:37)

at com.dianping.pigeon.remoting.provider.process.filter.TracerFilter.invoke(TracerFilter.java:15)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.filter.ProviderContextFilter.invoke(ProviderContextFilter.java:28)

at com.dianping.pigeon.remoting.provider.process.filter.ProviderContextFilter.invoke(ProviderContextFilter.java:18)

at com.dianping.pigeon.remoting.provider.process.ProviderProcessHandlerFactory$1.handle(ProviderProcessHandlerFactory.java:99)

at com.dianping.pigeon.remoting.provider.process.threadpool.RequestThreadPoolProcessor$2.call(RequestThreadPoolProcessor.java:254)

at com.dianping.pigeon.remoting.provider.process.threadpool.RequestThreadPoolProcessor$2.call(RequestThreadPoolProcessor.java:243)

at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

- <0x00000007ab2b6228> (a java.util.concurrent.ThreadPoolExecutor$Worker)

Pigeon 阻塞线程 ThreadDump 信息

priority:5 - threadId:0x00007fa599636000 - nativeId:0x2ec8 - nativeId (decimal):11976 - state:BLOCKED

stackTrace:

java.lang.Thread.State: BLOCKED (on object monitor)

at deps.redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:207)

at deps.redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:47)

at deps.redis.clients.jedis.Protocol.process(Protocol.java:204)

at deps.redis.clients.jedis.Protocol.read(Protocol.java:271)

at deps.redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:305)

at deps.redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:236)

at deps.redis.clients.jedis.BinaryJedis.hget(BinaryJedis.java:788)

at deps.redis.clients.jedis.BinaryJedisCluster$13.execute(BinaryJedisCluster.java:202)

at deps.redis.clients.jedis.BinaryJedisCluster$13.execute(BinaryJedisCluster.java:199)

at deps.redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:64)

at deps.redis.clients.jedis.JedisClusterCommand.runBinary(JedisClusterCommand.java:41)

at deps.redis.clients.jedis.BinaryJedisCluster.hget(BinaryJedisCluster.java:199)

at com.dianping.squirrel.client.impl.redis.RedisStoreClientImpl$41.excute(RedisStoreClientImpl.java:1022)

at com.dianping.squirrel.client.impl.AbstractStoreClient$MonitorCommand.run(AbstractStoreClient.java:1066)

at com.dianping.squirrel.client.impl.redis.RedisStoreClientImpl.hget(RedisStoreClientImpl.java:1018)

at com.dianping.poi.mainflow.core.redisdao.TimestampRedisDao.getUpdateTime(TimestampRedisDao.java:18)

at com.dianping.poi.mainflow.common.RefreshableCache.checkUpdate(RefreshableCache.java:99)

- locked <0x00000007623197a0> (a com.dianping.poi.mainflow.core.cache.FlowTemplateRuleCache)

at com.dianping.poi.mainflow.common.RefreshableCache.getValue(RefreshableCache.java:53)

at com.dianping.poi.mainflow.common.RefreshableCache.getValue(RefreshableCache.java:43)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.getTemplateRule(WorkflowBusiness.java:160)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.setTemplateByWorkflow(WorkflowBusiness.java:134)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:253)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:183)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness.createWorkflow(WorkflowBusiness.java:176)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness$$FastClassBySpringCGLIB$$f3bb47a4.invoke( <generated> )

at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)

at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:736)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)

at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)

at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671)

at com.dianping.poi.mainflow.core.business.WorkflowBusiness$$EnhancerBySpringCGLIB$$e721a2aa.createWorkflow( <generated> )