diff --git i/src/backend/utils/time/snapmgr.c w/src/backend/utils/time/snapmgr.c index 1c063c592ce..cbfc462ee26 100644 --- i/src/backend/utils/time/snapmgr.c +++ w/src/backend/utils/time/snapmgr.c @@ -123,6 +123,7 @@ typedef struct OldSnapshotControlData int head_offset; /* subscript of oldest tracked time */ TimestampTz head_timestamp; /* time corresponding to head xid */ int count_used; /* how many slots are in use */ + TimestampTz starttime; // rounded to minute TransactionId xid_by_minute[FLEXIBLE_ARRAY_MEMBER]; } OldSnapshotControlData; @@ -290,6 +291,8 @@ SnapMgrInit(void) oldSnapshotControl->head_offset = 0; oldSnapshotControl->head_timestamp = 0; oldSnapshotControl->count_used = 0; + oldSnapshotControl->starttime = + AlignTimestampToMinuteBoundary(GetCurrentTimestamp()); } } @@ -1762,6 +1765,39 @@ SetOldSnapshotThresholdTimestamp(TimestampTz ts, TransactionId xlimit) SpinLockRelease(&oldSnapshotControl->mutex_threshold); } +static void PrintOldSnapshotMapping(const char *head, bool already_locked) +{ + StringInfoData s; + + initStringInfo(&s); + + if (!already_locked) + LWLockAcquire(OldSnapshotTimeMapLock, LW_SHARED); + + + appendStringInfo(&s, "old snapshot mapping at \"%s\" with head ts: %lu, current entries: %d max entries: %d, offset: %d\n", + head, + (oldSnapshotControl->head_timestamp - oldSnapshotControl->starttime) / USECS_PER_MINUTE, + oldSnapshotControl->count_used, + OLD_SNAPSHOT_TIME_MAP_ENTRIES, + oldSnapshotControl->head_offset); + + for (int off = 0; off < oldSnapshotControl->count_used; off++) + { + int ringoff = (off + oldSnapshotControl->head_offset) % OLD_SNAPSHOT_TIME_MAP_ENTRIES; + + appendStringInfo(&s, " entry %d (ring %d): min %ld: xid %d\n", + off, ringoff, + (oldSnapshotControl->head_timestamp - oldSnapshotControl->starttime) / USECS_PER_MINUTE + off, + oldSnapshotControl->xid_by_minute[ringoff]); + } + + if (!already_locked) + LWLockRelease(OldSnapshotTimeMapLock); + + elog(WARNING, "%s", s.data); +} + /* * TransactionIdLimitedForOldSnapshots * @@ -1824,6 +1860,7 @@ TransactionIdLimitedForOldSnapshots(TransactionId recentXmin, if (!same_ts_as_threshold) { + PrintOldSnapshotMapping("non cached limit", false); if (ts == update_ts) { xlimit = latest_xmin; @@ -1923,14 +1960,14 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) */ if (whenTaken < 0) { - elog(DEBUG1, + elog(PANIC, "MaintainOldSnapshotTimeMapping called with negative whenTaken = %ld", (long) whenTaken); return; } if (!TransactionIdIsNormal(xmin)) { - elog(DEBUG1, + elog(PANIC, "MaintainOldSnapshotTimeMapping called with xmin = %lu", (unsigned long) xmin); return; @@ -1938,6 +1975,8 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) LWLockAcquire(OldSnapshotTimeMapLock, LW_EXCLUSIVE); + PrintOldSnapshotMapping("before update", true); + Assert(oldSnapshotControl->head_offset >= 0); Assert(oldSnapshotControl->head_offset < OLD_SNAPSHOT_TIME_MAP_ENTRIES); Assert((oldSnapshotControl->head_timestamp % USECS_PER_MINUTE) == 0); @@ -1956,7 +1995,7 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) { /* old ts; log it at DEBUG */ LWLockRelease(OldSnapshotTimeMapLock); - elog(DEBUG1, + elog(PANIC, "MaintainOldSnapshotTimeMapping called with old whenTaken = %ld", (long) whenTaken); return; @@ -1971,6 +2010,12 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) / USECS_PER_MINUTE)) % OLD_SNAPSHOT_TIME_MAP_ENTRIES; + elog(WARNING, "head %ld s: updating existing bucket %d for sec %ld with xmin %u", + (oldSnapshotControl->head_timestamp - oldSnapshotControl->starttime) / USECS_PER_SEC, + bucket, + (ts - oldSnapshotControl->starttime) / USECS_PER_SEC, + xmin); + if (TransactionIdPrecedes(oldSnapshotControl->xid_by_minute[bucket], xmin)) oldSnapshotControl->xid_by_minute[bucket] = xmin; } @@ -1980,6 +2025,13 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) int advance = ((ts - oldSnapshotControl->head_timestamp) / USECS_PER_MINUTE); + elog(WARNING, "head %ld s: filling %d buckets starting at %d for sec %ld with xmin %u", + (oldSnapshotControl->head_timestamp - oldSnapshotControl->starttime) / USECS_PER_SEC, + advance, + oldSnapshotControl->head_offset, + (ts - oldSnapshotControl->starttime) / USECS_PER_SEC, + xmin); + oldSnapshotControl->head_timestamp = ts; if (advance >= OLD_SNAPSHOT_TIME_MAP_ENTRIES) @@ -2021,6 +2073,8 @@ MaintainOldSnapshotTimeMapping(TimestampTz whenTaken, TransactionId xmin) } } + PrintOldSnapshotMapping("after update", true); + LWLockRelease(OldSnapshotTimeMapLock); }