cd ..

executor定时流程卡住排查记录

# 问题排查
芯笑

背景

2026-06-25 早上发现data-center-executor里有定时流程一直没有继续跑。日志里每半小时都会打印一次“正在运行，放弃本次运行”。

涉及流程：

processId: 2067059402225221633
processName: 140.58-2026-in-admit-adilt-diag-discharge
Oracle 数据源: 2067059022670069761
Oracle 地址: 172.31.140.58:1521/orcl

当时没有停服务，也没有重启 jar，所以现场还在，适合直接查线程和连接池状态。

最开始看到的现象

流程从01:30开始执行，后面02:00、02:30、03:00一直到早上都被跳过。

流程运行日志里能看到：

2026-06-25 05:00:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 04:30:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 04:00:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 03:30:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 03:00:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 02:30:04 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 02:00:06 【INFO】 RunScheduledTask ： 流程2067059402225221633正在运行，放弃本次运行，时间：2026-06-25
2026-06-25 01:30:03 【REPORT】 RunScheduledTask ： 流程开始执行,共 8 步骤

这里第一感觉容易误判成“锁没有释放”。但还不能直接下结论，需要先确认01:30那次到底有没有执行结束。

先查加锁和解锁日志

在服务器日志目录执行：

for f in executor-2026-06-25*.zip; do
  echo "===== $f ====="
  unzip -p "$f" | grep -n "2067059402225221633" | grep -E "加锁成功|当前实例进程id|unLock结果|正在运行|发送流程运行结果消息"
done

查到的关键结果：

19845:2026-06-25 00:00:03.163 INFO  [,] [quartzScheduler_Worker-48] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge加锁成功
19846:2026-06-25 00:00:03.163 INFO  [,] [quartzScheduler_Worker-48] com.xxx.datacenter.executor.main.job.TaskJob : 当前实例进程id:2069672394090426369,当前流程id：2067059402225221633
25921:2026-06-25 00:00:04.180 INFO  [,] [quartzScheduler_Worker-48] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge，unLock结果:true

49476:2026-06-25 00:30:03.447 INFO  [,] [quartzScheduler_Worker-9] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge加锁成功
49478:2026-06-25 00:30:03.447 INFO  [,] [quartzScheduler_Worker-9] com.xxx.datacenter.executor.main.job.TaskJob : 当前实例进程id:2069672394090426369,当前流程id：2067059402225221633
55916:2026-06-25 00:30:04.843 INFO  [,] [quartzScheduler_Worker-9] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge，unLock结果:true

79114:2026-06-25 01:00:03.212 INFO  [,] [quartzScheduler_Worker-10] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge加锁成功
79115:2026-06-25 01:00:03.212 INFO  [,] [quartzScheduler_Worker-10] com.xxx.datacenter.executor.main.job.TaskJob : 当前实例进程id:2069672394090426369,当前流程id：2067059402225221633
86451:2026-06-25 01:00:04.962 INFO  [,] [quartzScheduler_Worker-10] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge，unLock结果:true

109376:2026-06-25 01:30:03.916 INFO  [,] [quartzScheduler_Worker-18] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2069672394090426369,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge加锁成功
109378:2026-06-25 01:30:03.916 INFO  [,] [quartzScheduler_Worker-18] com.xxx.datacenter.executor.main.job.TaskJob : 当前实例进程id:2069672394090426369,当前流程id：2067059402225221633
136434:2026-06-25 02:00:06.175 INFO  [,] [quartzScheduler_Worker-7] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2067059402225221633,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge正在运行，已经加锁
162996:2026-06-25 02:30:04.630 INFO  [,] [quartzScheduler_Worker-10] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2067059402225221633,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge正在运行，已经加锁
189453:2026-06-25 03:00:04.292 INFO  [,] [quartzScheduler_Worker-1] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2067059402225221633,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge正在运行，已经加锁
215562:2026-06-25 03:30:04.313 INFO  [,] [quartzScheduler_Worker-30] com.xxx.datacenter.executor.main.job.TaskJob : 流程runId:2067059402225221633,2067059402225221633-140.58-2026-in-admit-adilt-diag-discharge正在运行，已经加锁

这里能看出：

