add traces

Author: kelvich

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

multimaster.c

@@ -707,7 +707,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;
 }
@@ -723,6 +724,7 @@ MtmPrePrepareTransaction(MtmCurrentTrans* x)
 { 
 	MtmTransState* ts;
 	TransactionId* subxids;
+	MTM_TXTRACE(x, "PrePrepareTransaction Start");
 
 	if (!x->isDistributed) {
 		return;
@@ -781,7 +783,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");
 }
 
 /*
@@ -809,6 +812,7 @@ static void
 MtmPostPrepareTransaction(MtmCurrentTrans* x)
 { 
 	MtmTransState* ts;
+	MTM_TXTRACE(x, "PostPrepareTransaction Start");
 
 	if (Mtm->inject2PCError == 2) { 
 		Mtm->inject2PCError = 0;
@@ -844,7 +848,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);			
 			} 
@@ -867,6 +873,8 @@ MtmPostPrepareTransaction(MtmCurrentTrans* x)
 		Mtm->inject2PCError = 0;
 		elog(ERROR, "ERROR INJECTION for transaction %d (%s)", x->xid, x->gid);
 	}
+
+	MTM_TXTRACE(x, "PostPrepareTransaction Finish");
 }
 
 
@@ -1063,8 +1071,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); 

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"

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");
 }
 
 /*

tests2/docker-entrypoint.sh

@@ -86,6 +86,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