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
From fdf8e391b8a23d70cf0748bd63682c0662c6c03e Mon Sep 17 00:00:00 2001 From: Ubuntu <[email protected]> Date: Thu, 18 Sep 2025 15:36:33 +0000 Subject: [PATCH v14] Add tests for temp file logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Temporary file usage is sometimes attributed to the wrong query in the logs output. One identified reason is that unnamed portal cleanup (and consequently temp file logging) happens during the next BIND message, after debug_query_string has already been updated to the new query. This commit is a first step towards fixing this, adding tests to track which query is displayed next to the temp file when the portal is dropped. Author: Sami Imseih <[email protected]> Author: Frédéric Yhuel <[email protected]> Reviewed-by: Mircea Cadariu <[email protected]> Discussion: https://www.postgresql.org/message-id/flat/[email protected] --- src/test/modules/test_misc/meson.build | 1 + .../modules/test_misc/t/009_log_temp_files.pl | 135 ++++++++++++++++++ 2 files changed, 136 insertions(+) create mode 100644 src/test/modules/test_misc/t/009_log_temp_files.pl diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 6b1e730bf46d..f258bf1ccd94 100644 --- a/src/test/modules/test_misc/meson.build +++ b/src/test/modules/test_misc/meson.build @@ -17,6 +17,7 @@ tests += { 't/006_signal_autovacuum.pl', 't/007_catcache_inval.pl', 't/008_replslot_single_user.pl', + 't/009_log_temp_files.pl', ], }, } diff --git a/src/test/modules/test_misc/t/009_log_temp_files.pl b/src/test/modules/test_misc/t/009_log_temp_files.pl new file mode 100644 index 000000000000..928d7dc36c20 --- /dev/null +++ b/src/test/modules/test_misc/t/009_log_temp_files.pl @@ -0,0 +1,135 @@ +# Copyright (c) 2025, PostgreSQL Global Development Group + +# Check how temporary file drops and statement queries are associated +# in the server logs for various query sequences with the simple and +# extended query protocols. + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +# Initialize a new PostgreSQL test cluster +my $node = PostgreSQL::Test::Cluster->new('primary'); +$node->init(); +$node->append_conf( + 'postgresql.conf', qq( +work_mem = 64kB +log_temp_files = 0 +debug_parallel_query = off +)); +$node->start; + +# Setup table and populate with data +$node->safe_psql( + "postgres", qq{ +CREATE UNLOGGED TABLE foo(a int); +INSERT INTO foo(a) SELECT * FROM generate_series(1, 5000); +}); + +note "unnamed portal: temporary file dropped under second SELECT query"; +my $log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +BEGIN; +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4990 \\g +SELECT 'unnamed portal'; +END; +}); +ok( $node->log_contains( + qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'unnamed portal'/s, + $log_offset), + "unnamed portal"); + +note "bind and implicit transaction: temporary file dropped"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4991 \\g +}); +ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset), + "bind and implicit transaction"); + +note "named portal: temporary file dropped under second SELECT query"; +$node->safe_psql( + "postgres", qq{ +BEGIN; +SELECT a FROM foo ORDER BY a OFFSET \$1 \\parse stmt +\\bind_named stmt 4999 \\g +SELECT 'named portal'; +END; +}); +ok( $node->log_contains( + qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'named portal'/s, + $log_offset), + "named portal"); + +note "pipelined query: temporary file dropped under second SELECT query"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +\\startpipeline +SELECT a FROM foo ORDER BY a OFFSET \$1 \\bind 4992 \\sendpipeline +SELECT 'pipelined query'; +\\endpipeline +}); +ok( $node->log_contains( + qr/LOG:\s+temporary file: path.*\n.*\ STATEMENT:\s+SELECT 'pipelined query'/s, + $log_offset), + "pipelined query"); + +note "parse and bind: temporary file dropped"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +SELECT a, a, a FROM foo ORDER BY a OFFSET \$1 \\parse p1 +\\bind_named p1 4993 \\g +}); +ok($node->log_contains(qr/LOG:\s+temporary file:/s, $log_offset), + "parse and bind"); + +note "simple query: temporary file dropped under SELECT query"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +BEGIN; +SELECT a FROM foo ORDER BY a OFFSET 4994; +END; +}); +ok( $node->log_contains( + qr/SELECT a FROM foo ORDER BY a OFFSET 4994;\n.*\ LOG:\s+temporary file: path/s, + $log_offset), + "simple query"); + +note "cursor: temporary file dropped under CLOSE"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +BEGIN; +DECLARE mycur CURSOR FOR SELECT a FROM foo ORDER BY a OFFSET 4995; +FETCH 10 FROM mycur; +SELECT 1; +CLOSE mycur; +END; +}); +ok( $node->log_contains( + qr/CLOSE mycur;\n.*\ LOG:\s+temporary file:/s, $log_offset), + "cursor"); + +note "prepare/execute: temporary file dropped under EXECUTE"; +$log_offset = -s $node->logfile; +$node->safe_psql( + "postgres", qq{ +BEGIN; +PREPARE p1 AS SELECT a FROM foo ORDER BY a OFFSET 4996; +EXECUTE p1; +DEALLOCATE p1; +END; +}); +ok( $node->log_contains( + qr/EXECUTE p1;\n.*\ LOG:\s+temporary file:/s, $log_offset), + "prepare/execute"); + +$node->stop('fast'); +done_testing(); -- 2.51.0
signature.asc
Description: PGP signature
