Skip to content

Commit ac0afb1

Browse files
knizhnikknizhnik
committed
Add more traces
1 parent 0b9c386 commit ac0afb1

File tree

3 files changed

+34
-25
lines changed

3 files changed

+34
-25
lines changed

‎contrib/mmts/multimaster.c‎

Lines changed: 29 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -695,20 +695,18 @@ MtmCreateTransState(MtmCurrentTrans* x)
695695
{
696696
bool found;
697697
MtmTransState* ts = hash_search(MtmXid2State, &x->xid, HASH_ENTER, &found);
698-
if (!found) {
699-
ts->status = TRANSACTION_STATUS_IN_PROGRESS;
700-
ts->snapshot = x->snapshot;
701-
ts->isLocal = true;
702-
if (TransactionIdIsValid(x->gtid.xid)) {
703-
Assert(x->gtid.node != MtmNodeId);
704-
ts->gtid = x->gtid;
705-
strcpy(ts->gid, x->gid);
706-
} else {
707-
/* I am coordinator of transaction */
708-
ts->gtid.xid = x->xid;
709-
ts->gtid.node = MtmNodeId;
710-
ts->gid[0] = '\0';
711-
}
698+
ts->status = TRANSACTION_STATUS_IN_PROGRESS;
699+
ts->snapshot = x->snapshot;
700+
ts->isLocal = true;
701+
if (TransactionIdIsValid(x->gtid.xid)) {
702+
Assert(x->gtid.node != MtmNodeId);
703+
ts->gtid = x->gtid;
704+
strcpy(ts->gid, x->gid);
705+
} else {
706+
/* I am coordinator of transaction */
707+
ts->gtid.xid = x->xid;
708+
ts->gtid.node = MtmNodeId;
709+
ts->gid[0] = '\0';
712710
}
713711
return ts;
714712
}
@@ -854,11 +852,11 @@ MtmPostPrepareTransaction(MtmCurrentTrans* x)
854852
if (!ts->votingCompleted) {
855853
if (ts->status != TRANSACTION_STATUS_ABORTED) {
856854
MtmAbortTransaction(ts);
857-
elog(WARNING, "Transaction is aborted because of %d msec timeout expiration, prepare time %d msec", (int)transTimeout, (int)USEC_TO_MSEC(ts->csn - x->snapshot));
855+
elog(WARNING, "Transaction %d is aborted because of %d msec timeout expiration, prepare time %d msec", x->xid, (int)transTimeout, (int)USEC_TO_MSEC(ts->csn - x->snapshot));
858856
}
859857
} else if (nConfigChanges != Mtm->nConfigChanges) {
860858
MtmAbortTransaction(ts);
861-
elog(WARNING, "Transaction is aborted because cluster configuration is changed during commit");
859+
elog(WARNING, "Transaction %d is aborted because cluster configuration is changed during commit", x->xid);
862860
}
863861
x->status = ts->status;
864862
MTM_LOG3("%d: Result of vote: %d", MyProcPid, ts->status);
@@ -880,9 +878,12 @@ MtmAbortPreparedTransaction(MtmCurrentTrans* x)
880878
MtmLock(LW_EXCLUSIVE);
881879
tm = (MtmTransMap*)hash_search(MtmGid2State, x->gid, HASH_REMOVE, NULL);
882880
Assert(tm != NULL);
881+
MTM_LOG1("Abort prepared transaction %d with gid='%s' is already aborted", x->xid, x->gid);
883882
MtmAbortTransaction(tm->state);
884883
MtmUnlock();
885884
x->status = TRANSACTION_STATUS_ABORTED;
885+
} else {
886+
MTM_LOG1("Transaction %d with gid='%s' is already aborted", x->xid, x->gid);
886887
}
887888
}
888889

@@ -918,6 +919,7 @@ MtmEndTransaction(MtmCurrentTrans* x, bool commit)
918919
Assert(Mtm->nActiveTransactions != 0);
919920
Mtm->nActiveTransactions -= 1;
920921
} else {
922+
MTM_LOG1("%d: abort transaction %d gid='%s' is called from MtmEndTransaction", MyProcPid, x->xid, x->gid);
921923
MtmAbortTransaction(ts);
922924
}
923925
}
@@ -998,7 +1000,7 @@ void MtmJoinTransaction(GlobalTransactionId* gtid, csn_t globalSnapshot)
9981000