这里先记一个小坑：TaskJob里“正在运行，已经加锁”的日志参数写错了，第一个runId打印的是processId，不是实际processRunId。所以02:00后日志里的：

流程runId:2067059402225221633

不要当成真实 runId。真实 runId 仍然是前面加锁成功的：

2069672394090426369

抓线程栈

因为01:30没有解锁，下一步要看执行线程卡在哪。

如果有jcmd：

jcmd 61693 Thread.print -l > /tmp/thread-20260625-1.txt
sleep 10
jcmd 61693 Thread.print -l > /tmp/thread-20260625-2.txt
sleep 10
jcmd 61693 Thread.print -l > /tmp/thread-20260625-3.txt

然后查01:30的 worker 线程：

grep -n -A80 '"quartzScheduler_Worker-18"' /tmp/thread-20260625-*.txt

三次线程栈里quartzScheduler_Worker-18都在同一个位置：

"quartzScheduler_Worker-18" ... java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:2185)
    at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1678)
    at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1415)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1395)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1385)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getSqlConn(DatabaseAccessor.java:458)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getColumnsBySql(DatabaseAccessor.java:529)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getColumns(DatabaseAccessor.java:517)
    at com.xxx.data.operator.reader.increment.DatabaseIncReader.read(DatabaseIncReader.java:43)
    at com.xxx.data.operator.reader.increment.OracleIncReader.executeDataOperate(OracleIncReader.java:29)
    at com.xxx.data.operator.step.BaseStep.convertDataset(BaseStep.java:303)
    at com.xxx.data.operator.step.BaseStep.executeStep(BaseStep.java:268)
    at com.xxx.data.operator.step.BaseStep.execute(BaseStep.java:234)
    at com.xxx.datacenter.executor.main.process.BaseProcessJob.executeProcess(BaseProcessJob.java:133)
    at com.xxx.datacenter.executor.main.process.BaseProcessJob.execute(BaseProcessJob.java:112)
    at com.xxx.datacenter.executor.main.job.TaskJob.execute(TaskJob.java:72)

这个栈说明01:30那次流程已经进入了TaskJob.execute()，也已经加了流程锁，但卡在 Oracle 增量读取器读取前的字段获取逻辑上。

卡住位置不是业务处理，也不是 Doris 写入，而是：

OracleIncReader
  -> DatabaseIncReader.read()
    -> DatabaseAccessor.getColumns()
      -> DatabaseAccessor.getSqlConn()
        -> DruidDataSource.getConnection()
          -> DruidDataSource.takeLast()

同时还看到其他线程在 Oracle 连接校验里：

OracleValidConnectionChecker.isValidConnection
SocketInputStream.socketRead0
DruidDataSource.getConnectionDirect
DatabaseAccessor.getSqlConn

这个现象更像 Druid/Oracle 连接创建或校验卡住，而不是流程锁本身有问题。

用 Arthas 查业务 Druid 池

进入Arthas选择xxx-data-center-executor进程后，先看业务动态数据源池有哪些 key：

ognl -c 685f4c2e '@com.xxx.xxx.db.dataSource.BaseDataSource@GLOBAL_CONNECTION_POOL.keySet()'

输出里能看到问题数据源：

@KeySetView[
    @String[Oracle-2059072794226065410-2059072794226065410],
    @String[Oracle-2056546131449741314-2056546131449741314],
    @String[Oracle-2059460523493425153-2059460523493425153],
    @String[DroisDB-2048961542413893633-2048961542413893633],
    ...
    @String[Oracle-2067059022670069761-2067059022670069761],
]

再查这个 Oracle 池的状态：

ognl -c 685f4c2e '#f=@com.xxx.xxx.db.dataSource.BaseDataSource@GLOBAL_CONNECTION_POOL.get("Oracle-2067059022670069761-2067059022670069761"),#ds=#f.get(),{#ds.getName(),#ds.getUrl(),#ds.getInitialSize(),#ds.getMaxActive(),#ds.getActiveCount(),#ds.getPoolingCount(),#ds.getWaitThreadCount(),#ds.getConnectCount(),#ds.getCloseCount(),#ds.getCreateErrorCount()}'

输出：

