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

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

> but it should be:

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

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

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

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

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

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

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

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

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

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

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

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

--
Sami Imseih
Amazon Web Services (AWS)