From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Mon, 3 Apr 2023 14:18:38 +0000 (-0400)
Subject: When using valgrind, log the current query after an error is detected.
X-Git-Tag: REL_16_BETA1~346
X-Git-Url: http://git.postgresql.org/gitweb/?a=commitdiff_plain;h=a8a00124f1ddb9c8506ff75317f6dd64cc480e61;p=postgresql.git

When using valgrind, log the current query after an error is detected.

In USE_VALGRIND builds, add code to print the text of the current query
to the valgrind log whenever the valgrind error count has increased
during the query.  Valgrind will already have printed its report,
if the error is distinct from ones already seen, so that this works
out fairly well as a way of annotating the log.

Onur Tirtir and Tom Lane

Discussion: https://postgr.es/m/AM9PR83MB0498531E804DC8DF8CFF0E8FE9D09@AM9PR83MB0498.EURPRD83.prod.outlook.com
---

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index cab709b07b1..a10ecbaf50b 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -27,6 +27,10 @@
 #include <sys/socket.h>
 #include <sys/time.h>
 
+#ifdef USE_VALGRIND
+#include <valgrind/valgrind.h>
+#endif
+
 #include "access/parallel.h"
 #include "access/printtup.h"
 #include "access/xact.h"
@@ -191,6 +195,36 @@ static void enable_statement_timeout(void);
 static void disable_statement_timeout(void);
 
 
+/* ----------------------------------------------------------------
+ *		infrastructure for valgrind debugging
+ * ----------------------------------------------------------------
+ */
+#ifdef USE_VALGRIND
+/* This variable should be set at the top of the main loop. */
+static unsigned int old_valgrind_error_count;
+
+/*
+ * If Valgrind detected any errors since old_valgrind_error_count was updated,
+ * report the current query as the cause.  This should be called at the end
+ * of message processing.
+ */
+static void
+valgrind_report_error_query(const char *query)
+{
+	unsigned int valgrind_error_count = VALGRIND_COUNT_ERRORS;
+
+	if (unlikely(valgrind_error_count != old_valgrind_error_count) &&
+		query != NULL)
+		VALGRIND_PRINTF("Valgrind detected %u error(s) during execution of \"%s\"\n",
+						valgrind_error_count - old_valgrind_error_count,
+						query);
+}
+
+#else							/* !USE_VALGRIND */
+#define valgrind_report_error_query(query) ((void) 0)
+#endif							/* USE_VALGRIND */
+
+
 /* ----------------------------------------------------------------
  *		routines to obtain user input
  * ----------------------------------------------------------------
@@ -2041,6 +2075,8 @@ exec_bind_message(StringInfo input_message)
 	if (save_log_statement_stats)
 		ShowUsage("BIND MESSAGE STATISTICS");
 
+	valgrind_report_error_query(debug_query_string);
+
 	debug_query_string = NULL;
 }
 
@@ -2292,6 +2328,8 @@ exec_execute_message(const char *portal_name, long max_rows)
 	if (save_log_statement_stats)
 		ShowUsage("EXECUTE MESSAGE STATISTICS");
 
+	valgrind_report_error_query(debug_query_string);
+
 	debug_query_string = NULL;
 }
 
@@ -4287,6 +4325,12 @@ PostgresMain(const char *dbname, const char *username)
 		/* Report the error to the client and/or server log */
 		EmitErrorReport();
 
+		/*
+		 * If Valgrind noticed something during the erroneous query, print the
+		 * query string, assuming we have one.
+		 */
+		valgrind_report_error_query(debug_query_string);
+
 		/*
 		 * Make sure debug_query_string gets reset before we possibly clobber
 		 * the storage it points at.
@@ -4371,6 +4415,13 @@ PostgresMain(const char *dbname, const char *username)
 		 */
 		doing_extended_query_message = false;
 
+		/*
+		 * For valgrind reporting purposes, the "current query" begins here.
+		 */
+#ifdef USE_VALGRIND
+		old_valgrind_error_count = VALGRIND_COUNT_ERRORS;
+#endif
+
 		/*
 		 * Release storage left over from prior query cycle, and create a new
 		 * query input buffer in the cleared MessageContext.
@@ -4571,6 +4622,8 @@ PostgresMain(const char *dbname, const char *username)
 					else
 						exec_simple_query(query_string);
 
+					valgrind_report_error_query(query_string);
+
 					send_ready_for_query = true;
 				}
 				break;
@@ -4600,6 +4653,8 @@ PostgresMain(const char *dbname, const char *username)
 
 					exec_parse_message(query_string, stmt_name,
 									   paramTypes, numParams);
+
+					valgrind_report_error_query(query_string);
 				}
 				break;
 
@@ -4614,6 +4669,8 @@ PostgresMain(const char *dbname, const char *username)
 				 * the field extraction out-of-line
 				 */
 				exec_bind_message(&input_message);
+
+				/* exec_bind_message does valgrind_report_error_query */
 				break;
 
 			case 'E':			/* execute */
@@ -4631,6 +4688,8 @@ PostgresMain(const char *dbname, const char *username)
 					pq_getmsgend(&input_message);
 
 					exec_execute_message(portal_name, max_rows);
+
+					/* exec_execute_message does valgrind_report_error_query */
 				}
 				break;
 
@@ -4664,6 +4723,8 @@ PostgresMain(const char *dbname, const char *username)
 				/* commit the function-invocation transaction */
 				finish_xact_command();
 
+				valgrind_report_error_query("fastpath function call");
+
 				send_ready_for_query = true;
 				break;
 
@@ -4708,6 +4769,8 @@ PostgresMain(const char *dbname, const char *username)
 
 					if (whereToSendOutput == DestRemote)
 						pq_putemptymessage('3');	/* CloseComplete */
+
+					valgrind_report_error_query("CLOSE message");
 				}
 				break;
 
@@ -4740,6 +4803,8 @@ PostgresMain(const char *dbname, const char *username)
 											describe_type)));
 							break;
 					}
+
+					valgrind_report_error_query("DESCRIBE message");
 				}
 				break;
 
@@ -4752,6 +4817,7 @@ PostgresMain(const char *dbname, const char *username)
 			case 'S':			/* sync */
 				pq_getmsgend(&input_message);
 				finish_xact_command();
+				valgrind_report_error_query("SYNC message");
 				send_ready_for_query = true;
 				break;