@ArrayList[
    @String[Oracle-2067059022670069761-2067059022670069761],
    @String[jdbc:oracle:thin:@172.31.140.58:1521/orcl],
    @Integer[2],
    @Integer[100],
    @Integer[0],
    @Integer[0],
    @Integer[10],
    @Long[1370],
    @Long[1358],
    @Long[1],
]

继续查更详细的状态：

ognl -c 685f4c2e '#f=@com.xxx.xxx.db.dataSource.BaseDataSource@GLOBAL_CONNECTION_POOL.get("Oracle-2067059022670069761-2067059022670069761"),#ds=#f.get(),{#ds.getActiveCount(),#ds.getPoolingCount(),#ds.getWaitThreadCount(),#ds.getCreateCount(),#ds.getDestroyCount(),#ds.getConnectCount(),#ds.getCloseCount(),#ds.getCreateErrorCount(),#ds.getNotEmptyWaitCount(),#ds.getNotEmptyWaitMillis(),#ds.isClosed()}'

输出：

@ArrayList[
    @Integer[0],
    @Integer[0],
    @Integer[10],
    @Long[3],
    @Long[1],
    @Long[1370],
    @Long[1358],
    @Long[1],
    @Long[322],
    @Long[0],
    @Boolean[false],
]

这组数据当时需要结合现场动作看。查询时，因为卡住的流程已经被手动停止过，并且重新加入了 10 个调度流程。所以这组数据不能解释成“老的 01:30 流程还占用连接”。

更准确的解释是：

如果是典型连接泄漏，一般会看到：

activeCount 接近 maxActive
poolingCount = 0
waitThreadCount > 0

但现场不是这样。这里更像是：池里没有可用连接，同时 Druid 创建或校验 Oracle 连接不顺畅，导致线程都在等。

手动执行 runNow 后的日志

后面又执行了一次runNowProcess，日志里先看到步骤加载时复用数据源：

2026-06-25 14:43:29.623 INFO [http-nio-8231-exec-5] ExecutorController : 接收到命令 action=:runNowProcess
2026-06-25 14:43:29.664 INFO [http-nio-8231-exec-5] BaseDataSource : 复用数据源【Oracle-2067059022670069761-2067059022670069761】
2026-06-25 14:43:29.665 INFO [http-nio-8231-exec-5] BaseDataSource : 复用数据源【DroisDB-2048961542413893633-2048961542413893633】

随后run-now1线程出现了一段 Druid 初始化和关闭：

2026-06-25 14:43:29.680 INFO [run-now1] DatabaseDataSource : 注册数据源【Oracle-2067059022670069761-2067059022670069761】【jdbc:oracle:thin:@172.31.140.58:1521/orcl】
2026-06-25 14:43:29.768 INFO [run-now1] DruidDataSource : {dataSource-46678,Oracle-2067059022670069761-2067059022670069761} inited
2026-06-25 14:43:29.768 INFO [run-now1] DruidDataSource : {dataSource-46678} closing ...
2026-06-25 14:43:29.777 INFO [run-now1] DruidDataSource : {dataSource-46678} closed

这段不是全局池恢复了，而是connectTest()临时创建了一个 Druid 池，初始化成功后马上关闭。

也就是说：

connectTest 成功，只能说明“临时新建一个池可以成功初始化”
不能说明 GLOBAL_CONNECTION_POOL 里的旧池是健康的

后面 Quartz 线程又报了 Oracle 连接校验错误：

2026-06-25 14:45:35.768 ERROR [quartzScheduler_Worker-37] JdbcUtils : close statement error
java.sql.SQLRecoverableException: 关闭的连接
    at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:5416)
    at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1585)
    at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1570)
    at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:98)
    at com.alibaba.druid.pool.vendor.OracleValidConnectionChecker.isValidConnection(OracleValidConnectionChecker.java:88)
    at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1471)
    at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1470)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1395)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getSqlConn(DatabaseAccessor.java:458)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getColumnsBySql(DatabaseAccessor.java:529)
    at com.xxx.xxx.db.accessor.DatabaseAccessor.getColumns(DatabaseAccessor.java:517)
    at com.xxx.data.operator.reader.increment.DatabaseIncReader.read(DatabaseIncReader.java:43)
    at com.xxx.data.operator.reader.increment.OracleIncReader.executeDataOperate(OracleIncReader.java:29)
    at com.xxx.datacenter.executor.main.process.BaseProcessJob.executeProcess(BaseProcessJob.java:133)
    at com.xxx.datacenter.executor.main.job.TaskJob.execute(TaskJob.java:72)

