[BUG] temporary file usage report with extended protocol and unnamed portals

Started by Frédéric Yhuel9 months ago62 messages
#1Frédéric Yhuel
frederic.yhuel@dalibo.com
2 attachment(s)

Hi,

It seems there's a bug in the logging of temporary file usage when the
extended protocol is used with unnamed portals.

For example, with the attached Java / pgJDBC programs, we get the
following logs:

[...] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp525566.0",
size 2416640
[..] STATEMENT: SELECT 1

but it should be:

[...] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp538230.0",
size 2416640
[...] STATEMENT: SELECT * FROM foo ORDER BY a OFFSET $1 LIMIT 2

It has been tested with HEAD and REL_17_STABLE.

My guess is that there's a race somewhere, probably when the global
variable "debug_query_string" is set.
The unnamed portal is closed when the BIND of the next query arrives
(here: SELECT 1), and I suspect that the variable is set before the
temporary file is deleted (and logged).

pgJDBC uses unnamed portals, but I don't think this is specific to JDBC.
I see the same problem with the attached Python / psycopg3 program.
I think it would be better if the drivers used named portals all the
time (and an explicit close message), but this seems to be a postgres bug.

What do you think?

Best regards,
Frédéric

PS : the dataset is created like this on the server:

CREATE UNLOGGED TABLE foo(a int);
INSERT INTO foo SELECT * FROM generate_series(1, 200000);
ALTER SYSTEM SET log_temp_files = 0;
ALTER SYSTEM SET log_min_duration_statement = -1
SELECT pg_reload_conf();

Attachments:

babar.pytext/x-python; charset=UTF-8; name=babar.pyDownload
Babar.javatext/x-java; charset=UTF-8; name=Babar.javaDownload
#2Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Frédéric Yhuel (#1)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/18/25 10:49, Frédéric Yhuel wrote:

Hi,

It seems there's a bug in the logging of temporary file usage when the
extended protocol is used with unnamed portals.

FWIW, the attached patch seems to fix the problem.

Best regards,
Frédéric

Attachments:

0001-fix-reporting-of-temp-files-usage.patchtext/x-patch; charset=UTF-8; name=0001-fix-reporting-of-temp-files-usage.patchDownload
From afb228f07f847c467ba05dbe204861e7be2ffc32 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Yhuel?= <frederic.yhuel@dalibo.com>
Date: Fri, 18 Apr 2025 13:20:52 +0200
Subject: [PATCH] fix reporting of temp files usage

when extended protocol is used with unnamed portals
---
 src/backend/utils/mmgr/portalmem.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c
index e3526e78064..246e711db81 100644
--- a/src/backend/utils/mmgr/portalmem.c
+++ b/src/backend/utils/mmgr/portalmem.c
@@ -27,6 +27,7 @@
 #include "utils/memutils.h"
 #include "utils/snapmgr.h"
 #include "utils/timestamp.h"
+#include "tcop/tcopprot.h"
 
 /*
  * Estimate of the maximum number of open portals a user would have,
@@ -488,6 +489,9 @@ PortalDrop(Portal portal, bool isTopCommit)
 				(errcode(ERRCODE_INVALID_CURSOR_STATE),
 				 errmsg("cannot drop active portal \"%s\"", portal->name)));
 
+	if (portal->queryDesc)
+		debug_query_string = portal->queryDesc->sourceText;
+
 	/*
 	 * Allow portalcmds.c to clean up the state it knows about, in particular
 	 * shutting down the executor if still active.  This step potentially runs
-- 
2.47.2

#3Sami Imseih
samimseih@gmail.com
In reply to: Frédéric Yhuel (#2)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

[...] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp525566.0",
size 2416640
[..] STATEMENT: SELECT 1

but it should be:

[...] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp538230.0",
size 2416640
[...] STATEMENT: SELECT * FROM foo ORDER BY a OFFSET $1 LIMIT 2

hmm, looking at the repro and your patch, I was really confused by
why the STATEMENT: ends up being SELECT 1 even though the
query with temp being tracked is the ORDER BY query.

So, I ran a slowed down test where there is a 15 second thread sleep between
the ORDER BY and SELECT 1 ( see attached ) and I also ran it with the
following GUCs enabled

```
log_temp_files = '0'
work_mem = '64kB'
max_parallel_workers_per_gather = '0'
log_min_duration_statement = '0'
```

2025-04-18 13:31:45.572 CDT [95918] LOG: duration: 0.046 ms bind
<unnamed>: select pg_sleep(0)
2025-04-18 13:31:45.572 CDT [95918] LOG: duration: 0.009 ms execute
<unnamed>: select pg_sleep(0)
2025-04-18 13:31:45.574 CDT [95918] LOG: duration: 0.454 ms parse
<unnamed>: SELECT * FROM foo ORDER BY a
2025-04-18 13:31:45.575 CDT [95918] LOG: duration: 0.278 ms bind
<unnamed>: SELECT * FROM foo ORDER BY a
2025-04-18 13:31:46.396 CDT [95918] LOG: duration: 821.076 ms
execute <unnamed>: SELECT * FROM foo ORDER BY a

2025-04-18 13:32:01.403 CDT [95918] LOG: duration: 0.438 ms parse
<unnamed>: SELECT 1
2025-04-18 13:32:01.454 CDT [95918] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp95918.0", size 202039296
2025-04-18 13:32:01.454 CDT [95918] STATEMENT: SELECT 1
2025-04-18 13:32:01.454 CDT [95918] LOG: duration: 50.818 ms bind
<unnamed>: SELECT 1
2025-04-18 13:32:01.454 CDT [95918] LOG: duration: 0.022 ms execute
<unnamed>: SELECT 1
2025-04-18 13:32:01.457 CDT [95918] LOG: duration: 0.064 ms parse S_1: COMMIT
2025-04-18 13:32:01.457 CDT [95918] LOG: duration: 0.017 ms bind S_1: COMMIT
2025-04-18 13:32:01.457 CDT [95918] LOG: duration: 0.105 ms execute
S_1: COMMIT

In the log above, it shows that the temporary file logging does not
actually occur
until the next query is executed, so at that point the query string is
already "SELECT 1"

what is even more interesting is when running the commands directly from psql
using extended query protocol, the STATEMENT is not logged after the
temporary file message.

```
SELECT FROM foo ORDER BY a \bind
;
SELECT 1 \bind
;
```

```
istance=0 kB, estimate=0 kB; lsn=0/E55A088, redo lsn=0/E55A030
2025-04-18 13:36:39.275 CDT [96237] LOG: duration: 1.447 ms parse
<unnamed>: SELECT FROM foo ORDER BY a
;
2025-04-18 13:36:39.275 CDT [96237] LOG: duration: 0.719 ms bind
<unnamed>: SELECT FROM foo ORDER BY a
;
2025-04-18 13:36:39.822 CDT [96237] LOG: duration: 546.803 ms
execute <unnamed>: SELECT FROM foo ORDER BY a
;
2025-04-18 13:36:39.852 CDT [96237] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp96237.0", size 202039296
2025-04-18 13:36:40.736 CDT [96237] LOG: duration: 0.394 ms parse
<unnamed>: SELECT 1
;
2025-04-18 13:36:40.736 CDT [96237] LOG: duration: 0.133 ms bind
<unnamed>: SELECT 1
;
2025-04-18 13:36:40.736 CDT [96237] LOG: duration: 0.023 ms execute
<unnamed>: SELECT 1
;
```

I think the DropPortal is happening later in the JDBC case, and only
after the next query is
executed, maybe? So your patch does take care of the problem because
it ensures that
the drop portal, when it occurs, is referencing the correct sql. I am
not yet sure if the patch
the right solution yet, it maybe the best answer.

I don't have a better answer, but wanted to share this research as well.

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

Test.javaapplication/octet-stream; name=Test.javaDownload
#4Sami Imseih
samimseih@gmail.com
In reply to: Sami Imseih (#3)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

I looked into this a bit more.

What occurs during exec_bind_message is that the debug_query_string of the
query is set early on. Later in that routine, a new portal is created
via CreatePortal,
which also drops the existing unnamed portal from the previous
execution and which
also logs the temp file information. So the logging is now using the
debug_query_string
of the current query and not the one referenced by the to-be-dropped portal.

This behavior means that there is a delay in log_temp_files logging,
since the portal
must be dropped, which can occur after the statement has completed
execution. We can look
into improving that, but I am not sure whether it is possible or can
be done safely.

I think the solution proposed by Frédéric seems reasonable: to switch
the debug_query_string
inside PortalDrop. However, I do not like the way the
debug_query_string changes values
after the CreatePortal call inside exec_bind_message; that seems incorrect.
So, I believe we should temporarily switch the debug_query_string
value only while
running PortalDrop. Attached is what I think could be safer to do.
What do you think?

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

v2-0001-Fix-race-condition-between-debug_query_string-and.patchapplication/octet-stream; name=v2-0001-Fix-race-condition-between-debug_query_string-and.patchDownload
From b86c752889aabd40e4e2f6ab1b36f090fe0abc6b Mon Sep 17 00:00:00 2001
From: Sami Imseih <simseih@amazon.com>
Date: Sat, 19 Apr 2025 08:00:27 -0500
Subject: [PATCH v2 1/1] Fix race condition between debug_query_string and
 PortalDrop
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

It was discovered that temporary file logging could be associated
with incorrect query text. This is because temporary file logging
occurs when the portal is dropped, but this can occur when a new
query starts execution, such as in the case of unnamed portals.
To correct this behavior, PortalDrop should temporarily switch to
using a debug_query_string set to that of the query associated with
the portal being dropped.

Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972%40dalibo.com
---
 src/backend/utils/mmgr/portalmem.c | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)

diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c
index e3526e78064..04224551cdf 100644
--- a/src/backend/utils/mmgr/portalmem.c
+++ b/src/backend/utils/mmgr/portalmem.c
@@ -27,6 +27,7 @@
 #include "utils/memutils.h"
 #include "utils/snapmgr.h"
 #include "utils/timestamp.h"
+#include "tcop/tcopprot.h"
 
 /*
  * Estimate of the maximum number of open portals a user would have,
@@ -469,6 +470,8 @@ MarkPortalFailed(Portal portal)
 void
 PortalDrop(Portal portal, bool isTopCommit)
 {
+	char *save_debug_query_string;
+
 	Assert(PortalIsValid(portal));
 
 	/*
@@ -488,6 +491,17 @@ PortalDrop(Portal portal, bool isTopCommit)
 				(errcode(ERRCODE_INVALID_CURSOR_STATE),
 				 errmsg("cannot drop active portal \"%s\"", portal->name)));
 
+	/*
+	 * By the time this point is reached, a query string different from the one
+	 * referenced by this to-be-dropped portal could be used. Therefore, let's
+	 * temporarily switch the debug_query_string to report on this portal.
+	 */
+	if (portal->queryDesc && debug_query_string)
+	{
+		save_debug_query_string = pstrdup(debug_query_string);
+		debug_query_string = portal->queryDesc->sourceText;
+	}
+
 	/*
 	 * Allow portalcmds.c to clean up the state it knows about, in particular
 	 * shutting down the executor if still active.  This step potentially runs
@@ -596,6 +610,8 @@ PortalDrop(Portal portal, bool isTopCommit)
 	/* release subsidiary storage */
 	MemoryContextDelete(portal->portalContext);
 
+	debug_query_string = save_debug_query_string;
+
 	/* release portal struct (it's in TopPortalContext) */
 	pfree(portal);
 }
-- 
2.39.5 (Apple Git-154)

