记一次系统卡顿的问题

问题

系统发生卡顿，一开始是整个系统都卡，点哪里都有问题，然后被人误打误撞重启了redis，系统
恢复了很多，但是下午又发现，某些定时任务执行极其缓慢。

之前也发生过系统卡顿，但当时是因为数据库的连接池不够用，通过配置增加了Hikari连接池数量。通过查看日志，这次不是同样的问题。

排查

教你如何排查Java系统运行缓慢等问题 附详细思路 | w3cschool笔记

根据上述流程，排查内存、CUP、死锁之后，把目光放在了接口耗时和等待线程上。

Windows将jstack内容输出到文件的命令：

jstack <进程ID> > thread_dump_1.log

先说接口耗时，系统平时的并发量不大，而且也不是高峰期，基本不存在高并发导致接口阻塞。通过jstack也没有发现大量接口阻塞在某个接口。

然后就是等待线程，通过jstack发现大量线程处于等待状态，但是太多且规律不统一，无法确定问题。通过查询合同任务所在的类，发现了以下线程信息：

"RTF_CLUSTERED_JOB_SCHEDULER_Worker-6" #330 prio=5 os_prio=0 tid=0x000001d10e918800 nid=0x841c waiting on condition [0x0000000bd80fd000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000003c091b690> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:197)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414)
	at ch.qos.logback.classic.Logger.error(Logger.java:530)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.utils.Logger.error(Logger.java:17)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.utils.CommonTools.getResultData(CommonTools.java:211)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.service.MetaDataService.contractRpc(MetaDataService.java:1246)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.service.MetaDataService.getContractData(MetaDataService.java:1146)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.service.MetaDataService.CreateOrUpdateHtDict(MetaDataService.java:1110)
	at com.inspur.gs.qy.jzgx.cjhdjgx.core.timedTask.CHTimeTaskImpl.CreateOrUpdateHtDict(CHTimeTaskImpl.java:90)
	at sun.reflect.GeneratedMethodAccessor2839.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.inspur.edp.cdf.component.core.invoker.adapter.common.CommonComponentInvokeService.run(CommonComponentInvokeService.java:251)
	at com.inspur.edp.cdf.component.core.invoker.adapter.common.CommonComponentInvokeService.invokeByJson(CommonComponentInvokeService.java:109)
	at com.inspur.edp.cdf.component.core.invoker.adapter.common.CommonComponentInvoker.invokeByJson(CommonComponentInvoker.java:36)
	at com.inspur.edp.cdf.component.core.service.ComponentInvokeServiceImpl.invokeByJson(ComponentInvokeServiceImpl.java:120)
	at io.iec.edp.caf.scheduler.actuator.jobimpl.ComponentJobImpl.execute(ComponentJobImpl.java:82)
	at io.iec.edp.caf.scheduler.agent.RemoteJobAgentServer.execute(RemoteJobAgentServer.java:44)
	at io.iec.edp.caf.scheduler.agent.RemoteJobAgentServer.remoteExecute(RemoteJobAgentServer.java:59)
	at sun.reflect.GeneratedMethodAccessor614.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at io.iec.edp.caf.rpc.client.local.RpcLocalInvokerImpl.doInvoke(RpcLocalInvokerImpl.java:377)
	at io.iec.edp.caf.rpc.client.local.RpcLocalInvokerImpl.fireRpcInvocation(RpcLocalInvokerImpl.java:268)
	at io.iec.edp.caf.rpc.client.local.RpcLocalInvokerImpl.invokeLocalService(RpcLocalInvokerImpl.java:113)
	at io.iec.edp.caf.rpc.client.RpcClientImpl.invoke(RpcClientImpl.java:201)
	at io.iec.edp.caf.rpc.client.RpcClientImpl.invoke(RpcClientImpl.java:125)
	at io.iec.edp.caf.rpc.client.RpcClientImpl.invoke(RpcClientImpl.java:141)
	at io.iec.edp.caf.scheduler.service.worker.RemoteJobAgentLocalProxy.execute(RemoteJobAgentLocalProxy.java:53)
	at io.iec.edp.caf.scheduler.service.worker.LocalJobImpl.executeJob(LocalJobImpl.java:62)
	at io.iec.edp.caf.scheduler.service.worker.RTFSchedulerJob.execute(RTFSchedulerJob.java:56)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
	- locked <0x00000004652f0ba8> (a java.lang.Object)

然后发现很多线程都停在了写日志的操作上，一开始以为是日志框架出现了问题，通过搜索发现
这个文章：记一个写日志阻塞的问题_logback线程阻塞-优快云博客

这个大佬也遇到了相似的问题，感觉应该是同一个问题，但我们没有使用到Runtime.getRuntime().exec这个方法，思来想去可能是产品用了，没有处理好，无从证实。

后续

打了产品补丁之后，卡顿问题被解决，通过对比补丁前后的jstack文件，大概率确定是日志阻塞的问题