这个和线程栈能对上：Quartz 线程真正从全局 Druid 池里拿连接时，Druid 在校验 Oracle 连接，发现底层连接已经关闭。

代码链路梳理

加入定时调度

入口：

RunScheduledTask.procMessage()

主要流程：

RunScheduledTask.procMessage()
  -> getOrBuildProcessRun(processId)
  -> ProcessJobRepositoryHelper.loadProcessJobByProcessRunId(processRunId)
  -> RunTimeFactory.build(...)
  -> buildTempLogCollector(...)
  -> ProcessRunCache.putProcessRunCache(processJob)
  -> SchedulerManage.addAndStartJob(processJob)
  -> startRelate(...)

加载流程步骤时会处理步骤属性：

ProcessJobRepositoryHelper.loadProcessJobByProcessRunId()
  -> loadStepJobById(processId)
  -> buildProcessStep(...)
  -> buildProcessStepProp(...)
  -> RepositoryHelper.buildSpecialProp(stepProp)

如果步骤里有dataSourceId，就会构建数据源对象：

IDataSource dataSource = DataSourceUtils.buildAndInitDataSource(dataSourceVo);
stepProp.setValue("dataSource", dataSource);

创建 Quartz Job

入口：

SchedulerManage.addAndStartJob()

主要做：

JobBuilder.newJob(TaskJob.class)
jobDataMap.put("processJobRunId", runId)
CronScheduleBuilder.cronSchedule(timeExp)
scheduler.scheduleJob(jobDetail, cronTrigger)

Quartz 里保存的是processJobRunId。

Quartz 到点执行

入口：

TaskJob.execute()

主要流程：

TaskJob.execute()
  -> ProcessRunCache.getProcessRunCache(processJobRunId)
  -> SynchronousLock.isLock(runId)
  -> SynchronousLock.lock(runId)
  -> processJob.execute()
  -> finally SynchronousLock.unLock(runId)

这里要注意：ProcessRunCache.getProcessRunCache()不是直接返回老对象，而是会重新加载步骤：

getProcessRunCache()
  -> convertNewProcessJob()
  -> ProcessJobRepositoryHelper.loadStepJobById(processId)

所以每次 Quartz 触发执行，都会重新构建步骤和IDataSource对象。但是底层 Druid 池有全局缓存，所以一般会复用已有池。

流程内执行步骤

入口：

BaseProcessJob.executeProcess()

主要流程：

for step in stepList
  -> checkConnection(step)
  -> step.execute()
  -> saveReaderData(step)
  -> 更新增量值
  -> 更新流程运行统计

读步骤

这次卡住的是 Oracle 增量读取器：

OracleIncReader.executeDataOperate()
  -> DatabaseIncReader.read()

DatabaseIncReader.read()会先拿字段，再查数据：

dataSource.getAccessor().getColumns(tableName)
dataSource.getAccessor().query(queryParam, columns)

然后进入数据库访问层：

DatabaseAccessor.getColumns()
  -> getColumnsBySql()
  -> getSqlConn()
  -> DruidDataSource.getConnection()

这就是现场线程卡住的位置。

写步骤

普通数据库写入也是类似：

Writer.step.execute()
  -> dataSource.getAccessor().batchSave / batchUpdate / save
  -> DatabaseAccessor.getSqlConn()
  -> 执行 SQL
  -> Connection.close()

Connection.close()对 Druid 来说不是关闭物理连接，而是归还连接到池。

Doris writer 比较特殊，日志里看到的是 Stream Load：

DorisStreamLoadObserver : doris stream load response: ...

这类写入不完全等同于普通 JDBC 批量写入，但数据源对象仍然是在步骤属性构建时创建或复用的。

业务 Druid 池是怎么创建和销毁的

业务动态数据源在依赖包里：

xxx-db-engine-1.0-SNAPSHOT.jar
com.xxx.xxx.db.dataSource.DatabaseDataSource