#5Tom Lane
tgl@sss.pgh.pa.us
In reply to: Sami Imseih (#4)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Sami Imseih <samimseih@gmail.com> writes:

I think the solution proposed by Frédéric seems reasonable: to switch
the debug_query_string
inside PortalDrop. However, I do not like the way the
debug_query_string changes values
after the CreatePortal call inside exec_bind_message; that seems incorrect.
So, I believe we should temporarily switch the debug_query_string
value only while
running PortalDrop. Attached is what I think could be safer to do.
What do you think?

I don't think this is safe at all. The portal's query string
is potentially shorter-lived than the portal, see in particular
exec_simple_query which just passes a pointer to the original
string in MessageContext.

I'm frankly inclined to do nothing, but if we must do something,
the way to fix it here would be to transiently set debug_query_string
to NULL so that the actions of PortalDrop aren't blamed on any
particular query. (In my testing, the "temporary file:" message comes
out without any attached STATEMENT most of the time already, so this
isn't losing much as far as that's concerned.)

The whole thing is just a band-aid, though. debug_query_string
is not the only indicator of what the backend is currently doing.
If somebody comes along and complains that the pg_stat_activity
entry doesn't reflect what's happening, are we going to take
that seriously?

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 would add an extra portal hashtable lookup, but I'm not sure
if that would be measurable or not. (Possibly we could get that
back by simplifying CreatePortal's API so that it doesn't need to
perform an initial lookup.)

regards, tom lane

#6Sami Imseih
samimseih@gmail.com
In reply to: Tom Lane (#5)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Sami Imseih <samimseih@gmail.com> writes:

I think the solution proposed by Frédéric seems reasonable: to switch
the debug_query_string
inside PortalDrop. However, I do not like the way the
debug_query_string changes values
after the CreatePortal call inside exec_bind_message; that seems incorrect.
So, I believe we should temporarily switch the debug_query_string
value only while
running PortalDrop. Attached is what I think could be safer to do.
What do you think?

I don't think this is safe at all. The portal's query string
is potentially shorter-lived than the portal, see in particular
exec_simple_query which just passes a pointer to the original
string in MessageContext.

Yes, you are correct. The comments about MessageContect in
mmgr/README give me pause.

"....
This
is kept separate from per-transaction and per-portal contexts because a
query string might need to live either a longer or shorter time than any
single transaction or portal.
"""

I'm frankly inclined to do nothing, but if we must do something,
the way to fix it here would be to transiently set debug_query_string
to NULL so that the actions of PortalDrop aren't blamed on any
particular query. (In my testing, the "temporary file:" message comes
out without any attached STATEMENT most of the time already, so this
isn't losing much as far as that's concerned.)

moreover, as I was looking into why the case mentioned earlier

```
SELECT FROM foo ORDER BY a \bind
;
SELECT 1 \bind
;
```

does not show STATEMENT after the temp file logging, I realized
it's because the temp files are cleaned up and reported at
the end of transaction, which means that debug_query_string is NULL at the
time the portal is dropped in the next query. This causes
check_log_of_query to return false.

/* query string available? */
if (debug_query_string == NULL)
return false;

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.

That did cross my mind as well, but I was trying to avoid doing this
type of rearranging. I still rather not go down that path considering the
case mentioned above will still not display the query text in a STATEMENT log.

I'm frankly inclined to do nothing, but if we must do something,
the way to fix it here would be to transiently set debug_query_string
to NULL so that the actions of PortalDrop aren't blamed on any
particular query.

I think this is better, because I rather we avoid lines like the below in which
there are temp files being reported all with STATEMENT logging
of a different query. It's better to just not show STATEMENT at all.

```
2025-04-19 16:44:38.082 CDT [38963] STATEMENT: SELECT 1
2025-04-19 16:44:38.115 CDT [38963] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp38963.1", size 1073741824
2025-04-19 16:44:38.115 CDT [38963] STATEMENT: SELECT 1
2025-04-19 16:44:38.149 CDT [38963] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp38963.2", size 1073741824
2025-04-19 16:44:38.149 CDT [38963] STATEMENT: SELECT 1
2025-04-19 16:44:38.305 CDT [38963] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp38963.3", size 1073741824
2025-04-19 16:44:38.305 CDT [38963] STATEMENT: SELECT 1
2025-04-19 16:44:38.558 CDT [38963] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp38963.4", size 1073741824
2025-04-19 16:44:38.558 CDT [38963] STATEMENT: SELECT 1
2025-04-19 16:44:38.744 CDT [38963] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp38963.5", size 1073741824
```

--
Sami Imseih
Amazon Web Services (AWS)

#7Guillaume Lelarge
guillaume.lelarge@dalibo.com
In reply to: Sami Imseih (#6)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Hi,

On 20/04/2025 00:42, Sami Imseih wrote:

[...]

I'm frankly inclined to do nothing, but if we must do something,
the way to fix it here would be to transiently set debug_query_string
to NULL so that the actions of PortalDrop aren't blamed on any
particular query.

I think this is better, because I rather we avoid lines like the below in which
there are temp files being reported all with STATEMENT logging
of a different query. It's better to just not show STATEMENT at all.

We should definitely avoid blaming the wrong query. I'd prefer we always
log queries using temp files but if this isn't doable easily or without
mistakes, then don't log the query at all.

--
Guillaume Lelarge
Consultant
https://dalibo.com

#8Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#6)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/20/25 00:42, Sami Imseih wrote:

(In my testing, the "temporary file:" message comes
out without any attached STATEMENT most of the time already, so this
isn't losing much as far as that's concerned.)

Indeed, this happens when using autocommit / implicit transactions.

But if you disable autocommit, and I think this is the most common
setting, we do have the attached statement.

moreover, as I was looking into why the case mentioned earlier

```
SELECT FROM foo ORDER BY a \bind
;
SELECT 1 \bind
;
```

does not show STATEMENT after the temp file logging, I realized
it's because the temp files are cleaned up and reported at
the end of transaction, which means that debug_query_string is NULL at the
time the portal is dropped in the next query. This causes
check_log_of_query to return false.

/* query string available? */
if (debug_query_string == NULL)
return false;

Yes, we actually have two related bugs.

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.

That did cross my mind as well, but I was trying to avoid doing this
type of rearranging. I still rather not go down that path considering the
case mentioned above will still not display the query text in a STATEMENT log.

IMHO, it would be nice to fix the explicit transactions case.

The bug with implicit transactions is less serious.

I can try to implement Tom's idea if we have a consensus.

Best regards,
Frédéric

#9Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Frédéric Yhuel (#8)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/21/25 07:46, Frédéric Yhuel wrote:

I can try to implement Tom's idea if we have a consensus.

v3 attached. Would that do?

Attachments:

v3-0001-fix-reporting-of-temp-files-usage.patchtext/x-patch; charset=UTF-8; name=v3-0001-fix-reporting-of-temp-files-usage.patchDownload
From 07d331ba0f91b999fcefd12696bfc1eda7e8f20f Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Yhuel?= <frederic.yhuel@dalibo.com>
Date: Fri, 18 Apr 2025 13:20:52 +0200
Subject: [PATCH v3] fix reporting of temp files usage

when extended protocol is used with unnamed portals
---
 src/backend/tcop/postgres.c        | 19 +++++++++++++------
 src/backend/utils/mmgr/portalmem.c |  4 ++++
 2 files changed, 17 insertions(+), 6 deletions(-)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dc4c600922d..1b0c98828c8 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1018,7 +1018,11 @@ exec_simple_query(const char *query_string)
 	bool		was_logged = false;
 	bool		use_implicit_block;
 	char		msec_str[32];
+	Portal		portal;
 
+	portal = GetPortalByName("");
+	if (PortalIsValid(portal))
+		PortalDrop(portal, false);
 	/*
 	 * Report query to various monitoring facilities.
 	 */
@@ -1672,6 +1676,12 @@ exec_bind_message(StringInfo input_message)
 					 errmsg("unnamed prepared statement does not exist")));
 	}
 
+	if (portal_name[0] == '\0')
+	{
+		portal = GetPortalByName(portal_name);
+		if (PortalIsValid(portal))
+			PortalDrop(portal, false);
+	}
 	/*
 	 * Report query to various monitoring facilities.
 	 */
@@ -1749,13 +1759,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
diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c
index e3526e78064..246e711db81 100644
--- a/src/backend/utils/mmgr/portalmem.c
+++ b/src/backend/utils/mmgr/portalmem.c
@@ -27,6 +27,7 @@
 #include "utils/memutils.h"
 #include "utils/snapmgr.h"
 #include "utils/timestamp.h"
+#include "tcop/tcopprot.h"
 
 /*
  * Estimate of the maximum number of open portals a user would have,
@@ -488,6 +489,9 @@ PortalDrop(Portal portal, bool isTopCommit)
 				(errcode(ERRCODE_INVALID_CURSOR_STATE),
 				 errmsg("cannot drop active portal \"%s\"", portal->name)));
 
+	if (portal->queryDesc)
+		debug_query_string = portal->queryDesc->sourceText;
+
 	/*
 	 * Allow portalcmds.c to clean up the state it knows about, in particular
 	 * shutting down the executor if still active.  This step potentially runs
-- 
2.47.2

#10Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Frédéric Yhuel (#8)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/21/25 07:46, Frédéric Yhuel wrote:

On 4/20/25 00:42, Sami Imseih wrote:

(In my testing, the "temporary file:" message comes
out without any attached STATEMENT most of the time already, so this
isn't losing much as far as that's concerned.)

Indeed, this happens when using autocommit / implicit transactions.

Actually, this also happens with Java-style cursors, i.e. using the
setFetchSize(<count>) method, which pgJDBC converts to using named
portals and EXECUTE <name> <count> protocol messages.

The explanation is probably very similar to the one Sami gave for the
implicit transaction case.

In any case, my v3 patch seems to fix all these cases.

(I'm not saying it's good enough to be committed as is. I think I should
at least add some comments. Anything else?)

#11Sami Imseih
samimseih@gmail.com
In reply to: Frédéric Yhuel (#10)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

In any case, my v3 patch seems to fix all these cases.

(I'm not saying it's good enough to be committed as is. I think I should
at least add some comments. Anything else?)

the patch relies on looking up queryDesc->sourceText inside DropPortal,
which Tom raised concerns about earlier in the thread [0]/messages/by-id/CAA5RZ0ssqRTz_9T0Gy74SiTViiX3V0rSFxc4N_4GNcbEBK9wow@mail.gmail.com

So, It seems to me we are better off just setting debug_query_string
to NULL in DropPortal, or alternatively why not just log the statement
automatically at the start of execution whenever we have log_temp_files > 0.
That will allow us to safely capture the statement to blame for the
temp files and
will cover all cases?

[0]: /messages/by-id/CAA5RZ0ssqRTz_9T0Gy74SiTViiX3V0rSFxc4N_4GNcbEBK9wow@mail.gmail.com

--
Sami Imseih
Amazon Web Services (AWS)

#12Sami Imseih
samimseih@gmail.com
In reply to: Sami Imseih (#11)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

So, It seems to me we are better off just setting debug_query_string
to NULL in DropPortal, or alternatively why not just log the statement
automatically at the start of execution whenever we have log_temp_files > 0.
That will allow us to safely capture the statement to blame for the
temp files and will cover all cases?

of course we only know about the temp file usage after execution,
so this means we will probably end up with unnecessary
statement logging, so this may not be such a good idea after all.

So this tells me not logging STATEMENT along with log_temp_files is a
better alternative and a statement can be logged with other existing
mechanisms like log_min_duration_statement.

--
Sami Imseih
Amazon Web Services (AWS)

#13Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#11)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/22/25 19:37, Sami Imseih wrote:

the patch relies on looking up queryDesc->sourceText inside DropPortal,
which Tom raised concerns about earlier in the thread [0]

Yes, I think I had misunderstood what Tom said. Thank you for pointing
that out.

However, is it really unsafe?

In exec_bind_message, the portal's query string comes from a duplicate
of the original string (see CreateCachedPlan). So we are safe in this case.

In exec_simple_query, the portal is dropped towards the end of this
function, so we are safe here too.

Am I missing something?

#14Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Frédéric Yhuel (#13)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/23/25 09:41, Frédéric Yhuel wrote:

On 4/22/25 19:37, Sami Imseih wrote:

the patch relies on looking up queryDesc->sourceText inside DropPortal,
which Tom raised concerns about earlier in the thread [0]

Yes, I think I had misunderstood what Tom said. Thank you for pointing
that out.

However, is it really unsafe?

In exec_bind_message, the portal's query string comes from a duplicate
of the original string (see CreateCachedPlan). So we are safe in this case.

In exec_simple_query, the portal is dropped towards the end of this
function, so we are safe here too.

Am I missing something?

Note: the patch doesn't work well with server-side prepared statements:
the PREPARE query is blamed instead of the EXECUTE one. But this is
maybe something that can be fixed easily.

#15Sami Imseih
samimseih@gmail.com
In reply to: Frédéric Yhuel (#13)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Yes, I think I had misunderstood what Tom said. Thank you for pointing
that out.

However, is it really unsafe?

I have not been able to find a case where this is unsafe, but
the documentation in mmgr/README does indicate that the
query string may live shorter than the portal in some cases.

"....
This
is kept separate from per-transaction and per-portal contexts because a
query string might need to live either a longer or shorter time than any
single transaction or portal.
"""

Also, another strange behavior of the way portal cleanup occurs is that
in extended-query-protocol and within a transaction, ExecutorEnd for the
last query is not actually called until the next command. This just seems
odd to me especially for extensions that rely on ExecutorEnd.

So, Can we do something like this? This drops the portal as soon as
execution completes ( the portal is fetched to completion ). This will
ensure that there is no delay in ExecutorEnd getting called and in the
case of log_temp_files, the message will be logged while debug_query_string
is still pointing to the correct query.

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dc4c600922d..efe0151ca8f 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2327,6 +2327,9 @@ exec_execute_message(const char *portal_name,
long max_rows)
                /* Send appropriate CommandComplete to client */
                EndCommand(&qc, dest, false);
+
+               if (!portal->portalPinned)
+                       PortalDrop(portal, false);
        }
        else
        {

```
postgres=# begin;
BEGIN
postgres=*# select from foo order by a \bind
postgres-*# ;
--
(1000000 rows)

postgres=*# select 1 \bind
postgres-*# ;
?column?
----------
1
(1 row)

postgres=*# commit;
COMMIT
```

```
2025-04-23 11:11:47.777 CDT [67362] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp67362.0", size 1009983488
2025-04-23 11:11:47.777 CDT [67362] STATEMENT: select from foo order by a
;
```

thoughts?

--
Sami Imseih
Amazon Web Services (AWS)

#16Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#15)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 4/23/25 18:13, Sami Imseih wrote:

Also, another strange behavior of the way portal cleanup occurs is that
in extended-query-protocol and within a transaction, ExecutorEnd for the
last query is not actually called until the next command. This just seems
odd to me especially for extensions that rely on ExecutorEnd.

So, Can we do something like this? This drops the portal as soon as
execution completes ( the portal is fetched to completion ). This will
ensure that there is no delay in ExecutorEnd getting called and in the
case of log_temp_files, the message will be logged while debug_query_string
is still pointing to the correct query.

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dc4c600922d..efe0151ca8f 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2327,6 +2327,9 @@ exec_execute_message(const char *portal_name,
long max_rows)
/* Send appropriate CommandComplete to client */
EndCommand(&qc, dest, false);
+
+               if (!portal->portalPinned)
+                       PortalDrop(portal, false);
}
else
{

I don't know if it is the correct solution, but it seems good to me
(FWIW), and I've tested it and it works well in all the following cases:

* Java program: extended protocol used for the two queries (the one that
use the temp file and the SELECT 1).

* Python program: the SELECT 1 is using the simple protocol.

* SQL PREPARE / EXECUTE

* Another version of the Java program using the
setFetchSize() method (and named portals).

#17Sami Imseih
samimseih@gmail.com
In reply to: Frédéric Yhuel (#16)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Thanks for testing. I also tested it a bit more today with other
patterns like different fetch sizes, named portal, etc. and I can't
find an issue with this, but I could be missing something.
I will go ahead and attach this change in patch form.

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

v4-Correct-timing-of-portal-drop-in-an-execute-message.patchapplication/octet-stream; name=v4-Correct-timing-of-portal-drop-in-an-execute-message.patchDownload
From c8f88cc7be57821ea9eb28bf6280ac980fed3519 Mon Sep 17 00:00:00 2001
From: Sami Imseih <simseih@amazon.com>
Date: Fri, 25 Apr 2025 16:59:50 -0500
Subject: [PATCH 1/1] Correct timing of portal drop in an execute message

In the extended query protocol, unnamed portals within a transaction
are dropped whenever the next query execution starts, and creating a
new unnamed portal requires dropping the previous one. This behavior
is problematic for several reasons, not least because it delays the
execution of the ExecutorEnd hook. This patch addresses the issue by
ensuring that the portal is dropped only after it has been fully
fetched to completion.
---
 src/backend/tcop/postgres.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dc4c600922d..cb4c4854078 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2327,6 +2327,10 @@ exec_execute_message(const char *portal_name, long max_rows)
 
 		/* Send appropriate CommandComplete to client */
 		EndCommand(&qc, dest, false);
+
+		/* close the portal, if not pinned */
+		if (!portal->portalPinned)
+			PortalDrop(portal, false);
 	}
 	else
 	{
-- 
2.39.5 (Apple Git-154)

#18Sami Imseih
samimseih@gmail.com
In reply to: Sami Imseih (#17)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

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.

Also, I realize that explicit cursors ( DECLARE CURSOR ) will
only log temp file at cursor close and in which case, the statement
associated with the temp file logging is the CLOSE command:

i.e.

```
2025-04-26 18:46:38.084 UTC [10415] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp10415.0", size 1014030336
2025-04-26 18:46:38.084 UTC [10415] STATEMENT: close mycursor_1;
```

I don't think there is much we can do there, or should we.

--
Sami Imseih

Attachments:

v5-0001-Correct-timing-of-portal-drop-in-an-execute-messa.patchapplication/octet-stream; name=v5-0001-Correct-timing-of-portal-drop-in-an-execute-messa.patchDownload
From 3558aba4af7b77ab98464f4d90155c46a2307534 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)"
 <simseih@dev-dsk-simseih-1d-3940b79e.us-east-1.amazon.com>
Date: Sat, 26 Apr 2025 17:34:09 +0000
Subject: [PATCH v5 1/1] Correct timing of portal drop in an execute message

In the extended query protocol, unnamed portals within a transaction
are dropped whenever the next query execution starts, which at that
point creating a new unnamed portal requires dropping the previous one.
This is problematic for problematic for several reasons, not least because
it delays the execution of the ExecutorEnd hook or delays the logging of
temp file usage ( log_temp_files ). This patch addresses the issue by
ensuring that the portal is dropped only after it has been fully
fetched to completion, in the cases that the portal is not a transaction
control statement or requires to be run outside of a transaction block.
---
 src/backend/tcop/postgres.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dc4c600922d..8c537dfca88 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2323,6 +2323,10 @@ exec_execute_message(const char *portal_name, long max_rows)
 			 * message.  The next protocol message will start a fresh timeout.
 			 */
 			disable_statement_timeout();
+
+			/* unnamed portal executed to completion, so close it */
+			if (portal_name[0] == '\0')
+				PortalDrop(portal, false);
 		}
 
 		/* Send appropriate CommandComplete to client */
-- 
2.47.1

#19Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#18)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

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.

I've tested your v5, and it works well.

I've also attached a TAP test that checks the following cases:

1. An unnamed statement followed by a simple query, both in the same
transaction;
2. An unnamed statement in an implicit transaction;
3. Unnamed statements in pipeline mode.

Patch handles these three cases correctly, while pre-patch blames the
wrong query for cases 1. and 3., and logs no query at all for case 2.

Initially, I've tried to use pg_regress, but the query is only written
in the server log (it is not sent to the frontend). Furthermore, the pid
number in the first line of the log makes it impossible (it seems) to
write the expected output file.

Also, I realize that explicit cursors ( DECLARE CURSOR ) will
only log temp file at cursor close and in which case, the statement
associated with the temp file logging is the CLOSE command:

i.e.

```
2025-04-26 18:46:38.084 UTC [10415] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp10415.0", size 1014030336
2025-04-26 18:46:38.084 UTC [10415] STATEMENT: close mycursor_1;
```

I don't think there is much we can do there, or should we.

I don't think either.

Best regards,
Frédéric

Attachments:

008_log_temp_files.plapplication/x-perl; name=008_log_temp_files.plDownload
#20Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#18)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

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

Attachments:

v6-0001-Fix-reporting-of-temp-files-usage.patchtext/x-patch; charset=UTF-8; name=v6-0001-Fix-reporting-of-temp-files-usage.patchDownload
From 99c6e96c09f8807bc33712001d7f89628231c241 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Yhuel?= <frederic.yhuel@dalibo.com>
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 <samimseih@gmail.com>
---
 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

#21Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Frédéric Yhuel (#20)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 8/21/25 14:02, Frédéric Yhuel wrote:

This v6 patch includes the TAP test that I sent in my previous email,
with some enhancements.

The meson test system was overlooked by this patch, and the attached v7
fixes that.

Attachments:

v7-0001-Fix-reporting-of-temp-files-usage.patchtext/x-patch; charset=UTF-8; name=v7-0001-Fix-reporting-of-temp-files-usage.patchDownload
From 554e8e62675574cbde0fd35b0a10f6ae56e5f0d6 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Yhuel?= <frederic.yhuel@dalibo.com>
Date: Wed, 18 Jun 2025 09:32:13 +0200
Subject: [PATCH v7] 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 <samimseih@gmail.com>
---
 src/backend/tcop/postgres.c                   |  21 +++-
 src/test/modules/test_misc/meson.build        |   1 +
 .../modules/test_misc/t/008_log_temp_files.pl | 113 ++++++++++++++++++
 3 files changed, 129 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/meson.build b/src/test/modules/test_misc/meson.build
index 9c50de7efb0..44d44d5344c 100644
--- a/src/test/modules/test_misc/meson.build
+++ b/src/test/modules/test_misc/meson.build
@@ -16,6 +16,7 @@ tests += {
       't/005_timeouts.pl',
       't/006_signal_autovacuum.pl',
       't/007_catcache_inval.pl',
+      't/008_log_temp_files.pl',
     ],
   },
 }
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

