From 5b78f6cd6387c36158652b90a650227a1430231a Mon Sep 17 00:00:00 2001 From: Onder Kalaci Date: Mon, 29 Mar 2021 18:25:18 +0200 Subject: [PATCH] Keep more execution statistics When DEBUG4 enabled, Citus now prints per task execution times. --- .../distributed/executor/adaptive_executor.c | 36 ++++++++++++++++++- .../expected/multi_mx_reference_table.out | 16 ++------- .../regress/sql/multi_mx_reference_table.sql | 4 +-- 3 files changed, 39 insertions(+), 17 deletions(-) diff --git a/src/backend/distributed/executor/adaptive_executor.c b/src/backend/distributed/executor/adaptive_executor.c index 5d2908bd8..5ebdd642d 100644 --- a/src/backend/distributed/executor/adaptive_executor.c +++ b/src/backend/distributed/executor/adaptive_executor.c @@ -586,6 +586,10 @@ typedef struct TaskPlacementExecution /* index in array of placement executions in a ShardCommandExecution */ int placementExecutionIndex; + + /* execution time statistics for this placement execution */ + instr_time startTime; + instr_time endTime; } TaskPlacementExecution; @@ -1763,6 +1767,8 @@ AssignTasksToConnectionsOrWorkerPool(DistributedExecution *execution) placementExecution->workerPool = workerPool; placementExecution->placementExecutionIndex = placementExecutionIndex; placementExecution->queryIndex = 0; + INSTR_TIME_SET_ZERO(placementExecution->startTime); + INSTR_TIME_SET_ZERO(placementExecution->endTime); if (placementExecutionReady) { @@ -3634,7 +3640,6 @@ StartPlacementExecutionOnSession(TaskPlacementExecution *placementExecution, ShardPlacement *taskPlacement = placementExecution->shardPlacement; List *placementAccessList = PlacementAccessListForTask(task, taskPlacement); - if (execution->transactionProperties->useRemoteTransactionBlocks != TRANSACTION_BLOCKS_DISALLOWED) { @@ -3656,6 +3661,17 @@ StartPlacementExecutionOnSession(TaskPlacementExecution *placementExecution, session->currentTask = placementExecution; placementExecution->executionState = PLACEMENT_EXECUTION_RUNNING; + Assert(INSTR_TIME_IS_ZERO(placementExecution->startTime)); + + /* + * The same TaskPlacementExecution can be used to have + * call SendNextQuery() several times if queryIndex is + * non-zero. Still, all are executed under the current + * placementExecution, so we can start the timer right + * now. + */ + INSTR_TIME_SET_CURRENT(placementExecution->startTime); + bool querySent = SendNextQuery(placementExecution, session); if (querySent) { @@ -4249,6 +4265,24 @@ PlacementExecutionDone(TaskPlacementExecution *placementExecution, bool succeede { /* mark the placement execution as finished */ placementExecution->executionState = PLACEMENT_EXECUTION_FINISHED; + + Assert(INSTR_TIME_IS_ZERO(placementExecution->endTime)); + INSTR_TIME_SET_CURRENT(placementExecution->endTime); + + if (IsLoggableLevel(DEBUG4)) + { + long durationMillisecs = + MillisecondsBetweenTimestamps(placementExecution->startTime, + placementExecution->endTime); + + ereport(DEBUG4, (errmsg("task execution (%d) for placement (%ld) on anchor " + "shard (%ld) finished in %ld msecs on worker " + "node %s:%d", shardCommandExecution->task->taskId, + placementExecution->shardPlacement->placementId, + shardCommandExecution->task->anchorShardId, + durationMillisecs, workerPool->nodeName, + workerPool->nodePort))); + } } else if (CanFailoverPlacementExecutionToLocalExecution(placementExecution)) { diff --git a/src/test/regress/expected/multi_mx_reference_table.out b/src/test/regress/expected/multi_mx_reference_table.out index 6474843cc..6ec100c80 100644 --- a/src/test/regress/expected/multi_mx_reference_table.out +++ b/src/test/regress/expected/multi_mx_reference_table.out @@ -918,26 +918,14 @@ SELECT create_reference_table('numbers'); (1 row) -SET client_min_messages TO debug4; +SET log_min_messages TO debug4; INSERT INTO numbers VALUES (1), (2), (3), (4); -DEBUG: Creating router plan -DEBUG: query before rebuilding: (null) -DEBUG: query after rebuilding: INSERT INTO public.numbers_1250015 AS citus_table_alias (a) VALUES (1), (2), (3), (4) -DEBUG: assigned task to node localhost:xxxxx -DEBUG: opening 1 new connections to localhost:xxxxx -DEBUG: established connection to localhost:xxxxx for session 4 -DEBUG: opening 1 new connections to localhost:xxxxx -DEBUG: established connection to localhost:xxxxx for session 5 -DEBUG: Total number of commands sent over the session 4: 1 -DEBUG: Total number of commands sent over the session 5: 1 SELECT count(*) FROM numbers; -DEBUG: Distributed planning for a fast-path router query -DEBUG: Creating router plan count --------------------------------------------------------------------- 4 (1 row) -RESET client_min_messages; +RESET log_min_messages; -- clean up tables DROP TABLE reference_table_test, reference_table_test_second, reference_table_test_third, numbers; diff --git a/src/test/regress/sql/multi_mx_reference_table.sql b/src/test/regress/sql/multi_mx_reference_table.sql index ea43da9bf..8bd1de9d3 100644 --- a/src/test/regress/sql/multi_mx_reference_table.sql +++ b/src/test/regress/sql/multi_mx_reference_table.sql @@ -562,10 +562,10 @@ SET citus.log_multi_join_order TO FALSE; -- issue 3766 CREATE TABLE numbers(a int); SELECT create_reference_table('numbers'); -SET client_min_messages TO debug4; +SET log_min_messages TO debug4; INSERT INTO numbers VALUES (1), (2), (3), (4); SELECT count(*) FROM numbers; -RESET client_min_messages; +RESET log_min_messages; -- clean up tables DROP TABLE reference_table_test, reference_table_test_second, reference_table_test_third, numbers;