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

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