#22Sami Imseih
samimseih@gmail.com
In reply to: Frédéric Yhuel (#21)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 8/21/25 14:02, Frédéric Yhuel wrote:

This v6 patch includes the TAP test that I sent in my previous email,
with some enhancements.

The meson test system was overlooked by this patch, and the attached v7
fixes that.

This version needs another rebase, but I don't think this is a proper solution
yet. It's dropping the portal in an area I don't think we should be concerned
with, and it's not covering some simple cases, like a bind/execute followed
by a simple query. Also, I don't like we have to incur an extra GetPortalByName
lookup in the simple query case.

What about we just drop the unnamed portal before setting the
debug_query_string,
as Tom pointed out, but we also track if we have an active unnamed portal before
incurring the GetPortalName.

I am attaching v8 which does that. In this version, a new routine called
drop_unnamed_portal checks if there is an unnamed portal (tracked by a
backend flag),
and drops the unnamed portal inside exec_simple_query and
exec_bind_message before setting debug_query_string; so early on in the routine
before creating the new portal.

```
2025-08-29 13:03:33.412 CDT [54069] STATEMENT: SELECT a FROM foo
ORDER BY a OFFSET $1
2025-08-29 13:03:33.412 CDT [54069] LOG: statement: SELECT 1;
2025-08-29 13:03:33.412 CDT [54069] ERROR: current transaction is
aborted, commands ignored until end of transaction block
2025-08-29 13:03:33.412 CDT [54069] STATEMENT: SELECT 1;
2025-08-29 13:03:33.501 CDT [54069] LOG: statement: COMMIT;
2025-08-29 13:05:11.617 CDT [54656] LOG: statement: BEGIN;
2025-08-29 13:05:11.618 CDT [54656] LOG: execute <unnamed>: SELECT a
FROM foo ORDER BY a OFFSET $1
2025-08-29 13:05:11.618 CDT [54656] DETAIL: Parameters: $1 = '4999'
2025-08-29 13:05:11.619 CDT [54656] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp54656.0", size 73728
2025-08-29 13:05:11.619 CDT [54656] LOG: statement: SELECT 1;
2025-08-29 13:05:11.619 CDT [54656] LOG: statement: COMMIT
```

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),

I think the temp logging on the cursor close is OK and expected, and we
are blaming the correct cursor.
```
DECLARE CURSOR
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
2
(1 row)

test=*# fetch foo;
LOG: statement: fetch foo;
a
---
3
(1 row)

test=*# SELECT $1 \bind 1
test-*# ;
LOG: execute <unnamed>: SELECT $1
;
DETAIL: Parameters: $1 = '1'
?column?
----------
1
(1 row)

test=*# close foo;
LOG: statement: close foo;
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp55603.0", size 90112
CLOSE CURSOR
test=*#
```

When we rollback, is the one case I can think of in which we will not be able
to blame the correct query, such as the example below. So I don't think
we will be able to make logging work correctly for all cases, since the
temp logging happens at a far lower layer.

```
test=# begin;
LOG: statement: begin;
BEGIN
test=*# declare foo cursor for SELECT a FROM foo ORDER BY a OFFSET 1;
LOG: statement: declare foo cursor for SELECT a FROM foo ORDER BY a OFFSET 1;
DECLARE CURSOR
test=*# fetch foo;
LOG: statement: fetch foo;
a
---
2
(1 row)

test=*# fetch foo;
LOG: statement: fetch foo;
a
---
3
(1 row)

test=*# fetch foo;
LOG: statement: fetch foo;
a
---
4
(1 row)

test=*# fetch all foo;
LOG: statement: fetch all foo;
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp56184.1", size 69944
a
------
5
...
....
test=*# SELECT $1 \bind 1
test-*# ;
LOG: execute <unnamed>: SELECT $1
;
DETAIL: Parameters: $1 = '1'
?column?
----------
1
(1 row)

test=*# close foo_noexist;
LOG: statement: close foo_noexist;
ERROR: cursor "foo_noexist" does not exist
LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp56184.0", size 90112
test=!#
```

Thoughts on v8?

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

v8-0001-Drop-unnamed-portal-before-setting-debug_query_st.patchapplication/octet-stream; name=v8-0001-Drop-unnamed-portal-before-setting-debug_query_st.patchDownload
From cc8b4c3b019126b4359290dfcc473ac131643558 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)"
 <simseih@dev-dsk-simseih-1e-c76a1a95.us-east-1.amazon.com>
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

#23Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#22)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

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

Attachments:

