Hi, On 11/09/2025 16:28, Sami Imseih wrote:
I prefer a separate thread for this, as it's an optimization of the existing behavior.
OK, I removed my changes to CreatePortal. I left the test description fixes and added a proposed commit message.
If no objections I will set it to ready for committer in the app. Kind regards, Mircea Cadariu
From 268e2a5bac002ed32db4b2b8ab5dc4bb4f64c290 Mon Sep 17 00:00:00 2001 From: "Sami Imseih (AWS)" <[email protected]> Date: Fri, 29 Aug 2025 17:19:34 +0000 Subject: [PATCH v10] =?UTF-8?q?Fix=20incorrect=20query=20attribution=20in?= =?UTF-8?q?=20temporary=E2=80=90file=20logging?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously, in the extended query protocol with unnamed portals, the log line for temporary files would show the wrong STATEMENT: line (e.g. from a subsequent simple query) rather than the query that actually caused the temp file. This happened because the unnamed portal from the previous Bind was dropped after setting the new debug_query_string, so the logging triggered by PortalDrop used the new query text instead of the one that had generated the temporary file. This patch ensures that when an unnamed portal is dropped, it is associated with the correct query text by dropping the previous unnamed portal before assigning the debug_query_string. Author: Sami Imseih <[email protected]> Author: Frédéric Yhuel <[email protected]> Reviewed-by: Mircea Cadariu <[email protected]> Discussion: https://www.postgresql.org/message-id/flat/[email protected] --- 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 d356830f75..d74e9e7bd1 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); @@ -1024,6 +1026,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. */ @@ -1676,6 +1684,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. */ @@ -1757,10 +1771,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 @@ -5236,3 +5254,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 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: ae0e1be9f2a20f6b64072dcee5b8dd7b9027a8fa -- 2.39.5 (Apple Git-154)
