From b2bc429dd0fb4f01920a3bf70a9756cf912f0c56 Mon Sep 17 00:00:00 2001 From: "Sami Imseih (AWS)" Date: Fri, 29 Aug 2025 17:19:34 +0000 Subject: [PATCH v9] 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 | 48 +++++++- src/backend/utils/mmgr/portalmem.c | 62 ++++++---- src/include/utils/portal.h | 1 + src/test/modules/test_misc/meson.build | 1 + .../modules/test_misc/t/009_log_temp_files.pl | 115 ++++++++++++++++++ 5 files changed, 199 insertions(+), 28 deletions(-) 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 0cecd46490..bbfee7c0ce 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. */ @@ -1213,7 +1221,13 @@ exec_simple_query(const char *query_string) * Create unnamed portal to run the query or queries in. If there * already is one, silently drop it. */ - portal = CreatePortal("", true, true); + if (!unnamed_portal) + portal = CreatePortalOnly(""); + else + portal = CreatePortal("", true, true); + + unnamed_portal = true; + /* Don't display the portal in pg_cursors */ portal->visible = false; @@ -1672,6 +1686,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,7 +1773,14 @@ exec_bind_message(StringInfo input_message) * if the unnamed portal is specified. */ if (portal_name[0] == '\0') - portal = CreatePortal(portal_name, true, true); + { + if (!unnamed_portal) + portal = CreatePortalOnly(portal_name); + else + portal = CreatePortal(portal_name, true, true); + + unnamed_portal = true; + } else portal = CreatePortal(portal_name, false, false); @@ -5229,3 +5256,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/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c index 0be1c2b0ff..facb475fd9 100644 --- a/src/backend/utils/mmgr/portalmem.c +++ b/src/backend/utils/mmgr/portalmem.c @@ -162,37 +162,13 @@ PortalGetPrimaryStmt(Portal portal) return NULL; } -/* - * CreatePortal - * Returns a new portal given a name. - * - * allowDup: if true, automatically drop any pre-existing portal of the - * same name (if false, an error is raised). - * - * dupSilent: if true, don't even emit a WARNING. - */ Portal -CreatePortal(const char *name, bool allowDup, bool dupSilent) +CreatePortalOnly(const char *name) { - Portal portal; + Portal portal; Assert(PointerIsValid(name)); - portal = GetPortalByName(name); - if (PortalIsValid(portal)) - { - if (!allowDup) - ereport(ERROR, - (errcode(ERRCODE_DUPLICATE_CURSOR), - errmsg("cursor \"%s\" already exists", name))); - if (!dupSilent) - ereport(WARNING, - (errcode(ERRCODE_DUPLICATE_CURSOR), - errmsg("closing existing cursor \"%s\"", - name))); - PortalDrop(portal, false); - } - /* make new portal structure */ portal = (Portal) MemoryContextAllocZero(TopPortalContext, sizeof *portal); @@ -227,6 +203,40 @@ CreatePortal(const char *name, bool allowDup, bool dupSilent) return portal; } +/* + * CreatePortal + * Returns a new portal given a name. + * + * allowDup: if true, automatically drop any pre-existing portal of the + * same name (if false, an error is raised). + * + * dupSilent: if true, don't even emit a WARNING. + */ +Portal +CreatePortal(const char *name, bool allowDup, bool dupSilent) +{ + Portal portal; + + Assert(PointerIsValid(name)); + + portal = GetPortalByName(name); + if (PortalIsValid(portal)) + { + if (!allowDup) + ereport(ERROR, + (errcode(ERRCODE_DUPLICATE_CURSOR), + errmsg("cursor \"%s\" already exists", name))); + if (!dupSilent) + ereport(WARNING, + (errcode(ERRCODE_DUPLICATE_CURSOR), + errmsg("closing existing cursor \"%s\"", + name))); + PortalDrop(portal, false); + } + + return CreatePortalOnly(name); +} + /* * CreateNewPortal * Create a new portal, assigning it a random nonconflicting name. diff --git a/src/include/utils/portal.h b/src/include/utils/portal.h index 0b62143af8..fb80bf3945 100644 --- a/src/include/utils/portal.h +++ b/src/include/utils/portal.h @@ -226,6 +226,7 @@ extern void AtSubAbort_Portals(SubTransactionId mySubid, ResourceOwner myXactOwner, ResourceOwner parentXactOwner); extern void AtSubCleanup_Portals(SubTransactionId mySubid); +extern Portal CreatePortalOnly(const char *name); extern Portal CreatePortal(const char *name, bool allowDup, bool dupSilent); extern Portal CreateNewPortal(void); extern void PinPortal(Portal portal); diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 6b1e730bf4..f258bf1ccd 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 0000000000..d16eb82a54 --- /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 log 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 log 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(); base-commit: 09119238a18191dea3deed635a2b2a6ffe904932 -- 2.39.5 (Apple Git-154)