v9-0001-Drop-unnamed-portal-before-setting-debug_query_st.patchtext/plain; charset=UTF-8; name=v9-0001-Drop-unnamed-portal-before-setting-debug_query_st.patchDownload
From b2bc429dd0fb4f01920a3bf70a9756cf912f0c56 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)"
 <simseih@dev-dsk-simseih-1e-c76a1a95.us-east-1.amazon.com>
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)

#24Sami Imseih
samimseih@gmail.com
In reply to: Mircea Cadariu (#23)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Only question is if we should avoid the extra portal hashtable lookup as well, or leave that for a separate patch.

I prefer a separate thread for this, as it's an optimization of the
existing behavior.

--
Sami Imseih
Amazon Web Services (AWS)

#25Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#24)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

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

Attachments:

v10-0001-Fix-incorrect-query-attribution-in-temporary-fil.patchtext/plain; charset=UTF-8; name=v10-0001-Fix-incorrect-query-attribution-in-temporary-fil.patchDownload
From 268e2a5bac002ed32db4b2b8ab5dc4bb4f64c290 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)"
 <simseih@dev-dsk-simseih-1e-c76a1a95.us-east-1.amazon.com>
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 <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
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 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)

#26Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#24)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Thu, Sep 11, 2025 at 10:28:50AM -0500, Sami Imseih wrote:

Only question is if we should avoid the extra portal hashtable lookup as well, or leave that for a separate patch.

I prefer a separate thread for this, as it's an optimization of the
existing behavior.

-		portal = CreatePortal("", true, true);
+		if (!unnamed_portal)
+			portal = CreatePortalOnly("");
+		else
+			portal = CreatePortal("", true, true);
[...]
-CreatePortal(const char *name, bool allowDup, bool dupSilent)
+CreatePortalOnly(const char *name)
+Portal
+CreatePortal(const char *name, bool allowDup, bool dupSilent)

Talking about v9 here, as far as I can see. I don't think that it is
a wise idea to create a new API for this layer, while duplicating two
times the same pattern where the old CreatePortal() function and the
new CreatePortalOnly() function are called. CreatePortalOnly() is
called by CreatePortal(), adding to the confusion. If we refactor
this API, it may be an idea to use a bits32 with two flags rather than
two booleans, especially if we justify a third boolean case. That
would make CreatePortal() more solid on ABI grounds in the long-term,
as well.

Just my 2c while looking at this particular part of the thread. Now
to the main patch proposed, v8 or v10..
--
Michael

#27Sami Imseih
samimseih@gmail.com
In reply to: Michael Paquier (#26)
2 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Just my 2c while looking at this particular part of the thread. Now
to the main patch proposed, v8 or v10..

I have been thinking about whether test coverage is worth it for temp
file logging. I think it is, but others may disagree. However, I also
don't think the current tests are correct.

For example, this is not true. We should now always log the correct query.
```
ok(0, "The wrong query has been logged");
```

Also, the tests should be checking that we are logging "temporary file: "
before the next statement is logged.

I split up the actual fix and the corrected tests into separate patches.
They can be committed together if there is agreement that tests are worth it.

--
Sami

Attachments:

v11-0001-Fix-temp-file-log-blame-for-unnamed-portals.patchapplication/octet-stream; name=v11-0001-Fix-temp-file-log-blame-for-unnamed-portals.patchDownload
From 3a506025e84349d212d57949971eb7f70767d328 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Tue, 16 Sep 2025 19:00:06 +0000
Subject: [PATCH v11 1/2] Fix temp file log blame for unnamed portals.
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

With the extended query protocol, temporary files created by unnamed
portals could be blamed on the wrong statement. Because temp file logging
happens when the portal is dropped, this patch ensures that unnamed portals
are dropped before resetting debug_query_string, so that temp files are
blamed on the correct statement.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/backend/tcop/postgres.c | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index d356830f756..d74e9e7bd12 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;
+}
-- 
2.43.0

v11-0002-Add-tests-for-temp-table-logging.patchapplication/octet-stream; name=v11-0002-Add-tests-for-temp-table-logging.patchDownload
From d6ec2d08f5059cb17c43908d768b5a89127aaa11 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Tue, 16 Sep 2025 19:03:54 +0000
Subject: [PATCH v11 2/2] Add tests for temp table logging

---
 src/test/modules/test_misc/meson.build        |  1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 91 +++++++++++++++++++
 2 files changed, 92 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

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..dc5d6aee70a
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,91 @@
+#
+# Verify that temp files are logged with the right statement.
+#
+# Copyright (c) 2021-2025, PostgreSQL Global Development Group
+#
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+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_min_duration_statement = 0
+));
+$node->start;
+
+# Setup table and populate with data
+$node->safe_psql("postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+VACUUM ANALYZE foo;
+});
+
+# unnamed portal test
+my $log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+SELECT 1;
+END;
+});
+$node->wait_for_log(qr/LOG:\s+execute <unnamed>:\s+SELECT a FROM foo ORDER BY a OFFSET \$1.*LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with unnamed portal");
+
+# named portal test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 1;
+END;
+});
+$node->wait_for_log(qr/LOG:\s+execute stmt:\s+SELECT a FROM foo ORDER BY a OFFSET \$1.*LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with named portal");
+
+# pipelined query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\sendpipeline
+SELECT 1;
+\\endpipeline
+});
+$node->wait_for_log(qr/LOG:\s+execute <unnamed>:\s+SELECT a FROM foo ORDER BY a OFFSET \$1.*LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with pipelined query");
+
+# cursor test
+$log_offset = -s $node->logfile;
+$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;
+END;
+});
+$node->wait_for_log(qr/LOG:  statement: CLOSE mycur;.*LOG:  temporary file: path.*/s, $log_offset);
+ok("log temp with cursor");
+
+# simple query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4999;
+END;
+});
+$node->wait_for_log(qr/LOG:  statement: SELECT a FROM foo ORDER BY a OFFSET 4999;.*statement: END;/s, $log_offset);
+ok("log temp with simple query");
+
+# Stop the node
+$node->stop('fast');
+done_testing();
-- 
2.43.0

#28Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#27)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 16/09/2025 21:13, Sami Imseih wrote:

They can be committed together if there is agreement that tests are worth it.

One argument for keeping the tests would be that they nicely bring
together the side-effect (logging) and these use-cases, whereas in the
code they're pretty distant, making the connection not obvious.

For example, they will come in handy when simplifying CreatePortal in a
separate patch as discussed.

Kind regards,

Mircea Cadariu

#29Sami Imseih
samimseih@gmail.com
In reply to: Mircea Cadariu (#28)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

One argument for keeping the tests would be that they nicely bring together the side-effect (logging) and these use-cases, whereas in the code they're pretty distant, making the connection not obvious.

Another argument is that we have no coverage on temp logging, which
is why this bug was discovered. There are likely plenty of tools
out there, for example pgbadger or manual log analysis, that
have probably misinterpreted temporary usage all this time,
because of the way the data was emitted.

--
Sami

#30Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#29)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Wed, Sep 17, 2025 at 10:52:31AM -0500, Sami Imseih wrote:

One argument for keeping the tests would be that they nicely bring together the side-effect (logging) and these use-cases, whereas in the code they're pretty distant, making the connection not obvious.

Another argument is that we have no coverage on temp logging, which
is why this bug was discovered. There are likely plenty of tools
out there, for example pgbadger or manual log analysis, that
have probably misinterpreted temporary usage all this time,
because of the way the data was emitted.

Perhaps this is a sign that there is no need to be really aggressive
with backpatching aanything, as well. At least that's my impression.
--
Michael

#31Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#27)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Tue, Sep 16, 2025 at 02:13:39PM -0500, Sami Imseih wrote:

Also, the tests should be checking that we are logging "temporary file: "
before the next statement is logged.

I split up the actual fix and the corrected tests into separate patches.
They can be committed together if there is agreement that tests are worth it.

I find the tests interesting to have, especially if we make these code
paths more complicated in terms of the statements we expect to log for
these logs when it comes to the temporary files cleaned up.

Now, if I apply patch v11-0002 that only adds the tests but not
v11-0001, the tests pass. It means that the tests as proposed do not
actually validate what 0001 changes. Shouldn't the tests with \bind
at least be able to detect the case of unnamed portals and that the
statements reports we are attaching to them become what we think is
the correct deal?
--
Michael

#32Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#22)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Sorry for the late reply.

On 8/29/25 20:27, Sami Imseih wrote:

This version needs another rebase, but I don't think this is a proper solution
yet. It's dropping the portal in an area I don't think we should be concerned
with,

You might be right, I don't know... my understanding of the code isn't
good enough.

and it's not covering some simple cases, like a bind/execute followed
by a simple query.

I don't understand this part, I think that my tests prove the contrary,
don't they?

#33Sami Imseih
samimseih@gmail.com
In reply to: Michael Paquier (#31)
2 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Now, if I apply patch v11-0002 that only adds the tests but not
v11-0001, the tests pass.

Ok. It looks like my regexp was wrong. v12-0002 fixes this by looking
for the correct STATEMENT: after the temp file logging.
I also realized that the initial tests we've been working with included:

```
+log_statement = all
+log_min_duration_statement = 0
```

which caused additional noise and did not isolate the temp logging,
and that could mislead the tests. So, I removed these settings.
So now, applied independently, the tests in 0002 will not pass.

I also went back to think about the concern by Tom early in the thread [0]/messages/by-id/23969.1745083695@sss.pgh.pa.us
that "The portal's query string is potentially shorter-lived than the portal."

I don't think this is a concern since the query string passed to the Portal
will outlive the portal, per this comment right before PortalDefineQuery:

```
/*
* We don't have to copy anything into the portal, because everything
* we are passing here is in MessageContext or the
* per_parsetree_context, and so will outlive the portal anyway.
*/
```

The "everything" also includes the query_text.

So, v12-0001 now sets debug_query_string before PortalDrop ( inside
drop_unnamed_portal). We will now with only log_temp_files set to "on",
see the "LOG: temporary file:" followed by the correctly blamed query
in the " STATEMENT: ".

[0]: /messages/by-id/23969.1745083695@sss.pgh.pa.us

--
Sami

Attachments:

v12-0001-Fix-temp-file-logging-blame-in-extended-query-pr.patchapplication/octet-stream; name=v12-0001-Fix-temp-file-logging-blame-in-extended-query-pr.patchDownload
From 41d252c82eebf7dc9c06637996df7dcdb90a5061 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:34:23 +0000
Subject: [PATCH v12 1/2] Fix temp file logging blame in extended query
 protocol
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

With the extended query protocol, temporary files created by unnamed
portals could be blamed on the wrong statement. Because temp file logging
happens when the portal is dropped, this patch ensures that unnamed portals
are dropped before resetting debug_query_string, so that temp files are
blamed on the correct statement.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/backend/tcop/postgres.c | 44 +++++++++++++++++++++++++++++++++++++
 1 file changed, 44 insertions(+)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index d356830f756..80fffd7aada 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,29 @@ 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))
+	{
+		/*
+		 * Set debug_query_string from the QueryDesc so that if logging occurs
+		 * during PortalDrop, messages are attributed to the query being run.
+		 */
+		if (portal->queryDesc)
+			debug_query_string = portal->queryDesc->sourceText;
+
+		PortalDrop(portal, false);
+	}
+
+	unnamed_portal = false;
+}
-- 
2.43.0