9991001
void MtmSetCurrentTransactionGID(char const* gid)
10001002
{
1001-
MTM_LOG3("Set current transaction GID %s", gid);
1003+
MTM_LOG3("Set current transaction xid=%d GID %s", MtmTx.xid, gid);
10021004
strcpy(MtmTx.gid, gid);
10031005
MtmTx.isDistributed = true;
10041006
MtmTx.isReplicated = true;
@@ -1383,15 +1385,21 @@ bool MtmRefreshClusterStatus(bool nowait)
13831385
MtmCheckQuorum();
13841386
/* Interrupt voting for active transaction and abort them */
13851387
for (ts = Mtm->transListHead; ts != NULL; ts = ts->next) {
1388+
MTM_LOG3("Active transaction gid='%s', coordinator=%d, xid=%d, status=%d, gtid.xid=%d",
1389+
ts->gid, ts->gtid.node, ts->xid, ts->status, ts->gtid.xid);
13861390
if (MtmIsCoordinator(ts)) {
13871391
if (!ts->votingCompleted && ts->status != TRANSACTION_STATUS_ABORTED) {
13881392
MtmAbortTransaction(ts);
13891393
MtmWakeUpBackend(ts);
13901394
}
13911395
} else if (TransactionIdIsValid(ts->gtid.xid) && BIT_CHECK(disabled, ts->gtid.node-1)) { // coordinator of transaction is on disabled node
1392-
if (ts->gid[0] && ts->status != TRANSACTION_STATUS_ABORTED) {
1393-
MtmAbortTransaction(ts);
1394-
FinishPreparedTransaction(ts->gid, false);
1396+
if (ts->gid[0]) {
1397+
if (ts->status == TRANSACTION_STATUS_UNKNOWN || ts->status == TRANSACTION_STATUS_IN_PROGRESS) {
1398+
MTM_LOG1("%d: Abort trasaction %s because its coordinator is at disabled node %d", MyProcPid, ts->gid, ts->gtid.node);
1399+
MtmAbortTransaction(ts);
1400+
MtmTx.status = TRANSACTION_STATUS_ABORTED; /* prevent recursive invocation of MtmAbortPreparedTransaction */
1401+
FinishPreparedTransaction(ts->gid, false);
1402+
}
13951403
}
13961404
}
13971405
}
@@ -1461,6 +1469,7 @@ void MtmOnNodeDisconnect(int nodeId)
14611469
} else if (TransactionIdIsValid(ts->gtid.xid) && ts->gtid.node == nodeId) { //coordinator of transaction is on disabled node
14621470
if (ts->gid[0] && ts->status != TRANSACTION_STATUS_ABORTED) {
14631471
MtmAbortTransaction(ts);
1472+
MtmTx.status = TRANSACTION_STATUS_ABORTED; /* prevent recursive invocation of MtmAbortPreparedTransaction */
14641473
FinishPreparedTransaction(ts->gid, false);
14651474
}
14661475
}

‎contrib/mmts/pglogical_apply.c‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -524,7 +524,7 @@ process_remote_commit(StringInfo in)
524524
{
525525
case PGLOGICAL_COMMIT:
526526
{
527-
MTM_LOG3("%d: PGLOGICAL_COMMIT commit", MyProcPid);
527+
MTM_LOG1("%d: PGLOGICAL_COMMIT commit", MyProcPid);
528528
if (IsTransactionState()) {
529529
Assert(TransactionIdIsValid(MtmGetCurrentTransactionId()));
530530
MtmBeginSession();
@@ -537,7 +537,7 @@ process_remote_commit(StringInfo in)
537537
Assert(IsTransactionState() && TransactionIdIsValid(MtmGetCurrentTransactionId()));
538538
gid = pq_getmsgstring(in);
539539
/* prepare TBLOCK_INPROGRESS state for PrepareTransactionBlock() */
540-
MTM_LOG3("%d: PGLOGICAL_PREPARE commit: gid=%s", MyProcPid, gid);
540+
MTM_LOG1("%d: PGLOGICAL_PREPARE commit: gid=%s", MyProcPid, gid);
541541
BeginTransactionBlock();
542542
CommitTransactionCommand();
543543
StartTransactionCommand();
@@ -554,7 +554,7 @@ process_remote_commit(StringInfo in)
554554
Assert(!TransactionIdIsValid(MtmGetCurrentTransactionId()));
555555
csn = pq_getmsgint64(in);
556556
gid = pq_getmsgstring(in);
557-
MTM_LOG3("%d: PGLOGICAL_COMMIT_PREPARED commit: csn=%ld, gid=%s", MyProcPid, csn, gid);
557+
MTM_LOG1("%d: PGLOGICAL_COMMIT_PREPARED commit: csn=%ld, gid=%s", MyProcPid, csn, gid);
558558
StartTransactionCommand();
559559
MtmBeginSession();
560560
MtmSetCurrentTransactionCSN(csn);
@@ -567,7 +567,7 @@ process_remote_commit(StringInfo in)
567567
{
568568
Assert(!TransactionIdIsValid(MtmGetCurrentTransactionId()));
569569
gid = pq_getmsgstring(in);
570-
MTM_LOG2("%d: PGLOGICAL_ABORT_PREPARED commit: gid=%s", MyProcPid, gid);
570+
MTM_LOG1("%d: PGLOGICAL_ABORT_PREPARED commit: gid=%s", MyProcPid, gid);
571571
if (MtmGetGlobalTransactionStatus(gid) != TRANSACTION_STATUS_ABORTED) {
572572
MTM_LOG2("%d: PGLOGICAL_ABORT_PREPARED commit: gid=%s #2", MyProcPid, gid);
573573
StartTransactionCommand();

‎contrib/mmts/pglogical_proto.c‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -160,7 +160,7 @@ pglogical_write_commit(StringInfo out, PGLogicalOutputData *data,
160160
}
161161
pq_sendbyte(out, 'C'); /* sending COMMIT */
162162

163-
MTM_LOG2("PGLOGICAL_SEND commit: event=%d, gid=%s, commit_lsn=%lx, txn->end_lsn=%lx, xlog=%lx", flags, txn->gid, commit_lsn, txn->end_lsn, GetXLogInsertRecPtr());
163+
MTM_LOG1("%ld: PGLOGICAL_SEND commit: event=%d, gid=%s, commit_lsn=%lx, txn->end_lsn=%lx, xlog=%lx", MtmGetSystemTime(), flags, txn->gid, commit_lsn, txn->end_lsn, GetXLogInsertRecPtr());
164164

165165
/* send the flags field */
166166
pq_sendbyte(out, flags);

0 commit comments

Comments
 (0)