From fdf8e391b8a23d70cf0748bd63682c0662c6c03e Mon Sep 17 00:00:00 2001 From: Ubuntu 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 Author: Frédéric Yhuel Reviewed-by: Mircea Cadariu Discussion: https://www.postgresql.org/message-id/flat/3d07ee43-8855-42db-97e0-bad5db82d972@dalibo.com --- 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