citus
citus copied to clipboard
citusdata
Make citus work well with auto_explain extension.
Currently, using auto_explain extension for a citus database may cause issues such as crashes and unexpected behavior. Although it might be possible to use auto_explain for very limited scenarios which manage to avoid the problematic sql commands, we would like to make sure that auto_explain is usable for the larger set of use cases.
This general issue is created for tracking the other specific issues reported about citus with auto_explain and work items to do for enabling the best experience possible.
-
[x] #2920
-
[x] #6424
-
[ ] #6436
-
[x] https://github.com/citusdata/citus/issues/6777
-
[x] Explain analyze is disabled for local execution. This may be the root cause of test run hangs we encountered and needs more investigation for creating its own specific issue.
-
[ ] See below:
With configured auto_explain.log_nested_statements = on I managed to get the undetectable deadlock: -
[ ] Run arbitrary_configs for more test coverage.
Even if we make citus work fine with auto_explain, we still have two UX problems. We don't have to solve them now, but good to document.
- especially relevant for query from any node environments:
We log both the queries on the distributed tables and the queries on the shards even for the same query. I currently don't have a good way avoid that.
For example, query on the dist table:
table target_table ;
LOG: duration: 10.680 ms plan:
{
"Query Text": "table target_table ;",
"Plan": {
"Node Type": "Custom Scan",
"Custom Plan Provider": "Citus Adaptive",
"Parallel Aware": false,
"Async Capable": false,
"Startup Cost": 0.00,
"Total Cost": 0.00,
"Plan Rows": 100000,
"Plan Width": 8,
"Actual Rows": 5,
"Actual Loops": 1,
"Distributed Query": {
"Job": {
"Task Count": 32,
"Tuple data received from nodes": "40 bytes",
"Tasks Shown": "One of 32",
"Tasks": [
{
"Tuple data received from node": "8 bytes",
"Node": "host=localhost port=9701 dbname=postgres",
"Remote Plan": [
Seq Scan on target_table_102140 target_table (actual rows=1 loops=1)
]
}
]
}
}
}
}
And, #shards
{
"Query Text": "EXPLAIN (ANALYZE FALSE, VERBOSE FALSE, COSTS TRUE, BUFFERS FALSE, WAL FALSE, TIMING FALSE, SUMMARY FALSE, FORMAT JSON) SELECT col_1, col_2 FROM public.target_table_102139 target_table WHERE true",
"Plan": {
"Node Type": "Seq Scan",
"Parallel Aware": false,
"Async Capable": false,
"Relation Name": "target_table_102139",
"Alias": "target_table",
"Startup Cost": 0.00,
"Total Cost": 32.60,
"Plan Rows": 2260,
"Plan Width": 8
}
}
- When ALTER SYSTEM SET auto_explain.log_analyze = ON; we only see Citus' internal EXPLAIN/ANALYZE logic instead of queries on the shards:
2022-11-03 14:48:55.104 CET [18348] LOG: duration: 0.088 ms plan:
{
"Query Text": "SELECT * FROM worker_save_query_explain_analyze('SELECT col_1, col_2 FROM public.target_table_102169 target_table WHERE true', '{\"verbose\": false, \"costs\": false, \"buffers\": false, \"wal\": false, \"timing\": false, \"summary\": false, \"format\": \"TEXT\"}') AS (field_0 integer, field_1 integer)",
"Plan": {
"Node Type": "Function Scan",
"Parallel Aware": false,
"Async Capable": false,
"Function Name": "worker_save_query_explain_analyze",
"Alias": "worker_save_query_explain_analyze",
"Startup Cost": 0.00,
"Total Cost": 10.00,
"Plan Rows": 1000,
"Plan Width": 8,
"Actual Startup Time": 0.087,
"Actual Total Time": 0.087,
"Actual Rows": 0,
"Actual Loops": 1
}
}
2022-11-03 14:48:55.105 CET [18348] LOG: duration: 0.007 ms plan:
{
"Query Text": "SELECT explain_analyze_output, execution_duration FROM worker_last_saved_explain_analyze()",
"Plan": {
"Node Type": "Function Scan",
"Parallel Aware": false,
"Async Capable": false,
"Function Name": "worker_last_saved_explain_analyze",
"Alias": "worker_last_saved_explain_analyze",
"Startup Cost": 0.00,
"Total Cost": 10.00,
"Plan Rows": 1000,
"Plan Width": 40,
"Actual Startup Time": 0.003,
"Actual Total Time": 0.004,
"Actual Rows": 1,
"Actual Loops": 1
}
}
With configured auto_explain.log_nested_statements = on I managed to get the undetectable deadlock:
regression=# select datname, pid, application_name, state, wait_event_type, wait_event, query from pg_stat_activity where state <> 'idle' and pid <> pg_backend_pid();
-[ RECORD 1 ]----+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
datname | regression
pid | 2344
application_name | citus_internal gpid=999999990000002250
state | active
wait_event_type | Lock
wait_event | relation
query | EXPLAIN (ANALYZE FALSE, VERBOSE FALSE, COSTS TRUE, BUFFERS FALSE, WAL FALSE, TIMING FALSE, SUMMARY FALSE, FORMAT TEXT) SELECT col_2 FROM test_pg12.generated_stored_ref_60055 generated_stored_ref
-[ RECORD 2 ]----+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
datname | regression
pid | 2250
application_name | pg_regress/pg12
state | active
wait_event_type | Extension
wait_event | Extension
query | SELECT undistribute_table('generated_stored_ref');
regression=# select pg_blocking_pids(2344);
-[ RECORD 1 ]----+-------
pg_blocking_pids | {2250}
Update: it is possible to achieve it without log_nested_statements and even without auto_explain:
SELECT citus_set_coordinator_host('localhost', 5432);
CREATE TABLE ref_table (col_1 int);
SELECT create_reference_table ('ref_table');
BEGIN;
ALTER TABLE ref_table DROP COLUMN col_1;
CREATE TABLE new_table (LIKE ref_table);
EXPLAIN INSERT INTO new_table SELECT * FROM ref_table; -- deadlock
ROLLBACK;
With configured auto_explain.log_nested_statements = on I managed to get the undetectable deadlock:
Thanks for looking into this! added to the issue description as well.
Hello. I am not sure if you are already aware of the following problem: with auto_explain.log_analyze=on configured I encounter the following assertion failure:
CREATE TABLE test_ref_table (key int PRIMARY KEY);
SELECT create_reference_table('test_ref_table');
select * from test_ref_table;
postgres logs:
TRAP: FailedAssertion("task->queryCount == 1", File: "executor/tuple_destination.c", Line: 280, PID: 85555)
bt
...
frame #3: 0x0000000100b8a8d8 postgres`ExceptionalCondition(conditionName="task->queryCount == 1", errorType="FailedAssertion", fileName="executor/tuple_de
stination.c", lineNumber=280) at assert.c:69:2
frame #4: 0x0000000101992e08 citus.so`TupleDestDestReceiverReceive(slot=0x000000015106c7a0, destReceiver=0x0000000151068f20) at tuple_destination.c:280:2
frame #5: 0x00000001006d024c postgres`ExecutePlan(estate=0x000000015106af20, planstate=0x000000015106b158, use_parallel_mode=false, operation=CMD_SELECT,
sendTuples=true, numberTuples=0, direction=ForwardScanDirection, dest=0x0000000151068f20, execute_once=true) at execMain.c:1582:9
frame #6: 0x00000001006d00b4 postgres`standard_ExecutorRun(queryDesc=0x0000000151068f78, direction=ForwardScanDirection, count=0, execute_once=true) at ex
ecMain.c:361:3
frame #7: 0x000000010198c998 citus.so`CitusExecutorRun(queryDesc=0x0000000151068f78, direction=ForwardScanDirection, count=0, execute_once=true) at multi_
executor.c:238:4
frame #8: 0x000000010114a980 pg_stat_statements.so`pgss_ExecutorRun(queryDesc=0x0000000151068f78, direction=ForwardScanDirection, count=0, execute_once=tr
ue) at pg_stat_statements.c:1001:4
frame #9: 0x000000010115f3b8 auto_explain.so`explain_ExecutorRun(queryDesc=0x0000000151068f78, direction=ForwardScanDirection, count=0, execute_once=true)
at auto_explain.c:334:4
frame #10: 0x00000001006cfe1c postgres`ExecutorRun(queryDesc=0x0000000151068f78, direction=ForwardScanDirection, count=0, execute_once=true) at execMain.c
:303:3
frame #11: 0x000000010198c584 citus.so`ExecuteTaskPlan(taskPlan=0x0000000151065c80, queryString="SELECT * FROM worker_save_query_explain_analyze('SELECT k
ey FROM public.test_ref_table_102042 test_ref_table', '{\"verbose\": false, \"costs\": false, \"buffers\": false, \"wal\": false, \"timing\": false, \"summary
\": false, \"format\": \"TEXT\"}') AS (field_0 integer)", tupleDest=0x0000000151056138, task=0x000000015105a840, paramListInfo=0x0000000000000000) at local_ex
ecutor.c:717:2
frame #12: 0x000000010198b754 citus.so`LocallyExecuteTaskPlan(taskPlan=0x0000000151065c80, queryString="SELECT * FROM worker_save_query_explain_analyze('S
ELECT key FROM public.test_ref_table_102042 test_ref_table', '{\"verbose\": false, \"costs\": false, \"buffers\": false, \"wal\": false, \"timing\": false, \"
summary\": false, \"format\": \"TEXT\"}') AS (field_0 integer)", tupleDest=0x0000000151056138, task=0x000000015105a840, paramListInfo=0x0000000000000000) at l
ocal_executor.c:651:19
frame #13: 0x000000010198b648 citus.so`LocallyPlanAndExecuteMultipleQueries(queryStrings=0x000000015105aa90, tupleDest=0x0000000151056138, task=0x00000001
5105a840) at local_executor.c:387:25
frame #14: 0x000000010198b030 citus.so`ExecuteLocalTaskListExtended(taskList=0x000000015105aec0, orig_paramListInfo=0x0000000000000000, distributedPlan=0x
000000014100fe20, defaultTupleDest=0x000000015087b550, isUtilityCommand=false) at local_executor.c:319:6
frame #15: 0x000000010197c200 citus.so`RunLocalExecution(scanState=0x0000000150877560, execution=0x0000000151056300) at adaptive_executor.c:932:25
frame #16: 0x000000010197b5e8 citus.so`AdaptiveExecutor(scanState=0x0000000150877560) at adaptive_executor.c:888:3
frame #17: 0x00000001019838dc citus.so`CitusExecScan(node=0x0000000150877560) at citus_custom_scan.c:245:3
frame #18: 0x00000001006fcc50 postgres`ExecCustomScan(pstate=0x0000000150877560) at nodeCustom.c:115:9
frame #19: 0x00000001006dd2b8 postgres`ExecProcNodeInstr(node=0x0000000150877560) at execProcnode.c:480:11
frame #20: 0x00000001006dc864 postgres`ExecProcNodeFirst(node=0x0000000150877560) at execProcnode.c:464:9
frame #21: 0x00000001006d4a60 postgres`ExecProcNode(node=0x0000000150877560) at executor.h:257:9
frame #22: 0x00000001006d01e0 postgres`ExecutePlan(estate=0x0000000150877320, planstate=0x0000000150877560, use_parallel_mode=false, operation=CMD_SELECT,
sendTuples=true, numberTuples=0, direction=ForwardScanDirection, dest=0x0000000152812568, execute_once=true) at execMain.c:1551:10
frame #23: 0x00000001006d00b4 postgres`standard_ExecutorRun(queryDesc=0x000000015280e320, direction=ForwardScanDirection, count=0, execute_once=true) at e
xecMain.c:361:3
frame #24: 0x000000010198c998 citus.so`CitusExecutorRun(queryDesc=0x000000015280e320, direction=ForwardScanDirection, count=0, execute_once=true) at multi
_executor.c:238:4
frame #25: 0x000000010114a980 pg_stat_statements.so`pgss_ExecutorRun(queryDesc=0x000000015280e320, direction=ForwardScanDirection, count=0, execute_once=t
rue) at pg_stat_statements.c:1001:4
frame #26: 0x000000010115f3b8 auto_explain.so`explain_ExecutorRun(queryDesc=0x000000015280e320, direction=ForwardScanDirection, count=0, execute_once=true
) at auto_explain.c:334:4
...
It might be that the problem is in the fact that local execution of explain analyze is only disabled inside ProcessUtilityInternal (for utility commands), while the query above is apparently not an utility but an 'executor' one.