v12-0002-Add-tests-for-temp-file-logging.patchapplication/octet-stream; name=v12-0002-Add-tests-for-temp-file-logging.patchDownload
From 6209155e4bad2202b9202c44108d02e0a0bc17df Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:36:33 +0000
Subject: [PATCH v12 2/2] Add tests for temp file logging
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Commit 41d252c82eebf7d revealed a lack of test coverage for temp file
logging. This commit adds the missing tests to improve coverage and
reliability.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/test/modules/test_misc/meson.build        |  1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 89 +++++++++++++++++++
 2 files changed, 90 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

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..053f839410a
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,89 @@
+#
+# Verify that temp files are logged with the right statement.
+#
+# Copyright (c) 2021-2025, PostgreSQL Global Development Group
+#
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+    'postgresql.conf', qq(
+work_mem = 64kB
+log_temp_files = 0
+));
+$node->start;
+
+# Setup table and populate with data
+$node->safe_psql("postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+VACUUM ANALYZE foo;
+});
+
+# unnamed portal test
+my $log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+SELECT 1;
+END;
+});
+$node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with unnamed portal");
+
+# named portal test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 1;
+END;
+});
+$node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with named portal");
+
+# pipelined query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\sendpipeline
+SELECT 1;
+\\endpipeline
+});
+$node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with pipelined query");
+
+# cursor test
+$log_offset = -s $node->logfile;
+$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;
+END;
+});
+$node->wait_for_log(qr/CLOSE mycur;\n.*\ LOG:\s+temporary file:/s, $log_offset);
+ok("log temp with cursor");
+
+# simple query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4999;
+END;
+});
+$node->wait_for_log(qr/SELECT a FROM foo ORDER BY a OFFSET 4999;\n.*\ LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with simple query");
+
+# Stop the node
+$node->stop('fast');
+done_testing();
-- 
2.43.0

#34Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Sami Imseih (#33)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 9/18/25 18:06, Sami Imseih wrote:

I also realized that the initial tests we've been working with included:

```
+log_statement = all
+log_min_duration_statement = 0
```

Yes, you added these two in your v8, together with a useless
log_line_prefix.

which caused additional noise and did not isolate the temp logging,
and that could mislead the tests.

I agree.

#35Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#33)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Hi,

On 18/09/2025 18:06, Sami Imseih wrote:

The "everything" also includes the query_text.

This makes me wonder then if all it takes is just adding this to
PortalDrop (proposed earlier in the thread by Frédéric):

if (portal->queryDesc)
    debug_query_string = portal->queryDesc->sourceText;

I tried it out and the tests in v12-0002 pass.

Kind regards,

Mircea Cadariu

#36Sami Imseih
samimseih@gmail.com
In reply to: Mircea Cadariu (#35)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

The "everything" also includes the query_text.

This makes me wonder then if all it takes is just adding this to PortalDrop (proposed earlier in the thread by Frédéric):

One thing I did not like about that approach is that we will need to
save the current debug_query_string inside PortalDrop before
temporarily setting it to the one from the about to be dropped
portal, and then set it back to the saved one before exiting.
Otherwise, we might end up logging the wrong query in some cases
(although I could not find a test case that proves my worry).

With v12, drop_unnamed_portal sets the debug_query_string of the
portal, and we know right after drop_unnamed_portal is completed
the debug_query_string is set to the current query.

--
Sami

#37Sami Imseih
samimseih@gmail.com
In reply to: Sami Imseih (#36)
2 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

This makes me wonder then if all it takes is just adding this to PortalDrop (proposed earlier in the thread by Frédéric):

One thing I did not like about that approach is that we will need to
save the current debug_query_string inside PortalDrop before
temporarily setting it to the one from the about to be dropped
portal, and then set it back to the saved one before exiting.
Otherwise, we might end up logging the wrong query in some cases
(although I could not find a test case that proves my worry).

After thinking about this a bit more, I found the test that breaks
with v12. It is a bind statement in an implicit transaction. The
portal will get dropped by the end of the transaction and will not
reach drop_unnamed_portal. So, v13 takes Frederic's original idea,
saves the pointer of debug_query_string, and resets it at the end of
DropPortal. I also enhanced the test coverage.

Debugging also shows that the STATEMENT: log is formed while we are
in ExecutorEnd. We know that other extensions rely on
QueryDesc->sourceText in that hook (i.e., pg_stat_statements), so
this is another reason this approach appears safe, in addition to
what was mentioned here [0]/messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com about the MessageContext outliving the
portal.

[0]: /messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com

--
Sami

Attachments:

v13-0002-Add-tests-for-temp-file-logging.patchapplication/octet-stream; name=v13-0002-Add-tests-for-temp-file-logging.patchDownload
From 46d276b56f1ccbb317d5a08a8b01e048b33c0aca Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:36:33 +0000
Subject: [PATCH v13 2/2] Add tests for temp file logging
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Commit 41d252c82eebf7d revealed a lack of test coverage for temp file
logging. This commit adds the missing tests to improve coverage and
reliability.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/test/modules/test_misc/meson.build        |   1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 115 ++++++++++++++++++
 2 files changed, 116 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

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..3d1a25bcfa8
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,115 @@
+#
+# Verify that temporary file usage is logged with the expected statement text
+# for various query execution paths (portals, pipelines, cursors, prepared
+# statements, etc.).
+#
+# Copyright (c) 2021-2025, PostgreSQL Global Development Group
+#
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+    'postgresql.conf', qq(
+work_mem = 64kB
+log_temp_files = 0
+));
+$node->start;
+
+my $log_offset = -s $node->logfile;
+
+# Setup table and populate with data
+$node->safe_psql("postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+});
+
+# unnamed portal test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+SELECT 1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with unnamed portal");
+
+# bind with implicit transaction test
+$node->safe_psql("postgres", qq{
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with bind and implicit transaction");
+
+# named portal test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with named portal");
+
+# pipelined query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\sendpipeline
+SELECT 1;
+\\endpipeline
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with pipelined query");
+
+# parse and bind tests
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
+\\bind_named p1 4999 \\g
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1/s, $log_offset);
+ok("log temp with parse and bind");
+
+# simple query test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4999;
+END;
+});
+$log_offset = $node->wait_for_log(qr/SELECT a FROM foo ORDER BY a OFFSET 4999;\n.*\ LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with simple query");
+
+# cursor test
+$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;
+END;
+});
+$log_offset = $node->wait_for_log(qr/CLOSE mycur;\n.*\ LOG:\s+temporary file:/s, $log_offset);
+ok("log temp with cursor");
+
+# prepare/execute test
+$node->safe_psql("postgres", qq{
+BEGIN;
+PREPARE p1 AS SELECT a FROM foo ORDER BY a OFFSET 4999;
+EXECUTE p1;
+DEALLOCATE p1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file:/s, $log_offset);
+ok("prepare and execute cursor");
+
+# Stop the node
+$node->stop('fast');
+done_testing();
-- 
2.43.0

v13-0001-Fix-temp-file-logging-blame-in-extended-query.patchapplication/octet-stream; name=v13-0001-Fix-temp-file-logging-blame-in-extended-query.patchDownload
From 19fc3ce6185f9c74d0393ee1bfbd6fe8020131c7 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Fri, 19 Sep 2025 20:06:37 +0000
Subject: [PATCH v13 1/2] Fix temp file logging blame in extended query
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

With the extended query protocol, temporary files created by unnamed
portals could be blamed on the wrong statement. Because temp file logging
happens when the portal is dropped, this patch ensures that unnamed portals
are dropped before resetting debug_query_string, so that temp files are
blamed on the correct statement.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/backend/utils/mmgr/portalmem.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c
index 0be1c2b0fff..c18d44c3e6a 100644
--- a/src/backend/utils/mmgr/portalmem.c
+++ b/src/backend/utils/mmgr/portalmem.c
@@ -23,6 +23,7 @@
 #include "funcapi.h"
 #include "miscadmin.h"
 #include "storage/ipc.h"
+#include "tcop/tcopprot.h"
 #include "utils/builtins.h"
 #include "utils/memutils.h"
 #include "utils/snapmgr.h"
@@ -467,8 +468,19 @@ MarkPortalFailed(Portal portal)
 void
 PortalDrop(Portal portal, bool isTopCommit)
 {
+	const char *saved_debug_query_string = NULL;
+
 	Assert(PortalIsValid(portal));
 
+	/*
+	 * Save the current debug_query_string and temporarily set it to the
+	 * portal's query while dropping, so log messages are blamed on the
+	 * portal.
+	 */
+	saved_debug_query_string = debug_query_string;
+	if (portal->queryDesc)
+		debug_query_string = portal->queryDesc->sourceText;
+
 	/*
 	 * Don't allow dropping a pinned portal, it's still needed by whoever
 	 * pinned it.
@@ -594,6 +606,9 @@ PortalDrop(Portal portal, bool isTopCommit)
 	/* release subsidiary storage */
 	MemoryContextDelete(portal->portalContext);
 
+	/* reset the debug_query_string */
+	debug_query_string = saved_debug_query_string;
+
 	/* release portal struct (it's in TopPortalContext) */
 	pfree(portal);
 }
-- 
2.43.0

#38Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#37)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Fri, Sep 19, 2025 at 03:28:46PM -0500, Sami Imseih wrote:

After thinking about this a bit more, I found the test that breaks
with v12. It is a bind statement in an implicit transaction. The
portal will get dropped by the end of the transaction and will not
reach drop_unnamed_portal. So, v13 takes Frederic's original idea,
saves the pointer of debug_query_string, and resets it at the end of
DropPortal. I also enhanced the test coverage.

Debugging also shows that the STATEMENT: log is formed while we are
in ExecutorEnd. We know that other extensions rely on
QueryDesc->sourceText in that hook (i.e., pg_stat_statements), so
this is another reason this approach appears safe, in addition to
what was mentioned here [0] about the MessageContext outliving the
portal.

[0] /messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com

Hmm. We are running in circles here, based on the argument that the
drop of an unnamed portal happens when the next BIND command shows
up, and the fact that it is an old protocol artifact that we have been
leaving with for ages in the backend engine for efficiency.

I do agree about the point that it may be better to encourage drivers
to not use unnamed portals, but at the same time I don't recall
anybody complaining about the fact that a statement string should
absolutely match with the statement where a temporary file has been
created and should be linked to it.

Thinking about this problem in a twisted way, could there be an
argument in favor of the existing logic as it is? It is true that the
cleanup happens when the next bind query happens. So, in fact, one
could also say that it makes sense to reflect when a temp file is
cleaned up and what's the query being processed that does the cleanup.
In this case, it is not the query that created the temp file, but the
one that's been processed, and the portal drop is documented in
protocol.sgml as being part of the follow-up BIND. (I did use the
term "twisted" here.)

In short, I would be inclined to do nothing here, but I do see an
argument in favor of the tests, particularly to track the fact that
the unnamed portal drop happens in the next BIND query, and looking
for temp file getting dropped in the server logs is an interesting way
to validate that. Some of the proposals of this thread broke this
protocol item, so that seems at least important to track in the
long-term.
--
Michael

#39Sami Imseih
samimseih@gmail.com
In reply to: Michael Paquier (#38)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

After thinking about this a bit more, I found the test that breaks
with v12. It is a bind statement in an implicit transaction. The
portal will get dropped by the end of the transaction and will not
reach drop_unnamed_portal. So, v13 takes Frederic's original idea,
saves the pointer of debug_query_string, and resets it at the end of
DropPortal. I also enhanced the test coverage.

Debugging also shows that the STATEMENT: log is formed while we are
in ExecutorEnd. We know that other extensions rely on
QueryDesc->sourceText in that hook (i.e., pg_stat_statements), so
this is another reason this approach appears safe, in addition to
what was mentioned here [0] about the MessageContext outliving the
portal.

[0] /messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com

Hmm. We are running in circles here, based on the argument that the
drop of an unnamed portal happens when the next BIND command shows
up, and the fact that it is an old protocol artifact that we have been
leaving with for ages in the backend engine for efficiency.

Yes, and with the correct tests, we ultimately returned to the original idea:
temporarily switching the debug_query_string inside PortalDrop proved
to be the only viable solution. Although, this was also the approach that
Tom early-on was against due to the possibility of "The portal's query string
is potentially shorter-lived than the portal" [0]/messages/by-id/23969.1745083695@sss.pgh.pa.us, although the code
comments [1]/messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com
say otherwise. I have been able to find a test case that breaks due to
this concern.

I do agree about the point that it may be better to encourage drivers
to not use unnamed portals, but at the same time I don't recall
anybody complaining about the fact that a statement string should
absolutely match with the statement where a temporary file has been
created and should be linked to it.

Tools like pgbadger show the wrong information with the current
output. I am surprised with the lack of complaints.

Thinking about this problem in a twisted way, could there be an
argument in favor of the existing logic as it is? It is true that the
cleanup happens when the next bind query happens. So, in fact, one
could also say that it makes sense to reflect when a temp file is
cleaned up and what's the query being processed that does the cleanup.

One could possibly make this claim, based on the comment of what
the STATEMENT: log actually does.
```
/*
* If the user wants the query that generated this error logged, do it.
*/
if (check_log_of_query(edata))
{
log_line_prefix(&buf, edata);
appendStringInfoString(&buf, _("STATEMENT: "));
```
But, from a temporary file logging perspective, this is very confusing
for the user.

In short, I would be inclined to do nothing here,

Maybe we document this behavior? [2]https://www.postgresql.org/docs/current/runtime-config-logging.html#GUC-LOG-TEMP-FILES

but I do see an
argument in favor of the tests, particularly to track the fact that
the unnamed portal drop happens in the next BIND query, and looking

+1

[0]: /messages/by-id/23969.1745083695@sss.pgh.pa.us
[1]: /messages/by-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA@mail.gmail.com
[2]: https://www.postgresql.org/docs/current/runtime-config-logging.html#GUC-LOG-TEMP-FILES

--
Sami

#40Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#39)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Thu, Sep 25, 2025 at 09:05:15PM -0500, Sami Imseih wrote:

In short, I would be inclined to do nothing here,

Maybe we document this behavior? [2]

In the GUC description. Why not. The protocol piece with unnamed
portal cleanup is hard to notice by itself..
--
Michael

#41Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Michael Paquier (#38)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 9/26/25 03:20, Michael Paquier wrote:

Thinking about this problem in a twisted way, could there be an
argument in favor of the existing logic as it is? It is true that the
cleanup happens when the next bind query happens. So, in fact, one
could also say that it makes sense to reflect when a temp file is
cleaned up and what's the query being processed that does the cleanup.
In this case, it is not the query that created the temp file, but the
one that's been processed, and the portal drop is documented in
protocol.sgml as being part of the follow-up BIND. (I did use the
term "twisted" here.)

Well, that is indeed a rather twisted approach ;-)

How are we going to explain this to the user?

Is it really acceptable to have this in the log?

[...] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp525566.0",
size 2416640
[...] STATEMENT: SELECT 1

If we're unable to provide a proper fix, we should probably remove
completely the "STATEMENT" log line. We can use pg_stat_statements to
find the amount of temporary file written by a given query.

#42Guillaume Lelarge
guillaume.lelarge@dalibo.com
In reply to: Frédéric Yhuel (#41)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 26/09/2025 08:45, Frédéric Yhuel wrote:

On 9/26/25 03:20, Michael Paquier wrote:

Thinking about this problem in a twisted way, could there be an
argument in favor of the existing logic as it is?  It is true that the
cleanup happens when the next bind query happens.  So, in fact, one
could also say that it makes sense to reflect when a temp file is
cleaned up and what's the query being processed that does the cleanup.
In this case, it is not the query that created the temp file, but the
one that's been processed, and the portal drop is documented in
protocol.sgml as being part of the follow-up BIND.  (I did use the
term "twisted" here.)

Well, that is indeed a rather twisted approach ;-)

How are we going to explain this to the user?

Is it really acceptable to have this in the log?

[...] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp525566.0",
size 2416640
[...] STATEMENT:  SELECT 1

If we're unable to provide a proper fix, we should probably remove
completely the "STATEMENT" log line. We can use pg_stat_statements to
find the amount of temporary file written by a given query.

Yeah, I don't see how it could help the user if PostgreSQL logs the
wrong query. At the very least, it should be written in the manual that
the user can't trust the STATEMENT line with temporary files logging.
But I would rather see it log the right query.

--
Guillaume Lelarge
Consultant
https://dalibo.com

#43Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Guillaume Lelarge (#42)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Shall we just look at the latest v13 and determine if it is a solution
for showing the correct query we can stand behind, if it's not, explain
why not, and in that case, possibly even figure out what preliminary
refactoring is in order that would help us arrive at a solution in a
more direct way?

I'd find this useful from an educational perspective, and possibly
others as well which have taken the time to build a mental model of this
area with this occasion.

The patch is more self-contained and less invasive than previous
proposals, which makes potential reverts easier.

Maybe what's debatable is the temporary storage in
saved_debug_query_string and back. The tests pass without this part
indeed. IIUC the switch back happens "naturally" in PortalStart when the
updated source text gets set.

But okay, just to be on the safe side we can keep the temporary storage
and switch so that the "old" query is in the picture strictly as minimum
as necessary.

Kind regards,

Mircea Cadariu

#44Michael Paquier
michael@paquier.xyz
In reply to: Guillaume Lelarge (#42)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Fri, Sep 26, 2025 at 09:28:15AM +0200, Guillaume Lelarge wrote:

Yeah, I don't see how it could help the user if PostgreSQL logs the wrong
query. At the very least, it should be written in the manual that the user
can't trust the STATEMENT line with temporary files logging. But I would
rather see it log the right query.

The question would be if we can come up with a fix solid enough to be
able to detect the fact that we are dealing with one or more edge
cases, one edge case being an unnamed portal dropped at the beginning
of a bind from a different query, assuming that we don't change the
protocol documented.

What I'm afraid of is that this would be similar to the proposals in
the original patch (not really clean at it used a direct point to the
debug query string) or v13 (pstrdup of the debug string), which are
both localized changes, and these seem unsafe to do because we'd
expect the saved data to have the same durability as the portal it's
related to. I'm not sure that there is a sane thing to do except
dropping unnamed portals more aggressively, which may be OK still not
backpatchable.
--
Michael

#45Sami Imseih
samimseih@gmail.com
In reply to: Michael Paquier (#44)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

What I'm afraid of is that this would be similar to the proposals in
the original patch (not really clean at it used a direct point to the
debug query string) or v13 (pstrdup of the debug string), which are
both localized changes, and these seem unsafe to do because we'd
expect the saved data to have the same durability as the portal it's
related to.

v13 does not call pstrdup. It keeps a reference to debug_query_string,
reassigns it to the Portal's query string during PortalDrop, then
restores the original reference before return. Before PortalDrop exits,
the temp file is closed and the message is emitted. I relied on [0]https://github.com/postgres/postgres/blob/master/src/backend/tcop/postgres.c#L1224-L1234 and
debugging to check the safety of this approach. With that said, there
could be edge cases where this may not be true.

I'm not sure that there is a sane thing to do except
dropping unnamed portals more aggressively, which may be OK still not
backpatchable.

Yeah, I agree. This was in fact one of the ideas earlier. It is not clear to me
why we should wait until the next bind to drop the last unnamed portal.

[0]: https://github.com/postgres/postgres/blob/master/src/backend/tcop/postgres.c#L1224-L1234

--
Sami

#46Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#45)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Sat, Sep 27, 2025 at 12:44:23PM -0500, Sami Imseih wrote:

I'm not sure that there is a sane thing to do except
dropping unnamed portals more aggressively, which may be OK still not
backpatchable.

Yeah, I agree. This was in fact one of the ideas earlier. It is not clear to me
why we should wait until the next bind to drop the last unnamed portal.

[0] https://github.com/postgres/postgres/blob/master/src/backend/tcop/postgres.c#L1224-L1234

I cannot say for sure, but my bet goes to efficiency. Dropping an
unnamed portal at the next bind is an artifact from 2003, fe19e56c572f
if my grep gets it right. log_temp_files is a bit older than that,
with be8a4318815.

FWIW, I don't really object to being more aggressive with the unnamed
portal drop. What I am going to object to is hacks that attempt to
work around this protocol artifact by relying on things that may have
a different lifetime than the portal dropped. I think that the
correct step would be to get some coverage in, reversing the order of
the patches. Then, let's deal with how the reports are changed in the
tests by making the portal drop more aggressive in one location or
another, even if it costs one extra hash table lookup. We cannot
backpatch that, still as your TAP script is proving the coverage
is easier with all these new psql meta-commands able to do extended
protocol manipulations.
--
Michael

#47Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#46)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Tue, Sep 30, 2025 at 11:34:34AM +0900, Michael Paquier wrote:

I think that the first
correct step would be to get some coverage in, reversing the order of
the patches.

So, coming back to this thread. Could somebody realign the TAP tests
for HEAD so as we have some test coverage to track which temp file is
unlinked by which query when a portal is dropped?
--
Michael

#48Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Michael Paquier (#47)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Hi Michael,

On 09/10/2025 09:11, Michael Paquier wrote:

So, coming back to this thread. Could somebody realign the TAP tests
for HEAD so as we have some test coverage to track which temp file is
unlinked by which query when a portal is dropped?

Did you mean just the tests, without the fix? If so, please find the
updated tests only patch attached.

Kind regards,

Mircea Cadariu

Attachments:

v14-0001-Add-tests-for-temp-file-logging.patchtext/plain; charset=UTF-8; name=v14-0001-Add-tests-for-temp-file-logging.patchDownload
From 4b55965fc145d978287c8bd8b79681cf58d4ff24 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:36:33 +0000
Subject: [PATCH v14] Add tests for temp file logging
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Temporary file usage is sometimes attributed to the wrong query in the logs
output. One identified reason is that unnamed portal cleanup (and consequently
temp file logging) happens during the next BIND message, after
debug_query_string has already been updated to the new query.

This commit is a first step towards fixing this, adding tests to track
which query is displayed next to the temp file when the portal is dropped.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/test/modules/test_misc/meson.build        |   1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 115 ++++++++++++++++++
 2 files changed, 116 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

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..f5071ebf89
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,115 @@
+#
+# Verify that temporary file usage is logged with the expected statement text
+# for various query execution paths (portals, pipelines, cursors, prepared
+# statements, etc.).
+#
+# Copyright (c) 2021-2025, PostgreSQL Global Development Group
+#
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+    'postgresql.conf', qq(
+work_mem = 64kB
+log_temp_files = 0
+));
+$node->start;
+
+my $log_offset = -s $node->logfile;
+
+# Setup table and populate with data
+$node->safe_psql("postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+});
+
+# unnamed portal test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+SELECT 1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 1/s, $log_offset);
+ok("log temp with unnamed portal");
+
+# bind with implicit transaction test
+$node->safe_psql("postgres", qq{
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\g
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file:/s, $log_offset);
+ok("log temp with bind and implicit transaction");
+
+# named portal test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 1/s, $log_offset);
+ok("log temp with named portal");
+
+# pipelined query test
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4999 \\sendpipeline
+SELECT 1;
+\\endpipeline
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 1/s, $log_offset);
+ok("log temp with pipelined query");
+
+# parse and bind tests
+$log_offset = -s $node->logfile;
+$node->safe_psql("postgres", qq{
+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
+\\bind_named p1 4999 \\g
+});
+$log_offset = $node->wait_for_log(qr/LOG:\s+temporary file:/s, $log_offset);
+ok("log temp with parse and bind");
+
+# simple query test
+$node->safe_psql("postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4999;
+END;
+});
+$log_offset = $node->wait_for_log(qr/SELECT a FROM foo ORDER BY a OFFSET 4999;\n.*\ LOG:\s+temporary file: path/s, $log_offset);
+ok("log temp with simple query");
+
+# cursor test
+$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;
+END;
+});
+$log_offset = $node->wait_for_log(qr/CLOSE mycur;\n.*\ LOG:\s+temporary file:/s, $log_offset);
+ok("log temp with cursor");
+
+# prepare/execute test
+$node->safe_psql("postgres", qq{
+BEGIN;
+PREPARE p1 AS SELECT a FROM foo ORDER BY a OFFSET 4999;
+EXECUTE p1;
+DEALLOCATE p1;
+END;
+});
+$log_offset = $node->wait_for_log(qr/EXECUTE p1;\n.*\ LOG:\s+temporary file:/s, $log_offset);
+ok("prepare and execute cursor");
+
+# Stop the node
+$node->stop('fast');
+done_testing();
-- 
2.39.5 (Apple Git-154)

#49Michael Paquier
michael@paquier.xyz
In reply to: Mircea Cadariu (#48)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Thu, Oct 09, 2025 at 04:04:46PM +0100, Mircea Cadariu wrote:

Did you mean just the tests, without the fix? If so, please find the updated
tests only patch attached.

The CI has reported that this test returns incorrect results when
using debug_parallel_query = regress, which is the case of the freebsd
task. Forcing debug_parallel_query = off in the test is able to cool
things down.

I did not really get the use of wait_for_log(). The query sequences
are well-timed, hence a set of log_contains() should be enough with
a correct offset to point to a position in the logs.

Instead of SELECT 1 and always using 4999 in the OFFSET clause, let's
use more patterns, like queries with text values related to the
sequence run, or dedicated numbers. Such changes make debugging
easier.

It's a bit late here, and I am not completely done yet. Here is for
now what I have for the tests. I still need to check more its
stability with more runs, and also I need to do a second pass. The CI
looks stable here at least.
--
Michael

Attachments:

v14-0001-Add-tests-for-temp-file-logging.patchtext/x-diff; charset=iso-8859-1Download
From fdf8e391b8a23d70cf0748bd63682c0662c6c03e Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:36:33 +0000
Subject: [PATCH v14] Add tests for temp file logging
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Temporary file usage is sometimes attributed to the wrong query in the logs
output. One identified reason is that unnamed portal cleanup (and consequently
temp file logging) happens during the next BIND message, after
debug_query_string has already been updated to the new query.

This commit is a first step towards fixing this, adding tests to track
which query is displayed next to the temp file when the portal is dropped.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/test/modules/test_misc/meson.build        |   1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 135 ++++++++++++++++++
 2 files changed, 136 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build
index 6b1e730bf46d..f258bf1ccd94 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 000000000000..928d7dc36c20
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,135 @@
+# Copyright (c) 2025, PostgreSQL Global Development Group
+
+# Check how temporary file drops and statement queries are associated
+# in the server logs for various query sequences with the simple and
+# extended query protocols.
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+	'postgresql.conf', qq(
+work_mem = 64kB
+log_temp_files = 0
+debug_parallel_query = off
+));
+$node->start;
+
+# Setup table and populate with data
+$node->safe_psql(
+	"postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+});
+
+note "unnamed portal: temporary file dropped under second SELECT query";
+my $log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4990 \\g
+SELECT 'unnamed portal';
+END;
+});
+ok( $node->log_contains(
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'unnamed portal'/s,
+		$log_offset),
+	"unnamed portal");
+
+note "bind and implicit transaction: temporary file dropped";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4991 \\g
+});
+ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
+	"bind and implicit transaction");
+
+note "named portal: temporary file dropped under second SELECT query";
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 'named portal';
+END;
+});
+ok( $node->log_contains(
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'named portal'/s,
+		$log_offset),
+	"named portal");
+
+note "pipelined query: temporary file dropped under second SELECT query";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4992 \\sendpipeline
+SELECT 'pipelined query';
+\\endpipeline
+});
+ok( $node->log_contains(
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'pipelined query'/s,
+		$log_offset),
+	"pipelined query");
+
+note "parse and bind: temporary file dropped";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
+\\bind_named p1 4993 \\g
+});
+ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
+	"parse and bind");
+
+note "simple query: temporary file dropped under SELECT query";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4994;
+END;
+});
+ok( $node->log_contains(
+		qr/SELECT a FROM foo ORDER BY a OFFSET 4994;\n.*\ LOG:\s+temporary file: path/s,
+		$log_offset),
+	"simple query");
+
+note "cursor: temporary file dropped under CLOSE";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+DECLARE mycur CURSOR FOR SELECT a FROM foo ORDER BY a OFFSET 4995;
+FETCH 10 FROM mycur;
+SELECT 1;
+CLOSE mycur;
+END;
+});
+ok( $node->log_contains(
+		qr/CLOSE mycur;\n.*\ LOG:\s+temporary file:/s, $log_offset),
+	"cursor");
+
+note "prepare/execute: temporary file dropped under EXECUTE";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+PREPARE p1 AS SELECT a FROM foo ORDER BY a OFFSET 4996;
+EXECUTE p1;
+DEALLOCATE p1;
+END;
+});
+ok( $node->log_contains(
+		qr/EXECUTE p1;\n.*\ LOG:\s+temporary file:/s, $log_offset),
+	"prepare/execute");
+
+$node->stop('fast');
+done_testing();
-- 
2.51.0

