Skip to content

Commit c746114

Browse files
shangm2meta-codesync[bot]
shangm2
authored and
meta-codesync[bot]
committed
misc(runtimestats): Add runtime metric to find the max cpu time of running drivers per operator and expose existing ioWaitWallNanos (#15354)
Summary: as titled Pull Request resolved: #15354 Reviewed By: arhimondr, tanjialiang Differential Revision: D85927678 Pulled By: shangm2 fbshipit-source-id: 43f164ad80de3848d4080f16e96b31b754cad8d2
1 parent e681772 commit c746114

File tree

4 files changed

+32
-1
lines changed

4 files changed

+32
-1
lines changed

‎velox/exec/Driver.cpp‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -801,6 +801,19 @@ void Driver::closeOperators() {
801801
for (auto& op : operators_) {
802802
auto stats = op->stats(true);
803803
stats.numDrivers = 1;
804+
805+
// Calculate this driver's CPU time for this specific operator and add it as
806+
// a runtime stat. This will be aggregated across all drivers, with the max
807+
// field containing the CPU time from the longest running driver.
808+
uint64_t operatorCpuNanos = stats.addInputTiming.cpuNanos +
809+
stats.getOutputTiming.cpuNanos + stats.finishTiming.cpuNanos +
810+
stats.isBlockedTiming.cpuNanos;
811+
812+
if (operatorCpuNanos > 0) {
813+
stats.runtimeStats[OperatorStats::kDriverCpuTime] =
814+
RuntimeMetric(operatorCpuNanos, RuntimeCounter::Unit::kNanos);
815+
}
816+
804817
task()->addOperatorStats(stats);
805818
}
806819
}

‎velox/exec/OperatorStats.h‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -89,6 +89,11 @@ struct DynamicFilterStats {
8989
};
9090

9191
struct OperatorStats {
92+
/// Runtime stat name for per-driver CPU time (actual work time, not including
93+
/// blocked time) for this operator. The max field will contain the CPU time
94+
/// from the longest running single driver.
95+
static constexpr const char* kDriverCpuTime = "driverCpuTimeNanos";
96+
9297
/// Initial ordinal position in the operator's pipeline.
9398
int32_t operatorId = 0;
9499
int32_t pipelineId = 0;

‎velox/exec/OperatorUtils.cpp‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -130,7 +130,9 @@ bool shouldAggregateRuntimeMetric(const std::string& name) {
130130
"dataSourceAddSplitWallNanos",
131131
"dataSourceLazyWallNanos",
132132
"queuedWallNanos",
133-
"flushTimes"};
133+
"flushTimes",
134+
"driverCpuTimeNanos",
135+
"ioWaitWallNanos"};
134136
if (metricNames.contains(name)) {
135137
return true;
136138
}

‎velox/exec/tests/PrintPlanWithStatsTest.cpp‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -170,13 +170,15 @@ TEST_F(PrintPlanWithStatsTest, innerJoinWithTableScan) {
170170
{" dataSourceLazyCpuNanos[ ]* sum: .+, count: .+, min: .+, max: .+"},
171171
{" dataSourceLazyInputBytes[ ]* sum: .+, count: .+, min: .+, max: .+"},
172172
{" dataSourceLazyWallNanos[ ]* sum: .+, count: 1, min: .+, max: .+"},
173+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
173174
{" runningAddInputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
174175
{" runningFinishWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
175176
{" runningGetOutputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
176177
{" -- HashJoin\\[3\\]\\[INNER c0=u_c0\\] -> c0:INTEGER, c1:BIGINT, u_c1:BIGINT"},
177178
{" Output: 2000 rows \\(.+\\), Cpu time: .+, Blocked wall time: .+, Peak memory: .+, Memory allocations: .+, CPU breakdown: B/I/O/F (.+/.+/.+/.+)"},
178179
{" HashBuild: Input: 100 rows \\(.+\\), Output: 0 rows \\(.+\\), Cpu time: .+, Blocked wall time: .+, Peak memory: .+, Memory allocations: .+, Threads: 1, CPU breakdown: B/I/O/F (.+/.+/.+/.+)"},
179180
{" distinctKey0\\s+sum: 101, count: 1, min: 101, max: 101, avg: 101"},
181+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
180182
{" hashtable.buildWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
181183
{" hashtable.capacity\\s+sum: 200, count: 1, min: 200, max: 200, avg: 200"},
182184
{" hashtable.numDistinct\\s+sum: 100, count: 1, min: 100, max: 100, avg: 100"},
@@ -193,6 +195,8 @@ TEST_F(PrintPlanWithStatsTest, innerJoinWithTableScan) {
193195
true},
194196
{" blockedWaitForJoinBuildWallNanos\\s+sum: .+, count: 1, min: .+, max: .+",
195197
true},
198+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+",
199+
true},
196200
{" dynamicFiltersProduced\\s+sum: 1, count: 1, min: 1, max: 1, avg: 1",
197201
true},
198202
{" queuedWallNanos\\s+sum: .+, count: 1, min: .+, max: .+", true},
@@ -207,6 +211,7 @@ TEST_F(PrintPlanWithStatsTest, innerJoinWithTableScan) {
207211
{" connectorSplitSize[ ]* sum: .+, count: .+, min: .+, max: .+"},
208212
{" dataSourceAddSplitWallNanos[ ]* sum: .+, count: 1, min: .+, max: .+"},
209213
{" dataSourceReadWallNanos[ ]* sum: .+, count: .+, min: .+, max: .+"},
214+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
210215
{" dynamicFiltersAccepted[ ]* sum: 1, count: 1, min: 1, max: 1, avg: 1"},
211216
{" footerBufferOverread[ ]* sum: .+, count: 1, min: .+, max: .+"},
212217
{" ioWaitWallNanos [ ]* sum: .+, count: .+ min: .+, max: .+"},
@@ -234,11 +239,13 @@ TEST_F(PrintPlanWithStatsTest, innerJoinWithTableScan) {
234239
{" waitForPreloadSplitNanos[ ]* sum: .+, count: .+, min: .+, max: .+, avg: .+"},
235240
{" -- Project\\[1\\]\\[expressions: \\(u_c0:INTEGER, ROW\\[\"c0\"\\]\\), \\(u_c1:BIGINT, ROW\\[\"c1\"\\]\\)\\] -> u_c0:INTEGER, u_c1:BIGINT"},
236241
{" Output: 100 rows \\(.+\\), Cpu time: .+, Blocked wall time: .+, Peak memory: 0B, Memory allocations: .+, Threads: 1, CPU breakdown: B/I/O/F (.+/.+/.+/.+)"},
242+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
237243
{" runningAddInputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
238244
{" runningFinishWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
239245
{" runningGetOutputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
240246
{" -- Values\\[0\\]\\[100 rows in 1 vectors\\] -> c0:INTEGER, c1:BIGINT"},
241247
{" Input: 0 rows \\(.+\\), Output: 100 rows \\(.+\\), Cpu time: .+, Blocked wall time: .+, Peak memory: 0B, Memory allocations: .+, Threads: 1, CPU breakdown: B/I/O/F (.+/.+/.+/.+)"},
248+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
242249
{" runningAddInputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
243250
{" runningFinishWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
244251
{" runningGetOutputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"}});
@@ -291,6 +298,7 @@ TEST_F(PrintPlanWithStatsTest, partialAggregateWithTableScan) {
291298
{" dataSourceLazyInputBytes\\s+sum: .+, count: .+, min: .+, max: .+"},
292299
{" dataSourceLazyWallNanos\\s+sum: .+, count: .+, min: .+, max: .+"},
293300
{" distinctKey0\\s+sum: .+, count: 1, min: .+, max: .+"},
301+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
294302
{" hashtable.capacity\\s+sum: (?:1273|1252), count: 1, min: (?:1273|1252), max: (?:1273|1252), avg: (?:1273|1252)"},
295303
{" hashtable.numDistinct\\s+sum: (?:849|835), count: 1, min: (?:849|835), max: (?:849|835), avg: (?:849|835)"},
296304
{" hashtable.numRehashes\\s+sum: 1, count: 1, min: 1, max: 1, avg: 1"},
@@ -304,6 +312,7 @@ TEST_F(PrintPlanWithStatsTest, partialAggregateWithTableScan) {
304312
{" connectorSplitSize[ ]* sum: .+, count: .+, min: .+, max: .+"},
305313
{" dataSourceAddSplitWallNanos[ ]* sum: .+, count: 1, min: .+, max: .+"},
306314
{" dataSourceReadWallNanos[ ]* sum: .+, count: .+, min: .+, max: .+"},
315+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
307316
{" footerBufferOverread[ ]* sum: .+, count: 1, min: .+, max: .+"},
308317
{" ioWaitWallNanos [ ]* sum: .+, count: .+ min: .+, max: .+"},
309318
{" numPrefetch [ ]* sum: .+, count: .+, min: .+, max: .+"},
@@ -366,6 +375,7 @@ TEST_F(PrintPlanWithStatsTest, tableWriterWithTableScan) {
366375
{" dataSourceLazyCpuNanos\\s+sum: .+, count: .+, min: .+, max: .+"},
367376
{" dataSourceLazyInputBytes\\s+sum: .+, count: .+, min: .+, max: .+"},
368377
{" dataSourceLazyWallNanos\\s+sum: .+, count: .+, min: .+, max: .+"},
378+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
369379
{" dwrfWriterCount\\s+sum: .+, count: 1, min: .+, max: .+"},
370380
{" numWrittenFiles\\s+sum: .+, count: 1, min: .+, max: .+"},
371381
{" runningAddInputWallNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
@@ -379,6 +389,7 @@ TEST_F(PrintPlanWithStatsTest, tableWriterWithTableScan) {
379389
{" connectorSplitSize[ ]* sum: .+, count: .+, min: .+, max: .+"},
380390
{" dataSourceAddSplitWallNanos[ ]* sum: .+, count: 1, min: .+, max: .+"},
381391
{" dataSourceReadWallNanos[ ]* sum: .+, count: .+, min: .+, max: .+"},
392+
{" driverCpuTimeNanos\\s+sum: .+, count: 1, min: .+, max: .+"},
382393
{" footerBufferOverread[ ]* sum: .+, count: 1, min: .+, max: .+"},
383394
{" ioWaitWallNanos [ ]* sum: .+, count: .+ min: .+, max: .+"},
384395
{" numPrefetch [ ]* sum: .+, count: .+, min: .+, max: .+"},

0 commit comments

Comments
 (0)