add traces

Author: kelvich

contrib/mmts/arbiter.c

@@ -853,6 +853,7 @@ static void MtmTransReceiver(Datum arg)
 					if (MtmIsCoordinator(ts)) {
 						switch (msg->code) { 
 						  case MSG_READY:
+							MTM_TXTRACE(ts, "MtmTransReceiver got MSG_READY");
 							if (ts->nVotes >= Mtm->nLiveNodes) {
 								MtmAbortTransaction(ts);
 								MtmWakeUpBackend(ts);
@@ -875,6 +876,7 @@ static void MtmTransReceiver(Datum arg)
 									} else if (MtmUseDtm) { 
 										Assert(ts->status == TRANSACTION_STATUS_IN_PROGRESS);
 										ts->nVotes = 1; /* I voted myself */
+										MTM_TXTRACE(ts, "MtmTransReceiver send MSG_PREPARE");
 										MtmSendNotificationMessage(ts, MSG_PREPARE);									  
 									} else { 
 										Assert(ts->status == TRANSACTION_STATUS_IN_PROGRESS);
@@ -894,6 +896,7 @@ static void MtmTransReceiver(Datum arg)
 							}
 							break;
 						  case MSG_PREPARED:
+							MTM_TXTRACE(ts, "MtmTransReceiver got MSG_PREPARED");
 							if (ts->nVotes >= Mtm->nLiveNodes) {					
 								MtmAbortTransaction(ts);
 								MtmWakeUpBackend(ts);

contrib/mmts/multimaster.c

@@ -708,7 +708,8 @@ MtmCreateTransState(MtmCurrentTrans* x)
 		/* I am coordinator of transaction */
 		ts->gtid.xid = x->xid;
 		ts->gtid.node = MtmNodeId;
-		ts->gid[0] = '\0';
+		//ts->gid[0] = '\0';
+		strcpy(ts->gid, x->gid);
 	}
 	return ts;
 }
@@ -724,6 +725,7 @@ MtmPrePrepareTransaction(MtmCurrentTrans* x)
 { 
 	MtmTransState* ts;
 	TransactionId* subxids;
+	MTM_TXTRACE(x, "PrePrepareTransaction Start");
 
 	if (!x->isDistributed) {
 		return;
@@ -782,7 +784,8 @@ MtmPrePrepareTransaction(MtmCurrentTrans* x)
 	MtmAddSubtransactions(ts, subxids, ts->nSubxids);
 	MTM_LOG3("%d: MtmPrePrepareTransaction prepare commit of %d (gtid.xid=%d, gtid.node=%d, CSN=%ld)", 
 			 MyProcPid, x->xid, ts->gtid.xid, ts->gtid.node, ts->csn);
-	MtmUnlock(); 
+	MtmUnlock();
+	MTM_TXTRACE(x, "PrePrepareTransaction Finish");
 }
 
 /*
@@ -810,6 +813,7 @@ static void
 MtmPostPrepareTransaction(MtmCurrentTrans* x)
 { 
 	MtmTransState* ts;
+	MTM_TXTRACE(x, "PostPrepareTransaction Start");
 
 	if (Mtm->inject2PCError == 2) { 
 		Mtm->inject2PCError = 0;
@@ -845,7 +849,9 @@ MtmPostPrepareTransaction(MtmCurrentTrans* x)
 		while (!ts->votingCompleted && Mtm->status == MTM_ONLINE && ts->status != TRANSACTION_STATUS_ABORTED && start + transTimeout >= MtmGetSystemTime()) 
 		{
 			MtmUnlock();
+			MTM_TXTRACE(x, "PostPrepareTransaction WaitLatch Start");
 			result = WaitLatch(&MyProc->procLatch, WL_LATCH_SET|WL_TIMEOUT, MtmHeartbeatRecvTimeout);
+			MTM_TXTRACE(x, "PostPrepareTransaction WaitLatch Finish");
 			if (result & WL_LATCH_SET) { 
 				ResetLatch(&MyProc->procLatch);			
 			} 
@@ -868,6 +874,8 @@ MtmPostPrepareTransaction(MtmCurrentTrans* x)
 		Mtm->inject2PCError = 0;
 		elog(ERROR, "ERROR INJECTION for transaction %d (%s)", x->xid, x->gid);
 	}
+
+	MTM_TXTRACE(x, "PostPrepareTransaction Finish");
 }
 
 
@@ -1064,8 +1072,9 @@ csn_t MtmGetTransactionCSN(TransactionId xid)
 }
 
 void MtmWakeUpBackend(MtmTransState* ts)
-{																		
-	if (!ts->votingCompleted) { 
+{
+	if (!ts->votingCompleted) {
+		MTM_TXTRACE(ts, "MtmWakeUpBackend");
 		MTM_LOG3("Wakeup backed procno=%d, pid=%d", ts->procno, ProcGlobal->allProcs[ts->procno].pid);
 		ts->votingCompleted = true;
 		SetLatch(&ProcGlobal->allProcs[ts->procno].procLatch); 

contrib/mmts/multimaster.h

@@ -32,6 +32,8 @@
 #define MTM_LOG4(fmt, ...) fprintf(stderr, fmt "\n", ## __VA_ARGS__) 
 #endif
 
+#define MTM_TXTRACE(tx, event) \
+		fprintf(stderr, "[MTM_TXTRACE] [%s] [%lld] %s\n", tx->gid, (long long)MtmGetSystemTime(), event)
 #define MULTIMASTER_NAME                "multimaster"
 #define MULTIMASTER_SCHEMA_NAME         "mtm"
 #define MULTIMASTER_DDL_TABLE           "ddl_log"

contrib/mmts/pglogical_proto.c

@@ -178,6 +178,8 @@ pglogical_write_commit(StringInfo out, PGLogicalOutputData *data,
     if (txn->xact_action != XLOG_XACT_COMMIT) { 
     	pq_sendstring(out, txn->gid);
 	}
+
+	MTM_TXTRACE(txn, "pglogical_write_commit Finish");
 }
 
 /*

contrib/mmts/tests2/docker-entrypoint.sh

@@ -88,6 +88,7 @@ if [ "$1" = 'postgres' ]; then
 			multimaster.conn_strings = '$CONNSTRS'
 			multimaster.heartbeat_recv_timeout = 1000
 			multimaster.heartbeat_send_timeout = 250
+			multimaster.twopc_min_timeout = 40000
 		EOF
 
 		tail -n 20 $PGDATA/postgresql.conf

src/backend/replication/logical/decode.c

@@ -24,6 +24,9 @@
  *
  * -------------------------------------------------------------------------
  */
+#include <sys/time.h>
+#include <time.h>
+
 #include "postgres.h"
 
 #include "access/heapam.h"
@@ -643,6 +646,15 @@ DecodePrepare(LogicalDecodingContext *ctx, XLogRecordBuffer *buf,
 	int			i;
 	TransactionId xid = parsed->twophase_xid;
 
+	struct timeval tv;
+	int64 ts;
+
+	gettimeofday(&tv, NULL);
+	ts = (int64)tv.tv_sec*USECS_PER_SEC + tv.tv_usec;
+
+	fprintf(stderr, "[MTM_TXTRACE] [%s] [%lld] DecodePrepare Started\n",
+									parsed->twophase_gid, (long long) ts);
+
 	if (parsed->xinfo & XACT_XINFO_HAS_ORIGIN)
 	{
 		origin_lsn = parsed->origin_lsn;