Horton

Thread

Commits

  1. Drop unnamed portal immediately after execution to completion

  2. Override log_error_verbosity to "default" in test 009_log_temp_files

  3. Add tests for logging of temporary file removal and statement

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

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-18T08:49:58Z

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

  2. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-18T13:04:34Z

    
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

  3. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-18T18:43:35Z

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

  4. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-19T13:31:20Z

    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)

  5. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Tom Lane <tgl@sss.pgh.pa.us> — 2025-04-19T17:28:15Z

    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

  6. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-19T22:42:53Z

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

  7. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Guillaume Lelarge <guillaume.lelarge@dalibo.com> — 2025-04-20T07:37:27Z

    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

  8. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-21T05:46:50Z

    
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

  9. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-21T11:01:08Z

    
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?

  10. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-22T10:43:10Z

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

  11. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-22T17:37:33Z

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

  12. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-22T18:00:15Z

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

  13. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-23T07:41:58Z

    
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?

  14. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-23T09:27:05Z

    
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.

  15. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-23T16:13:17Z

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

  16. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-04-24T08:46:39Z

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

  17. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-25T22:31:13Z

    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)

  18. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-04-26T18:57:27Z

    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

  19. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-06-18T08:30:57Z

    
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

  20. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-08-21T12:02:40Z

    
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

  21. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-08-28T12:23:17Z

    
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.

  22. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-08-29T18:27:03Z

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

  23. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-09-08T16:34:00Z

    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

  24. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-11T15:28:50Z

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

  25. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-09-12T14:04:35Z

    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

  26. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-16T06:22:55Z

    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

  27. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-16T19:13:39Z

    > 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

  28. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-09-17T13:35:53Z

    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

  29. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-17T15:52:31Z

    > 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

  30. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-18T06:53:47Z

    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

  31. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-18T07:06:17Z

    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

  32. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-09-18T09:52:12Z

    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?

  33. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-18T16:06:31Z

    > 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

  34. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-09-19T07:06:49Z

    
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.

  35. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-09-19T10:26:46Z

    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

  36. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-19T12:50:09Z

    > 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

  37. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-19T20:28:46Z

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

  38. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-26T01:20:19Z

    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

  39. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-26T02:05:15Z

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

  40. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-26T02:28:48Z

    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

  41. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-09-26T06:45:25Z

    
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.

  42. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Guillaume Lelarge <guillaume.lelarge@dalibo.com> — 2025-09-26T07:28:15Z

    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

  43. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-09-26T08:55:34Z

    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

  44. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-26T11:33:02Z

    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

  45. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-09-27T17:44:23Z

    > 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

  46. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-09-30T02:34:34Z

    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

  47. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-09T08:11:30Z

    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

  48. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-10-09T15:04:46Z

    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

  49. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-15T08:58:37Z

    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

  50. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-16T01:18:39Z

    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

  51. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-16T02:36:36Z

    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&dt=2025-10-16%2001%3A23%3A06

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

  52. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-10-16T09:27:25Z

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

  53. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-10-16T21:04:41Z

    > prion has just failed because it uses log_error_verbosity = verbose:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=prion&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&br=master

--

Sami

  54. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-16T23:23:48Z

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

  55. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-10-24T11:34:56Z

    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

  56. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-10-27T23:30:51Z

    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

  57. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-10-28T17:37:10Z

    > > 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], 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] https://www.postgresql.org/message-id/CAA5RZ0vGPa%3DUjiNiS0gK1zHVhysSBPMSaGU5Qc%3D1PrVKJ6ODCw%40mail.gmail.com

--
Sami Imseih
Amazon Web Services (AWS)

  58. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-10-29T14:11:34Z

    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

  59. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Sami Imseih <samimseih@gmail.com> — 2025-10-29T21:58:22Z

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

  60. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Mircea Cadariu <cadariu.mircea@gmail.com> — 2025-10-30T11:46:00Z

    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.

  61. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Michael Paquier <michael@paquier.xyz> — 2025-11-05T05:44:39Z

    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

  62. Re: [BUG] temporary file usage report with extended protocol and unnamed portals

    Frédéric Yhuel <frederic.yhuel@dalibo.com> — 2025-11-07T08:06:46Z

    
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 🙂👍🏼