Обсуждение: [BUG] temporary file usage report with extended protocol and unnamed portals

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();

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

> [...] 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)

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)

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

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

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

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

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?

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

> 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]

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] https://www.postgresql.org/message-id/CAA5RZ0ssqRTz_9T0Gy74SiTViiX3V0rSFxc4N_4GNcbEBK9wow%40mail.gmail.com

--
Sami Imseih
Amazon Web Services (AWS)

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

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?

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.

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

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

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)

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

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

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.

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

Hi,

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

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

Hi,

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

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

> 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

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

> 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

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

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

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?

> 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]
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] https://www.postgresql.org/message-id/23969.1745083695%40sss.pgh.pa.us

--
Sami

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.

Hi,

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

> 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

>> 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] about the MessageContext outliving the
portal.

[0] https://www.postgresql.org/message-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA%40mail.gmail.com

--
Sami

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] https://www.postgresql.org/message-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA%40mail.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

> > 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] https://www.postgresql.org/message-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA%40mail.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], although the code
comments [1]
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]

> 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] https://www.postgresql.org/message-id/23969.1745083695%40sss.pgh.pa.us
[1] https://www.postgresql.org/message-id/CAA5RZ0vB-h2pFimPSi72ObWfpRwKR5kaN9XWW17TOkLntC9svA%40mail.gmail.com
[2] https://www.postgresql.org/docs/current/runtime-config-logging.html#GUC-LOG-TEMP-FILES

--
Sami

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

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.

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

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

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

> 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] 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

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