#50Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#49)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Wed, Oct 15, 2025 at 05:58:37PM +0900, Michael Paquier wrote:

I did not really get the use of wait_for_log(). The query sequences
are well-timed, hence a set of log_contains() should be enough with
a correct offset to point to a position in the logs.

Just a point of detail here. v13 and v12 of the patch relied on
wait_for_log(), which returns the size of the log file, updating the
offset used in the follow-up tests. But failures would cause the test
to be stuck until a timeout kicks in to stop the test. That part was
annoying.

It's a bit late here, and I am not completely done yet. Here is for
now what I have for the tests. I still need to check more its
stability with more runs, and also I need to do a second pass. The CI
looks stable here at least.

Another thing I have added is a check for STATEMENT in the two tests
where we do not expected a statement to be logged. I have also done a
couple more runs in the CI and locally, without noticing any failures,
so applied the result. Now let's see if the buildfarm says something.
The first results are stable, I'll keep an eye on the whole.
--
Michael

#51Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#50)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Thu, Oct 16, 2025 at 10:18:39AM +0900, Michael Paquier wrote:

Another thing I have added is a check for STATEMENT in the two tests
where we do not expected a statement to be logged. I have also done a
couple more runs in the CI and locally, without noticing any failures,
so applied the result. Now let's see if the buildfarm says something.
The first results are stable, I'll keep an eye on the whole.

