[Backport to 2.2] [YSQL] #5051 For non-prepared statements, optimize …

…pg_statistic system table lookups

Summary:
Allow caching of negative (not found) results for pg_statistic and
pg_statistic_ext tables since we do not change those in YSQL yet.

Additionally, update the debug utilities for YSQL by removing the general
variable 'yb_debug_mode' and adding:

yb_debug_report_error_stacktrace:
   - Add stacktrace information to every YSQL error.
   - Effectively replaces (yb_debug_mode).
yb_debug_log_catcache_events:
   - Log cache misses and cache refresh events.
yb_debug_log_internal_restarts:
   - Log automatic statement (or transaction) restarts
   - e.g. read-restarts and schema mismatch restarts.
yb_debug_log_docdb_requests:
   - Log protobufs of all outgoing DocDB requests.

Test Plan:
Jenkins: rebase: 2.2

In ysqlsh, run the following queries and check that no
'Catalog cache miss' entries are found in the tserver's
postgresql log.

```
-- setup tables
create table t1(k int primary key, v int);
create table t2(k int primary key, v int);
-- Execute the query once to load up the caches
select * from t1, t2 where t1.k = t2.k;
-- enable cache events log and re-run the query.
set yb_debug_log_catcache_events = true;
select * from t1, t2 where t1.k = t2.k;
select * from t1, t2 where t1.k = t2.k;
select * from t1, t2 where t1.k = t2.k;
-- reset (disable) the cache events log.
reset yb_debug_log_catcache_events;
```

Reviewers: neha, neil, dmitry, alex

Reviewed By: alex

Subscribers: yql, kannan

Differential Revision: https://phabricator.dev.yugabyte.com/D9034

src/postgres/src/backend/tcop/postgres.c

@@ -3694,6 +3694,11 @@ static void YBRefreshCache()
 				        errmsg("Cannot refresh cache within a transaction")));
 	}
 
+	if (yb_debug_log_catcache_events)
+	{
+		ereport(LOG,(errmsg("Refreshing catalog cache.")));
+	}
+
 	/* Get the latest syscatalog version from the master */
 	uint64_t catalog_master_version = 0;
 	YBCPgGetCatalogMasterVersion(&catalog_master_version);
@@ -3716,7 +3721,7 @@ static void YBRefreshCache()
 	finish_xact_command();
 }
 
