概要描述

问题现象：常见于 一个存储过程内的连续2个sql，第一个结束后，等几分钟才开始支持下一个sql。

先说结论：dbaservice不包含下面2个阶段的时间

1.task.MAPRED-SPARK.Stage中（一般是读表）， OrcGetSplit 后面的 将数据挪到中间计算结果
2.stask.MOVE.Stage 中（一般是写表），将中间计算结果写入到目标表数据目录

详细说明

我们结合 quark server 的INFO级别日志逐个解析PERFLOG：

第一个job 776505:

OrcGetSplits 在 09:02:07 执行结束

2025-05-26 09:02:07,763 INFO orc.OrcInputFormat: (PerfLogger.java:PerfLogEnd(138)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – </PERFLOG method=OrcGetSplits start=1748221327753 end=1748221327763 duration=10>

第一个job 776505 开始时间记录 09:02:08,137

2025-05-26 09:02:08,137 INFO scheduler.DAGScheduler: (Logging.scala:logInfo(59)) [sparkDriver-akka.actor.default-dispatcher-22()] – Submitting Stage 913008 (MapPartitionsRDD[11523063] at withDescription at Operator.scala:624), which has no missing parents, from job 776502

第一个job 776505 结束时间记录 09:04:24,334

2025-05-26 09:04:24,334 INFO inceptor.InceptorContext: (Logging.scala:logInfo(59)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Job finished: runJob at FileSinkOperator.scala:315, took 136.225020004 s

这是将数据挪到中间计算结果

2025-05-26 09:04:24,379 INFO exec.FileSinkOperator: (Utilities.java:mvFileToFinalPath(2017)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.rowCount.-ext-10001 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e …
,379 INFO exec.FileSinkOperator: (Utilities.java:mvFileToFinalPath(2017)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.rowCount.-ext-10001 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/rowCount.-ext-10001
403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.rowCount.-ext-10001 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/rowCount.-ext-10001
2025-05-26 09:04:24,425 INFO exec.FileSinkOperator: (Utilities.java:mvFileToFinalPath(2017)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.-ext-10000 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2 …
,425 INFO exec.FileSinkOperator: (Utilities.java:mvFileToFinalPath(2017)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.-ext-10000 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/-ext-10000
8adc-ba98403f5e68)] – Moving tmp dir: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/_tmp.-ext-10000 to: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/-ext-10000
2025-05-26 09:04:29,081 INFO leviathan.TimedEventTracker: (Logging.scala:logInfo(59)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – [Leviathan][74314854]RegularId: 4e1b58550df3cece Extra Info: Session: 8eaad63e-79b2-48ba-8adc-ba98403f5e68 JobNo: 0 Time: 141566
INFO leviathan.TimedEventTracker: (Logging.scala:logInfo(59)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – [Leviathan][74314854]RegularId: 4e1b58550df3cece Extra Info: Session: 8eaad63e-79b2-48ba-8adc-ba98403f5e68 JobNo: 0 Time: 141566

2025-05-26 09:02:08,109 INFO inceptor.InceptorContext: (Logging.scala:logInfo(59)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Starting job: runJob at FileSinkOperator.scala:315
2025-05-26 09:04:29,085 INFO ql.Driver: (PerfLogger.java:PerfLogEnd(138)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – </PERFLOG method=task.MAPRED-SPARK.Stage-19 start=1748221327470 end=1748221469085 duration=141615>

task.MOVE.Stage-20 开始

2025-05-26 09:04:29,085 INFO ql.Driver: (PerfLogger.java:PerfLogBegin(111)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] –

这是 中间计算结果写入到目标表数据目录

….
2025-05-26 09:07:53,251 INFO metadata.Hive: (Hive.java:moveFile(4760)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Renaming src: hdfs://nameservice1/inceptor9/tmp/hive/etl/8eaad63e-79b2-48ba-8adc-ba98403f5e68/hive_2025-05-26_09-02-07_083_6092310148995332798-10049/-ext-10000/001954_0, dest: hdfs://nameservice1/inceptor1/user/hive/warehouse/pub.db/pub/t_pub_cqrm_airport_feature_2/001954_0, Status:true
…..

2025-05-26 09:07:53,384 INFO ql.Driver: (PerfLogger.java:PerfLogEnd(138)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – </PERFLOG method=task.MOVE.Stage-20 start=1748221469085 end=1748221673384 duration=204299>

第二个job 776879:

第二个job 776879 开始时间记录 09:07:53,591

2025-05-26 09:07:53,591 INFO scheduler.DAGScheduler: (Logging.scala:logInfo(59)) [sparkDriver-akka.actor.default-dispatcher-44()] – Submitting Stage 913384 (MapPartitionsRDD[11525826] at withDescription at Operator.scala:624), which has no missing parents, from job 776879

第二个job 776879 结束时间记录 09:07:53,693

2025-05-26 09:07:53,693 INFO inceptor.InceptorContext: (Logging.scala:logInfo(59)) [Session Thread,58996,sql,387182-1748221261770(SessionHandle=8eaad63e-79b2-48ba-8adc-ba98403f5e68)] – Job finished: runJob at FileSinkOperator.scala:315, took 0.103383817 s