prion has just failed because it uses log_error_verbosity = verbose:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&amp;dt=2025-10-16%2001%3A23%3A06

Will address this one in a bit..
--
Michael

#52Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Michael Paquier (#51)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 16/10/2025 03:36, Michael Paquier wrote:

prion has just failed because it uses log_error_verbosity = verbose:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&amp;dt=2025-10-16%2001%3A23%3A06

Thanks for progressing this! In v15 attached, I adjusted the regex to
work with all settings mentioned in the thread so far.

How to check if there's any other setting like this to cover?

Kind regards,

Mircea Cadariu

Attachments:

v15-0001-Add-tests-for-temp-file-logging.patchtext/plain; charset=UTF-8; name=v15-0001-Add-tests-for-temp-file-logging.patchDownload
From 5099366cf05c881ee43f5e6f1bc80eba5938f5f5 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Thu, 18 Sep 2025 15:36:33 +0000
Subject: [PATCH v15] Add tests for temp file logging
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Temporary file usage is sometimes attributed to the wrong query in the logs
output. One identified reason is that unnamed portal cleanup (and consequently
temp file logging) happens during the next BIND message, after
debug_query_string has already been updated to the new query.

This commit is a first step towards fixing this, adding tests to track
which query is displayed next to the temp file when the portal is dropped.

Author: Sami Imseih <samimseih@gmail.com>
Author: Frédéric Yhuel <frederic.yhuel@dalibo.com>
Reviewed-by: Mircea Cadariu <cadariu.mircea@gmail.com>
Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com
---
 src/test/modules/test_misc/meson.build        |   1 +
 .../modules/test_misc/t/009_log_temp_files.pl | 135 ++++++++++++++++++
 2 files changed, 136 insertions(+)
 create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl

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..fe5a125852
--- /dev/null
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -0,0 +1,135 @@
+# Copyright (c) 2025, PostgreSQL Global Development Group
+
+# Check how temporary file drops and statement queries are associated
+# in the server logs for various query sequences with the simple and
+# extended query protocols.
+
+use strict;
+use warnings FATAL => 'all';
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize a new PostgreSQL test cluster
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+	'postgresql.conf', qq(
+work_mem = 64kB
+log_temp_files = 0
+debug_parallel_query = off
+));
+$node->start;
+
+# Setup table and populate with data
+$node->safe_psql(
+	"postgres", qq{
+CREATE UNLOGGED TABLE foo(a int);
+INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000);
+});
+
+note "unnamed portal: temporary file dropped under second SELECT query";
+my $log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4990 \\g
+SELECT 'unnamed portal';
+END;
+});
+ok( $node->log_contains(
+		qr/LOG:.*?temporary file:.*?(?:statement|STATEMENT):\s+SELECT 'unnamed portal'/s,
+		$log_offset),
+	"unnamed portal");
+
+note "bind and implicit transaction: temporary file dropped";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4991 \\g
+});
+ok($node->log_contains(qr/LOG:.*?temporary file:/s, $log_offset),
+	"bind and implicit transaction");
+
+note "named portal: temporary file dropped under second SELECT query";
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt
+\\bind_named stmt 4999 \\g
+SELECT 'named portal';
+END;
+});
+ok( $node->log_contains(
+		qr/LOG:.*?temporary file:.*?(?:statement|STATEMENT):\s+SELECT 'named portal'/s,
+		$log_offset),
+	"named portal");
+
+note "pipelined query: temporary file dropped under second SELECT query";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+\\startpipeline
+SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4992 \\sendpipeline
+SELECT 'pipelined query';
+\\endpipeline
+});
+ok( $node->log_contains(
+		qr/LOG:.*?temporary file:.*?(?:STATEMENT:\s+SELECT 'pipelined query'|execute <unnamed>: SELECT 'pipelined query')/s,
+		$log_offset),
+	"pipelined query");
+
+note "parse and bind: temporary file dropped";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
+\\bind_named p1 4993 \\g
+});
+ok($node->log_contains(qr/LOG:.*?temporary file:/s, $log_offset),
+	"parse and bind");
+
+note "simple query: temporary file dropped under SELECT query";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+SELECT a FROM foo ORDER BY a OFFSET 4994;
+END;
+});
+ok( $node->log_contains(
+		qr/SELECT a FROM foo ORDER BY a OFFSET 4994;.*?LOG:.*?temporary file: path/s,
+		$log_offset),
+	"simple query");
+
+note "cursor: temporary file dropped under CLOSE";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+DECLARE mycur CURSOR FOR SELECT a FROM foo ORDER BY a OFFSET 4995;
+FETCH 10 FROM mycur;
+SELECT 1;
+CLOSE mycur;
+END;
+});
+ok( $node->log_contains(
+		qr/CLOSE mycur;.*?LOG:.*?temporary file:/s, $log_offset),
+	"cursor");
+
+note "prepare/execute: temporary file dropped under EXECUTE";
+$log_offset = -s $node->logfile;
+$node->safe_psql(
+	"postgres", qq{
+BEGIN;
+PREPARE p1 AS SELECT a FROM foo ORDER BY a OFFSET 4996;
+EXECUTE p1;
+DEALLOCATE p1;
+END;
+});
+ok( $node->log_contains(
+		qr/EXECUTE p1;.*?LOG:.*?temporary file:/s, $log_offset),
+	"prepare/execute");
+
+$node->stop('fast');
+done_testing();
-- 
2.39.5 (Apple Git-154)

#53Sami Imseih
samimseih@gmail.com
In reply to: Mircea Cadariu (#52)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

prion has just failed because it uses log_error_verbosity = verbose:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&amp;dt=2025-10-16%2001%3A23%3A06

Thanks for progressing this! In v15 attached, I adjusted the regex to work with all settings mentioned in the thread so far.

How to check if there's any other setting like this to cover?

It looks like this was resolved with 02c171f, which overrides the
log_error_verbosity to 'default' in 009_log_temp_files.pl

https://buildfarm.postgresql.org/cgi-bin/show_history.pl?nm=prion&amp;br=master

--

Sami

#54Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#53)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Thu, Oct 16, 2025 at 04:04:41PM -0500, Sami Imseih wrote:

prion has just failed because it uses log_error_verbosity = verbose:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&amp;dt=2025-10-16%2001%3A23%3A06

Thanks for progressing this! In v15 attached, I adjusted the regex to work with all settings mentioned in the thread so far.

How to check if there's any other setting like this to cover?

It looks like this was resolved with 02c171f, which overrides the
log_error_verbosity to 'default' in 009_log_temp_files.pl

https://buildfarm.postgresql.org/cgi-bin/show_history.pl?nm=prion&amp;br=master

Yes, and the other members are not complaining as far as I can see, so
we should be clear in terms of the tests. Now, back to the main
issue..
--
Michael

#55Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Michael Paquier (#54)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 17/10/2025 00:23, Michael Paquier wrote:

Yes, and the other members are not complaining as far as I can see, so
we should be clear in terms of the tests. Now, back to the main
issue..

So far so good!

About the main issue, seems to me the consensus is that dropping unnamed
portals more aggressively is the way to go?

Kind regards,

Mircea Cadariu

#56Michael Paquier
michael@paquier.xyz
In reply to: Mircea Cadariu (#55)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Fri, Oct 24, 2025 at 12:34:56PM +0100, Mircea Cadariu wrote:

So far so good!

Yes, the buildfarm has not been complaining.

About the main issue, seems to me the consensus is that dropping unnamed
portals more aggressively is the way to go?

At the cost of one extra hash table lookup, that unlikely does not
matter for performance anyway. I guess so.

It's not something that can be backpatched. We need to make sure that
the documentation about an unnamed portal drop happening on a
follow-up BIND query is fixed. If somebody would like to send a
refresh patch, including for how the tests change, that would be
welcome here.
--
Michael

#57Sami Imseih
samimseih@gmail.com
In reply to: Michael Paquier (#56)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

About the main issue, seems to me the consensus is that dropping unnamed
portals more aggressively is the way to go?

At the cost of one extra hash table lookup, that unlikely does not
matter for performance anyway. I guess so.

AFAICT, we don’t need to introduce an extra hash lookup. What we
need to do is ensure that the unnamed portal was run to completion
inside exec_execute_message; if it was, we can drop it. Dropping
relies on the fact that we already have a valid pointer to the portal.
v16 is based on [0]/messages/by-id/CAA5RZ0vGPa=UjiNiS0gK1zHVhysSBPMSaGU5Qc=1PrVKJ6ODCw@mail.gmail.com, with updates to the documentation and tests.

Note that in the tests, I opted to keep SELECT 'pipelined query' and
SELECT 'named portal', since they provide another execution after
the temporary logging inside the transaction. However, we are no
longer looking for their statement text in the logfile.

I wanted to add test cases in which we require multiple fetches
from the same portal, but we don't have the ability to change
the fetch size (i.e. max_rows) in psql. So here is the test I ran
using jdbc, but it's not helpful, since JDBC created a named
portal :( so I just hacked the patch to exercise the code path
of dropping the unnamed portal during _execute_ with:

"
-                       if (portal->name[0] == '\0')
+                       if (portal->name[0] == 'C')
                                PortalDrop(portal, false);
                }
"

and the logging is

"""
2025-10-28 17:33:48.606 UTC [260207] LOG: duration: 0.107 ms execute
<unnamed>: BEGIN
2025-10-28 17:33:48.607 UTC [260207] LOG: duration: 0.816 ms parse
<unnamed>: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.607 UTC [260207] LOG: duration: 0.455 ms bind
<unnamed>/C_1: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.608 UTC [260207] LOG: duration: 1.307 ms execute
<unnamed>/C_1: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.619 UTC [260207] LOG: duration: 0.018 ms execute
fetch from <unnamed>/C_1: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.619 UTC [260207] LOG: duration: 0.005 ms execute
fetch from <unnamed>/C_1: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.619 UTC [260207] LOG: temporary file: path
"base/pgsql_tmp/pgsql_tmp260207.0", size 73728
2025-10-28 17:33:48.619 UTC [260207] STATEMENT: SELECT a FROM foo
ORDER BY a OFFSET 4990
2025-10-28 17:33:48.619 UTC [260207] LOG: duration: 0.125 ms execute
fetch from <unnamed>/C_1: SELECT a FROM foo ORDER BY a OFFSET 4990
2025-10-28 17:33:48.620 UTC [260207] LOG: duration: 0.020 ms parse S_2: COMMIT
"""

which looks correct to me as the temp file is logged at the last
execution. It will be good to probably increase the capability
of psql to perform such tests, but for now I thought this was
a good verification, maybe.

It's not something that can be backpatched.

I agree, as this is a change to the protocol.

[0]: /messages/by-id/CAA5RZ0vGPa=UjiNiS0gK1zHVhysSBPMSaGU5Qc=1PrVKJ6ODCw@mail.gmail.com

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

v16-0001-Drop-unnamed-portal-immediately-after-execution-.patchapplication/octet-stream; name=v16-0001-Drop-unnamed-portal-immediately-after-execution-.patchDownload
From b2e851c81e75b37ed4e59a76e5f10e53401c96a0 Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Tue, 28 Oct 2025 17:13:41 +0000
Subject: [PATCH v16 1/1] Drop unnamed portal immediately after execution to
 completion

Previously, unnamed portals were kept until the next Bind or the end of
the transaction. This could cause temporary files to persist longer than
expected and make logging not reflect the actual SQL responsible for
the temporary file.

This patch changes exec_execute_message() to drop unnamed portals
immediately after execution to completion, ensuring temporary files are
removed promptly and statement logging correctly reflects the SQL that
created the temporary file.

The documentation is updated to accurately describe the lifetime of
unnamed portals, and test cases are updated to verify temporary file
removal and proper statement logging after unnamed portal execution.

Discussion: https://www.postgresql.org/message-id/CAA5RZ0tTrTUoEr3kDXCuKsvqYGq8OOHiBwoD-dyJocq95uEOTQ%40mail.gmail.com
---
 doc/src/sgml/protocol.sgml                         |  4 ++--
 src/backend/tcop/postgres.c                        |  7 +++++++
 src/test/modules/test_misc/t/009_log_temp_files.pl | 10 +++++-----
 3 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/doc/src/sgml/protocol.sgml b/doc/src/sgml/protocol.sgml
index 9d755232873..d1b9af11b07 100644
--- a/doc/src/sgml/protocol.sgml
+++ b/doc/src/sgml/protocol.sgml
@@ -1006,8 +1006,8 @@ SELCT 1/0;<!-- this typo is intentional -->
    <para>
     If successfully created, a named portal object lasts till the end of the
     current transaction, unless explicitly destroyed.  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.  (Note
+    destroyed at the end of the transaction, or as soon as the statement
+    specifying the unnamed portal as destination is processed to completion.  (Note
     that a simple Query message also destroys the unnamed portal.)  Named
     portals must be explicitly closed before they can be redefined by another
     Bind message, but this is not required for the unnamed portal.
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 7dd75a490aa..9a5534f8d13 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2327,6 +2327,13 @@ exec_execute_message(const char *portal_name, long max_rows)
 			 * message.  The next protocol message will start a fresh timeout.
 			 */
 			disable_statement_timeout();
+
+			/*
+			 * We completed fetching from an unnamed portal, we don't need it
+			 * beyond this point.
+			 */
+			if (portal->name[0] == '\0')
+				PortalDrop(portal, false);
 		}
 
 		/* Send appropriate CommandComplete to client */
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
index 462a949e411..383d9971fe2 100644
--- a/src/test/modules/test_misc/t/009_log_temp_files.pl
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -39,7 +39,7 @@ SELECT 'unnamed portal';
 END;
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'unnamed portal'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"unnamed portal");
 
@@ -51,7 +51,7 @@ SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4991 \\g
 });
 ok( $node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
 	"bind and implicit transaction, temporary file removed");
