PostgreSQL citus, Greenplum 分布式执行计划 DEBUG

17 minute read

背景

开启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    

Flag Counter

digoal’s 大量PostgreSQL文章入口