-static void YBPrepareCacheRefreshIfNeeded(MemoryContext oldcontext,
+static void YBPrepareCacheRefreshIfNeeded(ErrorData *edata,
                                           bool consider_retry,
                                           bool *need_retry)
 {
@@ -3734,10 +3739,6 @@ static void YBPrepareCacheRefreshIfNeeded(MemoryContext oldcontext,
 	if (!IsYugaByteEnabled())
 		return;
 
-	/* Get error data */
-	ErrorData *edata;
-	MemoryContextSwitchTo(oldcontext);
-	edata = CopyErrorData();
 	bool is_retryable_err = YBNeedRetryAfterCacheRefresh(edata);
 	if ((table_to_refresh = strstr(edata->message,
 								   table_cache_refresh_search_str)) != NULL)
@@ -3798,7 +3799,6 @@ static void YBPrepareCacheRefreshIfNeeded(MemoryContext oldcontext,
 		{
 			/* Clear error state */
 			FlushErrorState();
-			FreeErrorData(edata);
 
 			/*
 			 * Make sure debug_query_string gets reset before we possibly clobber
@@ -3855,7 +3855,6 @@ static void YBPrepareCacheRefreshIfNeeded(MemoryContext oldcontext,
 	{
 		/* Clear error state */
 		FlushErrorState();
-		FreeErrorData(edata);
 	}
 }
 
@@ -4213,6 +4212,15 @@ yb_attempt_to_restart_on_error(int attempt,
 
 	if (yb_is_read_restart_nedeed(edata) &&
 	    yb_is_read_restart_possible(attempt, restart_data)) {
+		if (yb_debug_log_internal_restarts)
+		{
+			ereport(LOG,
+			        (errmsg("Restarting statement due to read-restart error:"
+			                "\nQuery: %s\nError: %s\nAttempt No: %d",
+			                restart_data->query_string,
+			                edata->message,
+			                attempt)));
+		}
 		/* cleanup the error, restart portal, restart txn and let the control flow continue */
 		FlushErrorState();
 		PopActiveSnapshot(); /* restart read error occurrs after portal snapshot is pushed */
@@ -4281,6 +4289,15 @@ yb_exec_execute_message_attempting_to_restart_read(const char* portal_name,
 	}
 }
 
+static void yb_report_cache_version_restart(const char* query, ErrorData *edata)
+{
+	ereport(LOG,
+	        (errmsg("Restarting statement due to catalog version mismatch:"
+	                "\nQuery: %s\nError: %s",
+	                query,
+	                edata->message)));
+}
+
 /* ----------------------------------------------------------------
  * PostgresMain
  *	   postgres main loop -- all backends, interactive or otherwise start here
@@ -4850,17 +4867,35 @@ PostgresMain(int argc, char *argv[],
 				}
 				PG_CATCH();
 				{
+					/* Get error data */
+					ErrorData *edata;
+					MemoryContext errorcontext = MemoryContextSwitchTo(oldcontext);
+					edata = CopyErrorData();
+
 					bool need_retry = false;
-					YBPrepareCacheRefreshIfNeeded(oldcontext,
+					YBPrepareCacheRefreshIfNeeded(edata,
                                                   yb_check_retry_allowed(query_string),
                                                   &need_retry);
 
 					if (need_retry)
 					{
 						if (!am_walsender || !exec_replication_command(query_string))
-                          yb_exec_simple_query_attempting_to_restart_read(query_string, oldcontext);
-					} else
+						{
+							if (yb_debug_log_internal_restarts)
+							{
+								yb_report_cache_version_restart(query_string, edata);
+							}
+							/*
+							 * Free edata before restarting, in other branches
+							 * the memory context will get reset after anyway.
+							 */
+							FreeErrorData(edata);
+							yb_exec_simple_query_attempting_to_restart_read(query_string, oldcontext);
+						}
+					}
+					else
 					{
+						MemoryContextSwitchTo(errorcontext);
 						PG_RE_THROW();
 					}
 				}
@@ -4907,14 +4942,20 @@ PostgresMain(int argc, char *argv[],
 					}
 					PG_CATCH();
 					{
+						/* Get error data */
+						ErrorData *edata;
+						MemoryContext errorcontext = MemoryContextSwitchTo(oldcontext);
+						edata = CopyErrorData();
+
 						/*
 						 * TODO Cannot retry parse statements yet (without
 						 * aborting the followup bind/execute.
 						 */
 						bool need_retry = false;
-						YBPrepareCacheRefreshIfNeeded(oldcontext,
+						YBPrepareCacheRefreshIfNeeded(edata,
 						                              false /* consider_retry */,
 						                              &need_retry);
+						MemoryContextSwitchTo(errorcontext);
 						PG_RE_THROW();
 
 					}
@@ -4962,6 +5003,11 @@ PostgresMain(int argc, char *argv[],
 					}
 					PG_CATCH();
 					{
+						/* Get error data */
+						ErrorData *edata;
+						MemoryContext errorcontext = MemoryContextSwitchTo(oldcontext);
+						edata = CopyErrorData();
+
 						/*
 						 * The portal recreation logic is restored to the pre-#2216 state
 						 * (it was reworked in #4254).
@@ -5009,12 +5055,22 @@ PostgresMain(int argc, char *argv[],
 						 * Execute may have been partially applied so need to
 						 * cleanup (and restart) the transaction.
 						 */
-						YBPrepareCacheRefreshIfNeeded(oldcontext,
+						YBPrepareCacheRefreshIfNeeded(edata,
 						                              can_retry,
 						                              &need_retry);
 
 						if (need_retry && can_retry)
 						{
+							if (yb_debug_log_internal_restarts)
+							{
+								yb_report_cache_version_restart(query_string, edata);
+							}
+							/*
+							 * Free edata before restarting, in other branches
+							 * the memory context will get reset after anyway.
+							 */
+							FreeErrorData(edata);
+
 							/* 1. Redo Parse: Create Cached stmt (no output) */
 							exec_parse_message(query_string,
 							                   portal_name,
@@ -5066,6 +5122,7 @@ PostgresMain(int argc, char *argv[],
 						}
 						else
 						{
+							MemoryContextSwitchTo(errorcontext);
 							PG_RE_THROW();
 						}
 

src/postgres/src/backend/utils/cache/catcache.c

@@ -1707,6 +1707,42 @@ SearchCatCacheMiss(CatCache *cache,
 	 */
 	relation = heap_open(cache->cc_reloid, AccessShareLock);
 
+	if (yb_debug_log_catcache_events)
+	{
+		StringInfoData buf;
+		initStringInfo(&buf);
+
+		/*
+		 * For safety, disable catcache logging within the scope of this
+		 * function as YBDatumToString below may trigger additional cache
+		 * lookups (to get the attribute type info).
+		 */
+		yb_debug_log_catcache_events = false;
+		for (int i = 0; i < nkeys; i++)
+		{
+			if (i > 0)
+				appendStringInfoString(&buf, ", ");
+
+			int attnum = cache->cc_keyno[i];
+			Oid typid = OIDOID; // default.
+			if (attnum > 0)
+				typid = TupleDescAttr(cache->cc_tupdesc, attnum - 1)->atttypid;
+
+			appendStringInfoString(&buf, YBDatumToString(cur_skey[i].sk_argument, typid));
+		}
+		ereport(LOG,
+		        (errmsg("Catalog cache miss on cache with id %d:\n"
+		                "Target rel: %s (oid : %d), index oid %d\n"
+		                "Search keys: %s",
+		                cache->id,
+		                cache->cc_relname,
+		                cache->cc_reloid,
+		                cache->cc_indexoid,
+		                buf.data)));
+		/* Done, reset catcache logging. */
+		yb_debug_log_catcache_events = true;
+	}
+
 	scandesc = systable_beginscan(relation,
 								  cache->cc_indexoid,
 								  IndexScanOK(cache, cur_skey),
@@ -1754,7 +1790,21 @@ SearchCatCacheMiss(CatCache *cache,
 		 */
 		if (IsYugaByteEnabled())
 		{
+			/*
+			 * Special cases where we allow negative caches:
+			 * 1. pg_cast (CASTSOURCETARGET) to avoid master lookups during
+			 *    parsing.
+			 *    TODO: reconsider this now that we support CREATE CAST.
+			 * 2. pg_statistic (STATRELATTINH) and pg_statistic_ext
+			 *    (STATEXTNAMENSP and STATEXTOID) since we do not support
+			 *    statistics in DocDB/YSQL yet.
+			 * 3. pg_class (RELNAMENSP) but only for system tables since users
+			 *    cannot create system tables in YSQL.
+			 */
 			bool allow_negative_entries = cache->id == CASTSOURCETARGET ||
+			                              cache->id == STATRELATTINH ||
+			                              cache->id == STATEXTNAMENSP ||
+			                              cache->id == STATEXTOID ||
 			                              (cache->id == RELNAMENSP &&
 			                               DatumGetObjectId(cur_skey[1].sk_argument) ==
 			                               PG_CATALOG_NAMESPACE &&

src/postgres/src/backend/utils/error/elog.c

@@ -788,7 +788,7 @@ errcode_for_socket_access(void)
 		/* Done with expanded fmt */ \
 		pfree(fmtbuf); \
 		/* In YB debug mode, add stack trace info (to first msg only) */ \
-		if (IsYugaByteEnabled() && yb_debug_mode && !appendval) { \
+		if (IsYugaByteEnabled() && yb_debug_report_error_stacktrace && !appendval) { \
 			appendStringInfoString(&buf, YBCGetStackTrace()); \
 		} \
 		/* Save the completed message into the stack item */ \

src/postgres/src/backend/utils/misc/guc.c

@@ -1835,12 +1835,45 @@ static struct config_bool ConfigureNamesBool[] =
 	},
 
 	{
-		{"yb_debug_mode", PGC_USERSET, DEVELOPER_OPTIONS,
-			gettext_noop("Enable yb debugging."),
+		{"yb_debug_report_error_stacktrace", PGC_USERSET, DEVELOPER_OPTIONS,
+			gettext_noop("Append stacktrace information for error messages."),
 			NULL,
 			GUC_NOT_IN_SAMPLE
 		},
-		&yb_debug_mode,
+		&yb_debug_report_error_stacktrace,
+		false,
+		NULL, NULL, NULL
+	},
+
+	{
+		{"yb_debug_log_catcache_events", PGC_USERSET, DEVELOPER_OPTIONS,
+			gettext_noop("Log details for every catalog cache event such as a cache miss or cache invalidation/refresh."),
+			NULL,
+			GUC_NOT_IN_SAMPLE
+		},
+		&yb_debug_log_catcache_events,
+		false,
+		NULL, NULL, NULL
+	},
+
+	{
+		{"yb_debug_log_internal_restarts", PGC_USERSET, DEVELOPER_OPTIONS,
+			gettext_noop("Log details for internal restarts such as read-restarts, cache-invalidation restarts, or txn restarts."),
+			NULL,
+			GUC_NOT_IN_SAMPLE
+		},
+		&yb_debug_log_internal_restarts,
+		false,
+		NULL, NULL, NULL
+	},
+
+	{
+		{"yb_debug_log_docdb_requests", PGC_USERSET, DEVELOPER_OPTIONS,
+			gettext_noop("Log the contents of all internal (protobuf) requests to DocDB."),
+			NULL,
+			GUC_NOT_IN_SAMPLE
+		},
+		&yb_debug_log_docdb_requests,
 		false,
 		NULL, NULL, NULL
 	},

src/postgres/src/backend/utils/misc/pg_yb_utils.c

@@ -670,7 +670,11 @@ YBRaiseNotSupportedSignal(const char *msg, int issue_no, int signal_level)
 //------------------------------------------------------------------------------
 // YB Debug utils.
 
-bool yb_debug_mode = false;
+bool yb_debug_report_error_stacktrace = false;
+
+bool yb_debug_log_catcache_events = false;
+
+bool yb_debug_log_internal_restarts = false;
 
 const char*
 YBDatumToString(Datum datum, Oid typid)

src/postgres/src/include/pg_yb_utils.h

@@ -274,10 +274,29 @@ void YBRaiseNotSupportedSignal(const char *msg, int issue_no, int signal_level);
 // YB Debug utils.
 
 /**
- * YSQL variable that can be used to enable/disable yugabyte debug mode.
- * e.g. 'SET yb_debug_mode=true'.
+ * YSQL guc variables that can be used to toggle yugabyte debug features.
+ * e.g. 'SET yb_debug_report_error_stacktrace=true' and
+ *      'RESET yb_debug_report_error_stacktrace'.
+ * See also the corresponding entries in guc.c.
+ */
+
+/* Add stacktrace information to every YSQL error. */
+extern bool yb_debug_report_error_stacktrace;
+
+/* Log cache misses and cache refresh events. */
+extern bool yb_debug_log_catcache_events;
+
+/*
+ * Log automatic statement (or transaction) restarts such as read-restarts and
+ * schema-version restarts (e.g. catalog version mismatch errors).
+ */
+extern bool yb_debug_log_internal_restarts;
+
+/*
+ * See also ybc_util.h which contains additional such variable declarations for
+ * variables that are (also) used in the pggate layer.
+ * Currently: yb_debug_log_docdb_requests.
  */
-extern bool yb_debug_mode;
 
 /*
  * Get a string representation of a datum (given its type).

src/yb/common/ybc_util.cc

@@ -38,6 +38,8 @@ using std::string;
 DEFINE_test_flag(string, process_info_dir, string(),
                  "Directory where all postgres process will writes their PIDs and executable name");
 
+bool yb_debug_log_docdb_requests = false;
+
 namespace yb {
 
 namespace {

src/yb/common/ybc_util.h

@@ -26,6 +26,12 @@ struct varlena;
 
 #endif
 
+/*
+ * Guc variable to log the protobuf string for every outgoing (DocDB) read/write request.
+ * See the "YB Debug utils" section in pg_yb_utils.h (as well as guc.c) for more information.
+ */
+extern bool yb_debug_log_docdb_requests;
+
 typedef struct YBCStatusStruct* YBCStatus;
 
 extern YBCStatus YBCStatusOK;