构建数据源时会走：

DataSourceUtils.buildAndInitDataSource()
  -> DataSourceFactory.buildDataSource(...)
  -> dataSource.init()

dataSource.init()内部会走：

BaseDataSource.getConnectionPool(dsKey)

这个方法里有全局缓存：

GLOBAL_CONNECTION_POOL

逻辑大概是：

if (GLOBAL_CONNECTION_POOL.containsKey(dsKey)) {
    log.info("复用数据源【{}】", dsKey);
    return GLOBAL_CONNECTION_POOL.get(dsKey).get();
} else {
    FutureTask<Object> dsFutureTask = new FutureTask<>(this::registerConnectionPool);
    ...
}

第一次用某个dsKey：

GLOBAL_CONNECTION_POOL 没有 key
  -> registerConnectionPool()
  -> buildDruidDataSource()
  -> druid.init()
  -> 放进 GLOBAL_CONNECTION_POOL

后面再用：

GLOBAL_CONNECTION_POOL 已有 key
  -> 直接复用旧 DruidDataSource

这就是日志里“复用数据源”的来源。

销毁情况

当前代码里没有看到流程结束后销毁业务池：

步骤执行完：不销毁 IDataSource
流程执行完：不关闭 GLOBAL_CONNECTION_POOL 里的 Druid 池
停止调度：不关闭业务 Druid 池
JVM 不重启：业务池基本一直存在

依赖里的DatabaseDataSource.destroy()也没有真正DruidDataSource.close()。因此坏池一旦留在GLOBAL_CONNECTION_POOL，后续流程还会继续复用它。

为什么不是简单的“连接没释放”

代码里普通 SQL 查询路径是有关闭连接的：

Connection conn = getSqlConn()
PreparedStatement ps = conn.prepareStatement(sql)
ResultSet rs = ps.executeQuery()
rs.close()
ps.close()
conn.close()

这里的conn.close()会把连接归还给 Druid 池。

如果是典型连接没释放，Druid 状态通常会是：

activeCount 接近 maxActive
poolingCount = 0
waitThreadCount > 0

但这次重新调度后的快照是：

activeCount = 0
poolingCount = 0
waitThreadCount = 10

结合线程栈和日志，更像是：

Druid 池里没有空闲连接
新连接创建/校验 Oracle 连接不顺畅
线程在 DruidDataSource.takeLast 等可用连接
由于没有 maxWait 或超时时间，线程长时间不返回
TaskJob finally 走不到
流程锁不释放
后续调度全部放弃

目前判断

这次问题不是单纯的流程锁 bug。流程锁只是放大了故障表现。

更接近的根因是：

Oracle 业务数据源对应的 Druid 池无法正常产出可用连接。
池里没有空闲连接，创建或校验 Oracle 连接时出现关闭连接、socket 阻塞等问题。
由于 Druid 获取连接缺少 maxWait，Oracle JDBC 缺少连接/读取超时，线程一直等在 DruidDataSource.takeLast。
线程不返回，TaskJob finally 不执行，流程锁无法释放。

目前修改措施

1. Druid 池增加超时

在DatabaseDataSource.buildDruidDataSource()里补：

ds.setMaxWait(30000);
ds.setValidationQueryTimeout(10);
ds.setTestWhileIdle(true);
ds.setTimeBetweenEvictionRunsMillis(60000);

目的不是让连接一定成功，而是让失败能及时返回，避免流程线程无限等。

2. Oracle JDBC 增加连接和读取超时

在 Oracle JDBC URL 加：

oracle.net.CONNECT_TIMEOUT=10000
oracle.jdbc.ReadTimeout=60000

这个避免 Oracle 网络或服务端异常时，线程长时间卡在 socket 读。

最后结论

这次故障链路可以概括成一句话：

01:30 那次流程拿到流程锁后，在 Oracle 增量读取步骤里向 Druid 池拿连接时卡住；
Druid 池无法提供可用 Oracle 连接，又没有超时快速失败；
流程线程不返回，finally 不执行，锁不释放；
后续定时触发都判断流程还在运行，所以全部放弃。
# 问题排查
分享
下一篇
服务注册错误IP导致支付链路异常排查实录