From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Mon, 16 Apr 2018 17:44:39 +0000 (-0400)
Subject: Add temporary debug logging, in 9.4 branch only.
X-Git-Tag: REL9_4_18~27
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=e55380f3b60108d402f64131fe655b0e5ccc1f31;p=postgresql

Add temporary debug logging, in 9.4 branch only.

Commit 5ee940e1c served its purpose by demonstrating that buildfarm
member okapi is seeing some sort of locally-visible state mismanagement,
not a cross-process data visibility problem as I'd first theorized.
Put in some elog(LOG) messages in hopes of gathering more info about
exactly what's happening there.  Again, this is temporary code to be
reverted once we have buildfarm results.

Discussion: https://postgr.es/m/6744.1523833660@sss.pgh.pa.us
---

diff --git a/src/backend/commands/indexcmds.c b/src/backend/commands/indexcmds.c
index 05afcb0088..e8b9d1a4dd 100644
--- a/src/backend/commands/indexcmds.c
+++ b/src/backend/commands/indexcmds.c
@@ -758,6 +758,8 @@ DefineIndex(Oid relationId,
 	 */
 	validate_index(relationId, indexRelationId, snapshot);
 
+	PrintSnapMgrStatus("concurrent index build, before snapshot release");
+
 	/*
 	 * Drop the reference snapshot.  We must do this before waiting out other
 	 * snapshot holders, else we will deadlock against other processes also
@@ -770,9 +772,13 @@ DefineIndex(Oid relationId,
 	limitXmin = snapshot->xmin;
 
 	PopActiveSnapshot();
+	PrintSnapMgrStatus("concurrent index build, after PopActiveSnapshot");
 	UnregisterSnapshot(snapshot);
+	PrintSnapMgrStatus("concurrent index build, after UnregisterSnapshot");
 	InvalidateCatalogSnapshot();
 
+	PrintSnapMgrStatus("concurrent index build, after InvalidateCatalogSnapshot");
+
 	/*
 	 * The index is now valid in the sense that it contains all currently
 	 * interesting tuples.  But since it might not contain tuples deleted just
diff --git a/src/backend/utils/time/snapmgr.c b/src/backend/utils/time/snapmgr.c
index 331c91044f..2a3d915e1f 100644
--- a/src/backend/utils/time/snapmgr.c
+++ b/src/backend/utils/time/snapmgr.c
@@ -1401,3 +1401,17 @@ HistoricSnapshotGetTupleCids(void)
 	Assert(HistoricSnapshotActive());
 	return tuplecid_data;
 }
+
+void
+PrintSnapMgrStatus(const char *context)
+{
+	int			asdepth = 0;
+	ActiveSnapshotElt *active;
+
+	for (active = ActiveSnapshot; active != NULL; active = active->as_next)
+		asdepth++;
+
+	elog(LOG, "%s: %d reg snaps, %d active snaps, cat snap %p, xmin %u",
+		 context, RegisteredSnapshots, asdepth,
+		 CatalogSnapshot, MyPgXact->xmin);
+}
diff --git a/src/include/utils/snapmgr.h b/src/include/utils/snapmgr.h
index c6aa361950..71452d9afe 100644
--- a/src/include/utils/snapmgr.h
+++ b/src/include/utils/snapmgr.h
@@ -65,4 +65,6 @@ extern void SetupHistoricSnapshot(Snapshot snapshot_now, struct HTAB *tuplecids)
 extern void TeardownHistoricSnapshot(bool is_error);
 extern bool HistoricSnapshotActive(void);
 
+extern void PrintSnapMgrStatus(const char *context);
+
 #endif   /* SNAPMGR_H */