Merge pull request #4859 from citusdata/task_execution_stats

Keep more execution statistics

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))
 	{

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;

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;