From cc8b4c3b019126b4359290dfcc473ac131643558 Mon Sep 17 00:00:00 2001 From: "Sami Imseih (AWS)" Date: Fri, 29 Aug 2025 17:19:34 +0000 Subject: [PATCH v8 1/1] Drop unnamed portal before setting debug_query_string Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com --- src/backend/tcop/postgres.c | 35 ++++++ src/test/modules/test_misc/meson.build | 1 + .../modules/test_misc/t/009_log_temp_files.pl | 115 ++++++++++++++++++ 3 files changed, 151 insertions(+) create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 0cecd464902..ae86d93b900 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -148,6 +148,7 @@ static bool ignore_till_sync = false; * in order to reduce overhead for short-lived queries. */ static CachedPlanSource *unnamed_stmt_psrc = NULL; +static bool unnamed_portal = false; /* assorted command-line switches */ static const char *userDoption = NULL; /* -D switch */ @@ -182,6 +183,7 @@ static bool IsTransactionExitStmt(Node *parsetree); static bool IsTransactionExitStmtList(List *pstmts); static bool IsTransactionStmtList(List *pstmts); static void drop_unnamed_stmt(void); +static void drop_unnamed_portal(void); static void log_disconnections(int code, Datum arg); static void enable_statement_timeout(void); static void disable_statement_timeout(void); @@ -1020,6 +1022,12 @@ exec_simple_query(const char *query_string) bool use_implicit_block; char msec_str[32]; + /* + * Drop the unnamed portal before setting debug_query_string, to avoid + * attributing messages from the drop (e.g., temp usage) to the new query. + */ + drop_unnamed_portal(); + /* * Report query to various monitoring facilities. */ @@ -1672,6 +1680,12 @@ exec_bind_message(StringInfo input_message) errmsg("unnamed prepared statement does not exist"))); } + /* + * Same as exec_simple_query, drop the unnamed portal before setting + * debug_query_string. + */ + drop_unnamed_portal(); + /* * Report query to various monitoring facilities. */ @@ -1753,10 +1767,14 @@ exec_bind_message(StringInfo input_message) * if the unnamed portal is specified. */ if (portal_name[0] == '\0') + { portal = CreatePortal(portal_name, true, true); + unnamed_portal = true; + } else portal = CreatePortal(portal_name, false, false); + /* * Prepare to copy stuff into the portal's memory context. We do all this * copying first, because it could possibly fail (out-of-memory) and we @@ -5229,3 +5247,20 @@ disable_statement_timeout(void) if (get_timeout_active(STATEMENT_TIMEOUT)) disable_timeout(STATEMENT_TIMEOUT, false); } + +/* Drop the unnamed portal if one exists */ +static void +drop_unnamed_portal(void) +{ + Portal portal; + + if (!unnamed_portal) + return; + + /* Get the portal and drop it */ + portal = GetPortalByName(""); + if (PortalIsValid(portal)) + PortalDrop(portal, false); + + unnamed_portal = false; +} diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 6b1e730bf46..f258bf1ccd9 100644 --- a/src/test/modules/test_misc/meson.build +++ b/src/test/modules/test_misc/meson.build @@ -17,6 +17,7 @@ tests += { 't/006_signal_autovacuum.pl', 't/007_catcache_inval.pl', 't/008_replslot_single_user.pl', + 't/009_log_temp_files.pl', ], }, } diff --git a/src/test/modules/test_misc/t/009_log_temp_files.pl b/src/test/modules/test_misc/t/009_log_temp_files.pl new file mode 100644 index 00000000000..9699f1767f1 --- /dev/null +++ b/src/test/modules/test_misc/t/009_log_temp_files.pl @@ -0,0 +1,115 @@ +# Copyright (c) 2025, PostgreSQL Global Development Group + +# Verify that temp files are logged with the right statement. + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +sub check_log +{ + my $node = shift; + my $offset = shift; + + if ($node->log_contains('STATEMENT: SELECT 1', $offset)) + { + ok(0, "The wrong query has been logged"); + } + elsif ($node->log_contains('STATEMENT: SELECT a FROM foo ORDER BY a', $offset)) + { + ok(1, "The right query has been logged"); + } + elsif ($node->log_contains('STATEMENT: CLOSE', $offset)) + { + ok(1, "Cursor CLOSE has been logged, OK"); + } + else + { + ok(1, "No query has been logged"); + } +} + +my $offset = 0; +my $node = PostgreSQL::Test::Cluster->new('primary'); +$node->init(); +$node->append_conf( + 'postgresql.conf', qq( +work_mem = 64kB +log_temp_files = 0 +log_statement = all +log_line_prefix='%t [%p]: [%l-1] user=%u,db=%d,host=%h,app=%a,cilent=%h' +log_min_duration_statement = 0 +)); +$node->start; + +$node->safe_psql("postgres", qq{ +CREATE UNLOGGED TABLE foo(a int); +INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000); +VACUUM ANALYZE foo; +}); + +$offset = -s $node->logfile; +# The following sequence used to logged the second query instead of the first one +# Now it should log no query at all +$node->safe_psql("postgres", qq{ +BEGIN; +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g +SELECT 1; +COMMIT; +}); +check_log($node, $offset); + +$offset = -s $node->logfile; +# The following sequence should log no query at all +$node->safe_psql("postgres", qq{ +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g +SELECT 1; +}); +check_log($node, $offset); + +$offset = -s $node->logfile; +# The following pipelined sequence used to logged the second query instead of the first one +# Now it should log no query at all +$node->safe_psql("postgres", qq{ +\\startpipeline +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\sendpipeline +SELECT 1; +\\endpipeline +}); +check_log($node, $offset); + +$offset = -s $node->logfile; +# The following sequence should log the right query +$node->safe_psql("postgres", qq{ +SELECT a FROM foo ORDER BY a OFFSET 4999; +}); +check_log($node, $offset); + +$offset = -s $node->logfile; +# The following sequence should log no query at all (named statement, unnamed portal) +$node->safe_psql("postgres", qq{ +BEGIN; +SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt +\\bind_named stmt 4999 \\g +SELECT 1; +COMMIT; +}); +check_log($node, $offset); + +$offset = -s $node->logfile; +# The following sequence should log the CLOSE query +$node->safe_psql("postgres", qq{ +BEGIN; +DECLARE mycur CURSOR FOR SELECT a FROM foo ORDER BY a OFFSET 4999; +FETCH 10 FROM mycur; +SELECT 1; +CLOSE mycur; +COMMIT; +}); +check_log($node, $offset); + + +$node->stop('fast'); +done_testing(); -- 2.47.3