PostgreSQL citus, Greenplum 分布式执行计划 DEBUG
背景
开启DEBUG，可以观察citus, Greenplum的SQL分布式执行计划，下发情况，主节点，数据节点交互情况。
执行explain前，打开DEBUG。
set client_min_messages ='debug5';
\set VERBOSITY verbose
explain
explain (analyze,verbose,timing,costs,buffers)
例子
Greenplum
1、 所有节点执行，聚合
postgres=# explain select count(*) from t;
DEBUG5: First char: 'Q'; gp_role = 'dispatch'.
DEBUG1: Message type Q received by from libpq, len = 32
DEBUG5: Simple query stmt: explain select count(*) from t;.
DEBUG5: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
DEBUG3: StartTransactionCommand
DEBUG5: createDtx created new distributed transaction gid = 1535334693-0000001383, gxid = 1383.
DEBUG5: setting SharedLocalSnapshotSlot->startTimestamp = 588738486258830[old=588738484208328])
DEBUG5: [Distributed Snapshot #0] *StartTransaction* (gxid = 1383, xid = 0, 'Master Distributed-Capable')
DEBUG3: StartTransaction
DEBUG3: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG5: StartTransaction in DTX Context = 'Master Distributed-Capable', distributed transaction {timestamp 0, xid 0} for local xid 0
LOG: statement: explain select count(*) from t;
DEBUG5: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
DEBUG5: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c45be0
DEBUG5: GetSnapshotData serializable true, xmin 0
DEBUG5: GetSnapshotData setting globalxmin and xmin to 7159
DEBUG5: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
DEBUG5: createDtxSnapshot distributed snapshot has xmin = 1383, count = 0, xmax = 1383.
DEBUG5: [Distributed Snapshot #1284] *Create* (gxid = 1383, 'Master Distributed-Capable')
DEBUG5: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
DEBUG5: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
DEBUG3: ProcessUtility
DEBUG5: [Distributed Snapshot #0] (gxid = 1383, 'Master Distributed-Capable')
DEBUG5: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c4ef00
DEBUG5: GetSnapshotData serializable false, xmin 7159
DEBUG5: GetSnapshotData setting globalxmin and xmin to 7159
DEBUG5: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
DEBUG5: createDtxSnapshot distributed snapshot has xmin = 1383, count = 0, xmax = 1383.
DEBUG5: [Distributed Snapshot #1285] *Create* (gxid = 1383, 'Master Distributed-Capable')
DEBUG5: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
DEBUG5: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
DEBUG2: cdb_estimate_rel_size estimated 1 tuples and 1 pages
DEBUG2: cdb_estimate_rel_size estimated 1 tuples and 3 pages
DEBUG1: Inserted entry for query (sessionid=44, commandcnt=43)
DEBUG1: Deleted entry for query (sessionid=44, commandcnt=43)
DEBUG3: CommitTransactionCommand
DEBUG3: CommitTransaction
DEBUG3: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG5: prepareDtxTransaction ignoring not distributed gid = 1535334693-0000001383
DEBUG5: releaseGxact called for gid = 1535334693-0000001383 (index = 22)
DEBUG5: notifyCommittedDtxTransaction nothing to do (currentGxact == NULL)
DEBUG5: finishDistributedTransactionContext called to change DistributedTransactionContext from Master Distributed-Capable to Local Only (caller = CommitTransaction, gxid = 0)
QUERY PLAN
----------------------------------------------------------------------------------
Aggregate (cost=1.07..1.08 rows=1 width=8)
-> Gather Motion 2:1 (slice1; segments: 2) (cost=1.01..1.05 rows=1 width=8)
-> Aggregate (cost=1.01..1.02 rows=1 width=8)
-> Seq Scan on t (cost=0.00..1.01 rows=1 width=0)
Optimizer status: legacy query optimizer
(5 rows)
2、 非分布键，聚合
postgres=# explain select count(*) from t group by c1;
DEBUG5: First char: 'Q'; gp_role = 'dispatch'.
DEBUG1: Message type Q received by from libpq, len = 44
DEBUG5: Simple query stmt: explain select count(*) from t group by c1;.
DEBUG5: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
DEBUG3: StartTransactionCommand
DEBUG5: createDtx created new distributed transaction gid = 1535334693-0000001384, gxid = 1384.
DEBUG5: setting SharedLocalSnapshotSlot->startTimestamp = 588739780933404[old=588738486258830])
DEBUG5: [Distributed Snapshot #0] *StartTransaction* (gxid = 1384, xid = 0, 'Master Distributed-Capable')
DEBUG3: StartTransaction
DEBUG3: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG5: StartTransaction in DTX Context = 'Master Distributed-Capable', distributed transaction {timestamp 0, xid 0} for local xid 0
LOG: statement: explain select count(*) from t group by c1;
DEBUG5: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
DEBUG5: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c45be0
DEBUG5: GetSnapshotData serializable true, xmin 0
DEBUG5: GetSnapshotData setting globalxmin and xmin to 7159
DEBUG5: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
DEBUG5: createDtxSnapshot distributed snapshot has xmin = 1384, count = 0, xmax = 1384.
DEBUG5: [Distributed Snapshot #1286] *Create* (gxid = 1384, 'Master Distributed-Capable')
DEBUG5: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
DEBUG5: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
DEBUG3: ProcessUtility
DEBUG5: [Distributed Snapshot #0] (gxid = 1384, 'Master Distributed-Capable')
DEBUG5: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c4ef00
DEBUG5: GetSnapshotData serializable false, xmin 7159
DEBUG5: GetSnapshotData setting globalxmin and xmin to 7159
DEBUG5: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
DEBUG5: createDtxSnapshot distributed snapshot has xmin = 1384, count = 0, xmax = 1384.
DEBUG5: [Distributed Snapshot #1287] *Create* (gxid = 1384, 'Master Distributed-Capable')
DEBUG5: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
DEBUG5: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
DEBUG2: cdb_estimate_rel_size estimated 1 tuples and 1 pages
DEBUG2: cdb_estimate_rel_size estimated 1 tuples and 3 pages
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 95.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 972
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 95.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 972
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 91.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 952
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 91.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 952
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 103.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 1012
DEBUG2: HashAgg: ngroups = 1, memquota = 6.71089e+07, entrysize = 103.2
DEBUG2: HashAgg: nbuckets = 32, nentries = 5, nbatches = 0
DEBUG2: HashAgg: expected memory footprint = 1012
DEBUG1: Inserted entry for query (sessionid=44, commandcnt=45)
DEBUG1: Deleted entry for query (sessionid=44, commandcnt=45)
DEBUG3: CommitTransactionCommand
DEBUG3: CommitTransaction
DEBUG3: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
DEBUG5: prepareDtxTransaction ignoring not distributed gid = 1535334693-0000001384
DEBUG5: releaseGxact called for gid = 1535334693-0000001384 (index = 22)
DEBUG5: notifyCommittedDtxTransaction nothing to do (currentGxact == NULL)
DEBUG5: finishDistributedTransactionContext called to change DistributedTransactionContext from Master Distributed-Capable to Local Only (caller = CommitTransaction, gxid = 0)
QUERY PLAN
-----------------------------------------------------------------------------------------------
Gather Motion 2:1 (slice2; segments: 2) (cost=1.05..1.06 rows=1 width=12)
-> HashAggregate (cost=1.05..1.06 rows=1 width=12)
Group By: t.c1
-> Redistribute Motion 2:2 (slice1; segments: 2) (cost=1.01..1.03 rows=1 width=12)
Hash Key: t.c1
-> HashAggregate (cost=1.01..1.01 rows=1 width=12)
Group By: t.c1
-> Seq Scan on t (cost=0.00..1.01 rows=1 width=4)
Optimizer status: legacy query optimizer
(9 rows)
3、 分布键，聚合
postgres=# explain analyze select count(*) from t where id=1;
DEBUG5: 00000: First char: 'Q'; gp_role = 'dispatch'.
LOCATION: PostgresMain, postgres.c:4921
DEBUG1: 00000: Message type Q received by from libpq, len = 51
LOCATION: PostgresMain, postgres.c:4929
DEBUG5: 00000: Simple query stmt: explain analyze select count(*) from t where id=1;.
LOCATION: PostgresMain, postgres.c:4936
DEBUG5: 00000: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
LOCATION: setupRegularDtxContext, cdbtm.c:3469
DEBUG3: 00000: StartTransactionCommand
LOCATION: start_xact_command, postgres.c:3187
DEBUG5: 00000: createDtx created new distributed transaction gid = 1535334693-0000001386, gxid = 1386.
LOCATION: createDtx, cdbtm.c:2596
DEBUG5: 00000: setting SharedLocalSnapshotSlot->startTimestamp = 588741036365223[old=588741015495884])
LOCATION: StartTransaction, xact.c:2331
DEBUG5: 00000: [Distributed Snapshot #0] *StartTransaction* (gxid = 1386, xid = 0, 'Master Distributed-Capable')
LOCATION: StartTransaction, xact.c:2446
DEBUG3: 00000: StartTransaction
LOCATION: ShowTransactionState, xact.c:5656
DEBUG3: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
LOCATION: ShowTransactionStateRec, xact.c:5694
DEBUG5: 00000: StartTransaction in DTX Context = 'Master Distributed-Capable', distributed transaction {timestamp 0, xid 0} for local xid 0
LOCATION: StartTransaction, xact.c:2531
LOG: 00000: statement: explain analyze select count(*) from t where id=1;
LOCATION: exec_simple_query, postgres.c:1577
DEBUG5: 00000: setupRegularDtxContext leaving with DistributedTransactionContext = 'Master Distributed-Capable'.
LOCATION: setupRegularDtxContext, cdbtm.c:3469
DEBUG5: 00000: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c45be0
LOCATION: GetSnapshotData, procarray.c:1108
DEBUG5: 00000: GetSnapshotData serializable true, xmin 0
LOCATION: GetSnapshotData, procarray.c:1342
DEBUG5: 00000: GetSnapshotData setting globalxmin and xmin to 7159
LOCATION: GetSnapshotData, procarray.c:1363
DEBUG5: 00000: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
LOCATION: FillInDistributedSnapshot, procarray.c:926
DEBUG5: 00000: createDtxSnapshot distributed snapshot has xmin = 1386, count = 0, xmax = 1386.
LOCATION: createDtxSnapshot, cdbtm.c:2516
DEBUG5: 00000: [Distributed Snapshot #1288] *Create* (gxid = 1386, 'Master Distributed-Capable')
LOCATION: createDtxSnapshot, cdbtm.c:2521
DEBUG5: 00000: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
LOCATION: FillInDistributedSnapshot, procarray.c:949
DEBUG5: 00000: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
LOCATION: GetSnapshotData, procarray.c:1532
DEBUG3: 00000: ProcessUtility
LOCATION: PortalRunUtility, pquery.c:1361
DEBUG5: 00000: [Distributed Snapshot #0] (gxid = 1386, 'Master Distributed-Capable')
LOCATION: GetTransactionSnapshot, tqual.c:1407
DEBUG5: 00000: GetSnapshotData maxCount 1000, inProgressEntryArray 0x3c4ef00
LOCATION: GetSnapshotData, procarray.c:1108
DEBUG5: 00000: GetSnapshotData serializable false, xmin 7159
LOCATION: GetSnapshotData, procarray.c:1342
DEBUG5: 00000: GetSnapshotData setting globalxmin and xmin to 7159
LOCATION: GetSnapshotData, procarray.c:1363
DEBUG5: 00000: FillInDistributedSnapshot DTX Context = 'Master Distributed-Capable'
LOCATION: FillInDistributedSnapshot, procarray.c:926
DEBUG5: 00000: createDtxSnapshot distributed snapshot has xmin = 1386, count = 0, xmax = 1386.
LOCATION: createDtxSnapshot, cdbtm.c:2516
DEBUG5: 00000: [Distributed Snapshot #1289] *Create* (gxid = 1386, 'Master Distributed-Capable')
LOCATION: createDtxSnapshot, cdbtm.c:2521
DEBUG5: 00000: Got distributed snapshot from DistributedSnapshotWithLocalXids_Create = true
LOCATION: FillInDistributedSnapshot, procarray.c:949
DEBUG5: 00000: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 0
LOCATION: GetSnapshotData, procarray.c:1532
DEBUG2: 00000: cdb_estimate_rel_size estimated 1 tuples and 1 pages
LOCATION: cdb_estimate_rel_size, plancat.c:501
DEBUG2: 00000: cdb_estimate_rel_size estimated 1 tuples and 3 pages
LOCATION: cdb_estimate_rel_size, plancat.c:501
DEBUG4: 00000: CDBHASH started for 2 segment databases
LOCATION: makeCdbHash, cdbhash.c:106
DEBUG1: 00000: Inserted entry for query (sessionid=44, commandcnt=48)
LOCATION: WorkfileQueryspace_InitEntry, workfile_queryspace.c:299
DEBUG5: 00000: dtmPreCommand going distributed (all gangs) for gid = 1535334693-0000001386 (ExecutorStart, detail = '(none)')
LOCATION: dtmPreCommand, cdbtm.c:465
DEBUG1: 00000: Query plan size to dispatch: 1KB
LOCATION: cdbdisp_buildPlanQueryParms, cdbdisp_query.c:605
DEBUG5: 00000: mppTxnOptions DefaultXactIsoLevel = READ COMMITTED, DefaultXactReadOnly = false, XactIsoLevel = READ COMMITTED, XactReadOnly = false.
LOCATION: mppTxnOptions, cdbtm.c:1690
DEBUG5: 00000: mppTxnOptions txnOptions = 0x2, needTwoPhase = false, explicitBegin = false, isoLevel = READ COMMITTED, readOnly = false.
LOCATION: mppTxnOptions, cdbtm.c:1712
DEBUG5: 00000: qdSerializeDtxContextInfo using LatestSnapshot
LOCATION: qdSerializeDtxContextInfo, cdbdisp_dtx.c:242
DEBUG5: 00000: [Distributed Snapshot #1289] *QD Use Latest* currcid = 0 (gxid = 1386, 'Master Distributed-Capable')
LOCATION: qdSerializeDtxContextInfo, cdbdisp_dtx.c:250
DEBUG5: 00000: DtxContextInfo_CreateOnMaster: created dtxcontext with dxid 1386/1386 nestingLevel 1 segmateSync 1/1 (current/cached)
LOCATION: DtxContextInfo_CreateOnMaster, cdbdtxcontextinfo.c:84
DEBUG5: 00000: DistributedSnapshot_Copy target maxCount 1000, inProgressXidArray 0x3c88bb0, and source maxCount 1000, count 0, inProgressXidArray 0x3c4ef00
LOCATION: DistributedSnapshot_Copy, cdbdistributedsnapshot.c:373
DEBUG5: 00000: updateSharedLocalSnapshot for DistributedTransactionContext = 'Master Distributed-Capable' passed local snapshot (xmin: 7159 xmax: 7159 xcnt: 0) curcid: 0
LOCATION: updateSharedLocalSnapshot, procarray.c:820
DEBUG5: 00000: updateSharedLocalSnapshot: combocidsize is now 0 max 256 segmateSync 1->1
LOCATION: updateSharedLocalSnapshot, procarray.c:850
DEBUG5: 00000: Master Distributed-Capable setting shared xid 0 -> 0
LOCATION: SetSharedTransactionId_writer, xact.c:2200
DEBUG5: 00000: updateSharedLocalSnapshot for DistributedTransactionContext = 'Master Distributed-Capable' setting shared local snapshot xid = 0 (xmin: 7159 xmax: 7159 xcnt: 0) curcid: 0, QDxid = 1386, QDcid = 0
LOCATION: updateSharedLocalSnapshot, procarray.c:870
DEBUG5: 00000: [Distributed Snapshot #0] *Writer Set Shared* gxid 1386, currcid 0 (gxid = 1386, slot #44, 'qdSerializeDtxContextInfo', 'Master Distributed-Capable')
LOCATION: updateSharedLocalSnapshot, procarray.c:880
DEBUG5: 00000: DtxContextInfo_SerializeSize is returning size = 76
LOCATION: DtxContextInfo_SerializeSize, cdbdtxcontextinfo.c:166
DEBUG3: 00000: DtxContextInfo_Serialize distributedTimeStamp 1535334693, distributedXid = 1386, curcid 0 nestingLevel 1 segmateSync 1
LOCATION: DtxContextInfo_Serialize, cdbdtxcontextinfo.c:202
DEBUG5: 00000: qdSerializeDtxContextInfo (called by cdbdisp_buildPlanQueryParms) returning a snapshot of 76 bytes (ptr is Non-NULL)
LOCATION: qdSerializeDtxContextInfo, cdbdisp_dtx.c:314
DEBUG2: 00000: add icid 6 cid 48 status 1
LOCATION: addCursorIcEntry, ic_udpifc.c:937
DEBUG1: 00000: Exec skip a motion recv, current slice id 0, mstype 2
LOCATION: ExecSliceDependencyNode, execProcnode.c:833
DEBUG3: 00000: In prepareRxConnForRead: conn 0x3ee3718, q_head 0 q_tail 1 q_size 1
LOCATION: prepareRxConnForRead, ic_udpifc.c:3610
DEBUG2: 00000: receiveChunksUDPIFC: non-directed rx woke on route 0
LOCATION: receiveChunksUDPIFC, ic_udpifc.c:3665
DEBUG2: 00000: got data with length 88
LOCATION: receiveChunksUDPIFC, ic_udpifc.c:3677
DEBUG5: 00000: First char: 'M'; gp_role = 'execute'. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: PostgresMain, postgres.c:4921
DEBUG1: 00000: Message type M received by from libpq, len = 706 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: PostgresMain, postgres.c:5000
DEBUG5: 00000: DtxContextInfo_Deserialize serializedDtxContextInfolen = 76. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DtxContextInfo_Deserialize, cdbdtxcontextinfo.c:348
DEBUG3: 00000: DtxContextInfo_Deserialize distributedTimeStamp 1535334693, distributedXid = 1386, curcid 0 nestingLevel 1 segmateSync 1 as WRITER (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DtxContextInfo_Deserialize, cdbdtxcontextinfo.c:385
DEBUG5: 00000: MPP dispatched stmt from QD: explain analyze select count(*) from t where id=1;. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: PostgresMain, postgres.c:5079
DEBUG5: 00000: setupQEDtxContext intermediate result: isEntryDbSingleton = false, isWriterQE = true, isReaderQE = false. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: setupQEDtxContext, cdbtm.c:3595
DEBUG5: 00000: DistributedSnapshot_Copy target maxCount 0, inProgressXidArray (nil), and source maxCount 1000, count 0, inProgressXidArray 0x450aa40 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DistributedSnapshot_Copy, cdbdistributedsnapshot.c:373
DEBUG5: 00000: DtxContextInfo_Copy distributed {timestamp 1535334693, xid 1386}, id = 1535334693-0000001386, command id 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DtxContextInfo_Copy, cdbdtxcontextinfo.c:317
DEBUG5: 00000: distributed snapshot {timestamp 1535334693, xminAllDistributedSnapshots 1386, snapshot id 1289, xmin 1386, count 0, xmax 1386} (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DtxContextInfo_Copy, cdbdtxcontextinfo.c:328
DEBUG5: 00000: setupQEDtxContext final result: DistributedTransactionContext = 'Segment Auto-Commit Implicit'. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: setupQEDtxContext, cdbtm.c:3728
DEBUG5: 00000: [Distributed Snapshot #1289] *Set QE* currcid = 0 (gxid = 1386, 'Segment Auto-Commit Implicit') (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: setupQEDtxContext, cdbtm.c:3736
DEBUG3: 00000: StartTransactionCommand (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: start_xact_command, postgres.c:3187
DEBUG5: 00000: qExec writer setting distributedXid: 1386 sharedQDxid 1386 (shared xid 0 -> 0) ready false (shared timeStamp = 588741036374830 -> 0) (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: StartTransaction, xact.c:2404
DEBUG5: 00000: [Distributed Snapshot #0] *StartTransaction* (gxid = 1386, xid = 0, 'Segment Auto-Commit Implicit') (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: StartTransaction, xact.c:2446
DEBUG3: 00000: StartTransaction (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: ShowTransactionState, xact.c:5656
DEBUG3: 00000: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: ShowTransactionStateRec, xact.c:5694
DEBUG5: 00000: StartTransaction in DTX Context = 'Segment Auto-Commit Implicit', distributed transaction {timestamp 1535334693, xid 911} for local xid 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: StartTransaction, xact.c:2531
DEBUG2: 00000: Current nice level of the process: 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: renice_current_process, postgres.c:274
DEBUG2: 00000: Reniced process to level 19 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: renice_current_process, postgres.c:292
DEBUG5: 00000: GetSnapshotData maxCount 0, inProgressEntryArray (nil) (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: GetSnapshotData, procarray.c:1108
DEBUG5: 00000: GetSnapshotData serializable true, xmin 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: GetSnapshotData, procarray.c:1342
DEBUG5: 00000: GetSnapshotData setting globalxmin and xmin to 106178 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: GetSnapshotData, procarray.c:1363
DEBUG5: 00000: FillInDistributedSnapshot DTX Context = 'Segment Auto-Commit Implicit' (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: FillInDistributedSnapshot, procarray.c:926
DEBUG5: 00000: DistributedSnapshot_Copy target maxCount 1000, inProgressXidArray 0x4518e40, and source maxCount 1000, count 0, inProgressXidArray 0x450b9f0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: DistributedSnapshot_Copy, cdbdistributedsnapshot.c:373
DEBUG5: 00000: updateSharedLocalSnapshot for DistributedTransactionContext = 'Segment Auto-Commit Implicit' passed local snapshot (xmin: 106178 xmax: 106178 xcnt: 0) curcid: 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: updateSharedLocalSnapshot, procarray.c:820
DEBUG5: 00000: updateSharedLocalSnapshot: combocidsize is now 0 max 256 segmateSync 0->1 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: updateSharedLocalSnapshot, procarray.c:850
DEBUG5: 00000: Segment Auto-Commit Implicit setting shared xid 0 -> 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: SetSharedTransactionId_writer, xact.c:2200
DEBUG5: 00000: updateSharedLocalSnapshot for DistributedTransactionContext = 'Segment Auto-Commit Implicit' setting shared local snapshot xid = 0 (xmin: 106178 xmax: 106178 xcnt: 0) curcid: 0, QDxid = 1386, QDcid = 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: updateSharedLocalSnapshot, procarray.c:870
DEBUG5: 00000: [Distributed Snapshot #1289] *Writer Set Shared* gxid 1386, currcid 0 (gxid = 1386, slot #44, 'GetSnapshotData', 'Segment Auto-Commit Implicit') (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: updateSharedLocalSnapshot, procarray.c:880
DEBUG5: 00000: GetSnapshotData(): WRITER currentcommandid 0 curcid 0 segmatesync 1 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: GetSnapshotData, procarray.c:1532
DEBUG1: 00000: Inserted entry for query (sessionid=44, commandcnt=48) (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: WorkfileQueryspace_InitEntry, workfile_queryspace.c:299
DEBUG1: 00000: GetSockAddr socket ai_family 2 ai_socktype 2 ai_protocol 17 for 127.0.0.1 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: getSockAddr, ic_udpifc.c:2731
DEBUG1: 00000: We are inet6, remote is inet. Converting to v4 mapped address. (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: setupOutgoingUDPConnection, ic_udpifc.c:2810
DEBUG1: 00000: Exec process a motion send, current slice id 1, mstype 1 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: ExecSliceDependencyNode, execProcnode.c:837
DEBUG1: 00000: Interconnect seg0 slice1 cleanup state: force; setup was completed (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: TeardownUDPIFCInterconnect_Internal, ic_udpifc.c:3335
DEBUG1: 00000: Interconnect State: isSender 1 isReceiver 0 snd_queue_depth 2 recv_queue_depth 4 Gp_max_packet_size 8192 UNACK_QUEUE_RING_SLOTS_NUM 2000 TIMER_SPAN 5000 DEFAULT_RTT 20000 forceEOS 1, gp_interconnect_id 6 ic_id_last_teardown 6 snd_buffer_pool.count 0 snd_buffer_pool.maxCount 0 snd_sock_bufsize 2097152 recv_sock_bufsize 2097152 snd_pkt_count 1 retransmits 0 crc_errors 0 recv_pkt_count 0 recv_ack_num 1 recv_queue_size_avg -nan capacity_avg -nan freebuf_avg 2.000000 mismatch_pkt_num 0 disordered_pkt_num 0 duplicated_pkt_num 0 rtt/dev [17511/4354, 17511.000000/4354.000000, 17511/4354] cwnd 2.000000 status_query_msg_num 0 (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: TeardownUDPIFCInterconnect_Internal, ic_udpifc.c:3546
DEBUG1: 00000: TeardownUDPIFCInterconnect successful (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: TeardownUDPIFCInterconnect_Internal, ic_udpifc.c:3570
DEBUG1: 00000: Deleted entry for query (sessionid=44, commandcnt=48) (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: WorkfileQueryspace_ReleaseEntry, workfile_queryspace.c:345
DEBUG3: 00000: CommitTransactionCommand (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: finish_xact_command, postgres.c:3211
DEBUG3: 00000: CommitTransaction (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: ShowTransactionState, xact.c:5656
DEBUG3: 00000: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: ShowTransactionStateRec, xact.c:5694
DEBUG5: 00000: prepareDtxTransaction nothing to do (DistributedTransactionContext = 'Segment Auto-Commit Implicit') (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: prepareDtxTransaction, cdbtm.c:1088
DEBUG5: 00000: notifyCommittedDtxTransaction nothing to do (DistributedTransactionContext = 'Segment Auto-Commit Implicit') (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: notifyCommittedDtxTransactionIsNeeded, cdbtm.c:340
DEBUG5: 00000: finishDistributedTransactionContext called to change DistributedTransactionContext from Segment Auto-Commit Implicit to Local Only (caller = CommitTransaction, gxid = 1386) (seg0 slice1 127.0.0.1:25432 pid=18488)
LOCATION: finishDistributedTransactionContext, cdbtm.c:3764
DEBUG1: 00000: Interconnect State: isSender 0 isReceiver 1 snd_queue_depth 2 recv_queue_depth 4 Gp_max_packet_size 8192 UNACK_QUEUE_RING_SLOTS_NUM 2000 TIMER_SPAN 5000 DEFAULT_RTT 20000 forceEOS 0, gp_interconnect_id 6 ic_id_last_teardown 0 snd_buffer_pool.count 0 snd_buffer_pool.maxCount 0 snd_sock_bufsize 2097152 recv_sock_bufsize 2097152 snd_pkt_count 0 retransmits 0 crc_errors 0 recv_pkt_count 1 recv_ack_num 0 recv_queue_size_avg 0.000000 capacity_avg -nan freebuf_avg -nan mismatch_pkt_num 0 disordered_pkt_num 0 duplicated_pkt_num 0 rtt/dev [0/0, 0.000000/0.000000, 0/0] cwnd 0.000000 status_query_msg_num 0
LOCATION: TeardownUDPIFCInterconnect_Internal, ic_udpifc.c:3546
DEBUG1: 00000: TeardownUDPIFCInterconnect successful
LOCATION: TeardownUDPIFCInterconnect_Internal, ic_udpifc.c:3570
DEBUG1: 00000: Deleted entry for query (sessionid=44, commandcnt=48)
LOCATION: WorkfileQueryspace_ReleaseEntry, workfile_queryspace.c:345
DEBUG3: 00000: CommitTransactionCommand
LOCATION: finish_xact_command, postgres.c:3211
DEBUG3: 00000: CommitTransaction
LOCATION: ShowTransactionState, xact.c:5656
DEBUG3: 00000: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
LOCATION: ShowTransactionStateRec, xact.c:5694
DEBUG5: 00000: prepareDtxTransaction ignoring not distributed gid = 1535334693-0000001386
LOCATION: prepareDtxTransaction, cdbtm.c:1102
DEBUG5: 00000: releaseGxact called for gid = 1535334693-0000001386 (index = 22)
LOCATION: releaseGxact_UnderLocks, cdbtm.c:2617
DEBUG5: 00000: notifyCommittedDtxTransaction nothing to do (currentGxact == NULL)
LOCATION: notifyCommittedDtxTransactionIsNeeded, cdbtm.c:346
DEBUG5: 00000: finishDistributedTransactionContext called to change DistributedTransactionContext from Master Distributed-Capable to Local Only (caller = CommitTransaction, gxid = 0)
LOCATION: finishDistributedTransactionContext, cdbtm.c:3764
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Aggregate (cost=1.07..1.08 rows=1 width=8)
Rows out: 1 rows with 0.004 ms to first row, 0.005 ms to end, start offset by 9.489 ms.
-> Gather Motion 1:1 (slice1; segments: 1) (cost=1.02..1.06 rows=1 width=8)
Rows out: 1 rows at destination with 2.691 ms to first row, 8.666 ms to end, start offset by 9.494 ms.
-> Aggregate (cost=1.02..1.03 rows=1 width=8)
Rows out: 1 rows with 0.008 ms to end, start offset by 12 ms.
-> Seq Scan on t (cost=0.00..1.01 rows=1 width=0)
Filter: id = 1
Rows out: 0 rows with 5.426 ms to end, start offset by 12 ms.
Slice statistics:
(slice0) Executor memory: 373K bytes.
(slice1) Executor memory: 334K bytes (seg0).
Statement statistics:
Memory used: 128000K bytes
Optimizer status: legacy query optimizer
Total runtime: 18.639 ms
(16 rows)
Citus
1、 非分布键过滤，非分布键分组聚合
postgres=# explain select max(id) from test where info='a' group by crt_time;
DEBUG: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
DEBUG: generated sql query for task 1
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104508 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
DEBUG: generated sql query for task 2
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104509 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
DEBUG: generated sql query for task 3
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104510 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
......
DEBUG: generated sql query for task 126
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104633 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
DEBUG: generated sql query for task 127
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104634 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
DEBUG: generated sql query for task 128
DETAIL: query string: "SELECT max(id) AS max, crt_time AS worker_column_2 FROM test_104635 test WHERE (info OPERATOR(pg_catalog.=) 'a'::text) GROUP BY crt_time"
DEBUG: assigned task 1 to node xxx.224:1921
DEBUG: assigned task 2 to node xxx.225:1921
DEBUG: assigned task 3 to node xxx.226:1921
......
DEBUG: assigned task 126 to node xxx.230:1921
DEBUG: assigned task 127 to node xxx.231:1921
DEBUG: assigned task 128 to node xxx.232:1921
DEBUG: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
QUERY PLAN
------------------------------------------------------------------------------------------------
HashAggregate (cost=0.00..0.00 rows=0 width=0)
Group Key: remote_scan.worker_column_2
-> Custom Scan (Citus Real-Time) (cost=0.00..0.00 rows=0 width=0)
Task Count: 128
Tasks Shown: One of 128
-> Task
Node: host=xxx.224 port=1921 dbname=postgres
-> GroupAggregate (cost=24.20..24.31 rows=6 width=12)
Group Key: crt_time
-> Sort (cost=24.20..24.22 rows=6 width=12)
Sort Key: crt_time
-> Seq Scan on test_104508 test (cost=0.00..24.12 rows=6 width=12)
Filter: (info = 'a'::text)
(13 rows)
Time: 96.372 ms
2、 分布键查询
postgres=# \set VERBOSITY verbose
postgres=# explain (analyze,verbose,timing,costs,buffers) select * from test where id=1;
DEBUG: 00000: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
LOCATION: ShowTransactionStateRec, xact.c:5022
DEBUG: 00000: Creating router plan
LOCATION: CreateSingleTaskRouterPlan, multi_router_planner.c:268
DEBUG: 00000: Plan is router executable
DETAIL: distribution column value: 1
LOCATION: JobExecutorType, multi_server_executor.c:70
DEBUG: 00000: CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0
LOCATION: ShowTransactionStateRec, xact.c:5022
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------
Custom Scan (Citus Router) (cost=0.00..0.00 rows=0 width=0) (actual time=7.732..7.733 rows=1 loops=1)
Output: remote_scan.id, remote_scan.info, remote_scan.crt_time
Task Count: 1
Tasks Shown: All
-> Task
Node: host=xxx.232 port=1921 dbname=postgres
-> Index Scan using test_pkey_104515 on public.test_104515 test (cost=0.15..2.37 rows=1 width=44) (actual time=0.012..0.013 rows=1 loops=1)
Output: id, info, crt_time
Index Cond: (test.id = 1)
Buffers: shared hit=2
Planning time: 0.037 ms
Execution time: 0.025 ms
Planning time: 1.693 ms
Execution time: 7.756 ms
(14 rows)
3、 不支持的聚合函数
postgres=# select stddev(id) from test where info='a';
DEBUG: 00000: StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0
LOCATION: ShowTransactionStateRec, xact.c:5022
ERROR: XX000: unsupported aggregate function stddev
LOCATION: GetAggregateType, multi_logical_optimizer.c:2915