On 4/26/25 20:57, Sami Imseih wrote:
I found several issues with v4. It does not deal correctly with pipelining, and we should only really be concerned with dropping an unnamed portal only. So, v5 now moves the DropPortal call after the unnamed portal was executed to completion ( as v4 was doing ), but does so only in the case in which we are not inside a transaction-control statement or the portal was executing a command that can be run inside a transaction block.
Having taken another look at this patch, I believe it is problematic as it does not align with the protocol documentation, which states:
"An unnamed portal is destroyed at the end of the transaction, or as soon as the next Bind statement specifying the unnamed portal as destination is issued."
Attached is another patch that strictly adheres to Tom's earlier proposal in this thread:
> Perhaps a cleaner answer is to rearrange things in postgres.c > so that if there's a pre-existing unnamed portal, we drop that > before we ever set debug_query_string and friends at all.This v6 patch includes the TAP test that I sent in my previous email, with some enhancements.
From a user's point of view, Sami's patch is much better, because it always logs the right query (except for the SQL cursor), whereas this one doesn't log any queries in certain cases. However, it appears challenging to devise a clean solution that accomplishes our desired outcome.
Best regards, Frédéric
From 99c6e96c09f8807bc33712001d7f89628231c241 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Yhuel?= <[email protected]> Date: Wed, 18 Jun 2025 09:32:13 +0200 Subject: [PATCH v6] Fix reporting of temp files usage Drop unnamed portals early enough so that we avoid blaming the wrong query. There will be cases where no query is logged at all, like when using the extended protocol with unnamed portal. Moreover, when using SQL cursors, either the CLOSE request or the COMMIT will be logged, which isn't great, but like before this patch. Reviewed-by: Sami Imseih <[email protected]> --- src/backend/tcop/postgres.c | 21 +++- .../modules/test_misc/t/008_log_temp_files.pl | 113 ++++++++++++++++++ 2 files changed, 128 insertions(+), 6 deletions(-) create mode 100644 src/test/modules/test_misc/t/008_log_temp_files.pl diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 2f8c3d5f918..f307ed67827 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -1748,13 +1748,10 @@ exec_bind_message(StringInfo input_message) errdetail_abort())); /* - * Create the portal. Allow silent replacement of an existing portal only - * if the unnamed portal is specified. + * Create the portal. Don't allow silent replacement of an existing named portal. + * An unnamed portal should have been removed already. */ - if (portal_name[0] == '\0') - portal = CreatePortal(portal_name, true, true); - else - portal = CreatePortal(portal_name, false, false); + portal = CreatePortal(portal_name, false, false); /* * Prepare to copy stuff into the portal's memory context. We do all this @@ -4745,6 +4742,18 @@ PostgresMain(const char *dbname, const char *username) if (ignore_till_sync && firstchar != EOF) continue; + /* Drop unnamed portals early enough in order to avoid weird things with + * debug_query_string, like blaming the wrong query in the logs, when + * we log temporary files. */ + if (firstchar == PqMsg_Query || firstchar == PqMsg_Bind) + { + Portal portal; + + portal = GetPortalByName(""); + if (PortalIsValid(portal)) + PortalDrop(portal, false); + } + switch (firstchar) { case PqMsg_Query: diff --git a/src/test/modules/test_misc/t/008_log_temp_files.pl b/src/test/modules/test_misc/t/008_log_temp_files.pl new file mode 100644 index 00000000000..ebdd36010ff --- /dev/null +++ b/src/test/modules/test_misc/t/008_log_temp_files.pl @@ -0,0 +1,113 @@ +# 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 = none +)); +$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.2
