Re: [BUG] temporary file usage report with extended protocol and unnamed portals - Mailing list pgsql-hackers

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