Hi,
On 29/08/2025 19:27, Sami Imseih wrote:
Thoughts on v8?
I tried v8 with the Java file in the original email and it works (I
don't see the wrong query in the logs).
Small fix needed in the test descriptions: used to logged -> used to log.
Only question is if we should avoid the extra portal hashtable lookup as
well, or leave that for a separate patch. I gave it a go anyways, see
attached v9, let me know what you think.
Kind regards,
Mircea Cadariu
From b2bc429dd0fb4f01920a3bf70a9756cf912f0c56 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)"
<[email protected]>
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/[email protected]
---
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)