-ok( !$node->log_contains(qr/STATEMENT:/s, $log_offset),
+ok( $node->log_contains(qr/STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset),
 	"bind and implicit transaction, no statement logged");
 
 note "named portal: temporary file dropped under second SELECT query";
@@ -64,7 +64,7 @@ SELECT 'named portal';
 END;
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'named portal'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"named portal");
 
@@ -78,7 +78,7 @@ SELECT 'pipelined query';
 \\endpipeline
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'pipelined query'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"pipelined query");
 
@@ -91,7 +91,7 @@ SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
 });
 ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
 	"parse and bind, temporary file removed");
-ok(!$node->log_contains(qr/STATEMENT:/s, $log_offset),
+ok($node->log_contains(qr/STATEMENT:\s+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1/s, $log_offset),
 	"bind and bind, no statement logged");
 
 note "simple query: temporary file dropped under SELECT query";
-- 
2.43.0

#58Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#57)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

Hi,

On 28/10/2025 17:37, Sami Imseih wrote:

v16 is based on [0], with updates to the documentation and tests.

Thanks for the updated patch!

+ok( $node->log_contains(qr/STATEMENT:\s+SELECT a FROM foo ORDER BY a
OFFSET \$1/s, $log_offset),
     "bind and implicit transaction, no statement logged");

Should it actually be "statement correctly logged" instead of "no
statement logged"?

Kind regards,

Mircea Cadariu

#59Sami Imseih
samimseih@gmail.com
In reply to: Mircea Cadariu (#58)
1 attachment(s)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

v16 is based on [0], with updates to the documentation and tests.

Thanks for the updated patch!

+ok( $node->log_contains(qr/STATEMENT:\s+SELECT a FROM foo ORDER BY a
OFFSET \$1/s, $log_offset),
"bind and implicit transaction, no statement logged");

Should it actually be "statement correctly logged" instead of "no
statement logged"?

oops, you're right.

We can actually remove "temporary file removed"
and "no statement logged" since we expect the
logging to blame the correct query in all these cases.

See v17

--
Sami Imseih
Amazon Web Services (AWS)

Attachments:

v17-0001-Drop-unnamed-portal-immediately-after-execution-.patchapplication/octet-stream; name=v17-0001-Drop-unnamed-portal-immediately-after-execution-.patchDownload
From c94588fa1de8a75b2cdea78f548b82e3c55f569f Mon Sep 17 00:00:00 2001
From: Ubuntu <ubuntu@ip-172-31-46-230.ec2.internal>
Date: Tue, 28 Oct 2025 17:13:41 +0000
Subject: [PATCH v17 1/1] Drop unnamed portal immediately after execution to
 completion

Previously, unnamed portals were kept until the next Bind or the end of
the transaction. This could cause temporary files to persist longer than
expected and make logging not reflect the actual SQL responsible for
the temporary file.

This patch changes exec_execute_message() to drop unnamed portals
immediately after execution to completion, ensuring temporary files are
removed promptly and statement logging correctly reflects the SQL that
created the temporary file.

The documentation is updated to accurately describe the lifetime of
unnamed portals, and test cases are updated to verify temporary file
removal and proper statement logging after unnamed portal execution.

Discussion: https://www.postgresql.org/message-id/CAA5RZ0tTrTUoEr3kDXCuKsvqYGq8OOHiBwoD-dyJocq95uEOTQ%40mail.gmail.com
---
 doc/src/sgml/protocol.sgml                     |  4 ++--
 src/backend/tcop/postgres.c                    |  7 +++++++
 .../modules/test_misc/t/009_log_temp_files.pl  | 18 +++++++-----------
 3 files changed, 16 insertions(+), 13 deletions(-)

diff --git a/doc/src/sgml/protocol.sgml b/doc/src/sgml/protocol.sgml
index 9d755232873..d1b9af11b07 100644
--- a/doc/src/sgml/protocol.sgml
+++ b/doc/src/sgml/protocol.sgml
@@ -1006,8 +1006,8 @@ SELCT 1/0;<!-- this typo is intentional -->
    <para>
     If successfully created, a named portal object lasts till the end of the
     current transaction, unless explicitly destroyed.  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.  (Note
+    destroyed at the end of the transaction, or as soon as the statement
+    specifying the unnamed portal as destination is processed to completion.  (Note
     that a simple Query message also destroys the unnamed portal.)  Named
     portals must be explicitly closed before they can be redefined by another
     Bind message, but this is not required for the unnamed portal.
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 7dd75a490aa..9a5534f8d13 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2327,6 +2327,13 @@ exec_execute_message(const char *portal_name, long max_rows)
 			 * message.  The next protocol message will start a fresh timeout.
 			 */
 			disable_statement_timeout();
+
+			/*
+			 * We completed fetching from an unnamed portal, we don't need it
+			 * beyond this point.
+			 */
+			if (portal->name[0] == '\0')
+				PortalDrop(portal, false);
 		}
 
 		/* Send appropriate CommandComplete to client */
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
index 462a949e411..46d0c7789ca 100644
--- a/src/test/modules/test_misc/t/009_log_temp_files.pl
+++ b/src/test/modules/test_misc/t/009_log_temp_files.pl
@@ -39,7 +39,7 @@ SELECT 'unnamed portal';
 END;
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'unnamed portal'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"unnamed portal");
 
@@ -49,10 +49,8 @@ $node->safe_psql(
 	"postgres", qq{
 SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4991 \\g
 });
-ok( $node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
-	"bind and implicit transaction, temporary file removed");
-ok( !$node->log_contains(qr/STATEMENT:/s, $log_offset),
-	"bind and implicit transaction, no statement logged");
+ok( $node->log_contains(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s, $log_offset),
+	"bind and implicit transaction");
 
 note "named portal: temporary file dropped under second SELECT query";
 $node->safe_psql(
@@ -64,7 +62,7 @@ SELECT 'named portal';
 END;
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'named portal'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"named portal");
 
@@ -78,7 +76,7 @@ SELECT 'pipelined query';
 \\endpipeline
 });
 ok( $node->log_contains(
-		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'pipelined query'/s,
+		qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a FROM foo ORDER BY a OFFSET \$1/s,
 		$log_offset),
 	"pipelined query");
 
@@ -89,10 +87,8 @@ $node->safe_psql(
 SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1
 \\bind_named p1 4993 \\g
 });
-ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset),
-	"parse and bind, temporary file removed");
-ok(!$node->log_contains(qr/STATEMENT:/s, $log_offset),
-	"bind and bind, no statement logged");
+ok($node->log_contains(qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT a, a, a FROM foo ORDER BY a OFFSET \$1/s, $log_offset),
+	"parse and bind");
 
 note "simple query: temporary file dropped under SELECT query";
 $log_offset = -s $node->logfile;
-- 
2.43.0

#60Mircea Cadariu
cadariu.mircea@gmail.com
In reply to: Sami Imseih (#59)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 29/10/2025 21:58, Sami Imseih wrote:

We can actually remove "temporary file removed"
and "no statement logged" since we expect the
logging to blame the correct query in all these cases.

Right, even better! v17 LGTM.

#61Michael Paquier
michael@paquier.xyz
In reply to: Sami Imseih (#59)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On Wed, Oct 29, 2025 at 04:58:22PM -0500, Sami Imseih wrote:

We can actually remove "temporary file removed"
and "no statement logged" since we expect the
logging to blame the correct query in all these cases.

While looking at the surroundings, I have noticed one comment on top
of the call of CreatePortal() in exec_simple_query() where an unnamed
portal is created, telling about a portal drop, but this still applies
to a succession of normal queries with for example rollbacks quickly
complaining (behavior documented). The same could still be said for
exec_bind_message() for CreatePortal() with an unnamed portal, still I
agree with the change in the docs that the completion of an unnamed
portal is more relevant to mention. So the doc change should be OK.

Some of the comments in the test were not correctly updated, I have
fixed these.

After looking again at the thread, I have decided to credit all three
of you as authors of this patch. Frederic has spent what I guess is a
lot of time on analyzing this, and then both Sami and Mircea have
followed up. This way, nobody should be jealous.

Then done on HEAD. If this proves to be a problem and that we have to
revert 1fd981f05369 for v19, at least we'll have the tests moving
forward. Anyway, let's have this change brew for now.
--
Michael

#62Frédéric Yhuel
frederic.yhuel@dalibo.com
In reply to: Michael Paquier (#61)
Re: [BUG] temporary file usage report with extended protocol and unnamed portals

On 11/5/25 6:44 AM, Michael Paquier wrote:

After looking again at the thread, I have decided to credit all three
of you as authors of this patch. Frederic has spent what I guess is a
lot of time on analyzing this, and then both Sami and Mircea have
followed up. This way, nobody should be jealous.

Then done on HEAD. If this proves to be a problem and that we have to
revert 1fd981f05369 for v19, at least we'll have the tests moving
forward. Anyway, let's have this change brew for now.

Thank you Micheal 🙂👍🏼