Location via proxy:   [ UP ]  
[Report a bug]   [Manage cookies]                
Skip to content

Commit 550bc0a

Browse files
committed
Refactor the TAP test of auto_explain
Previously, the tests were structured so as all the queries whose plans are checked run first, followed by pattern checks using the full set of server logs. This can be problematic when extending the tests, as this increases query plan overlaps, where two tests finish by having similar plan outputs potentially invalidating the tests wanted. The tests are refactored so as log content matches are checked in isolation of each query run, by grabbing the position of the server logs before running each query whose plan is generated in the logs. This avoids issues when extending the tests, something that would become a larger problem with a follow-up patch that adds a new GUC in auto_explain to control the size of the each parameter logged. Author: Dagfinn Ilmari Mannsåker Discussion: https://postgr.es/m/87ee09mohb.fsf@wibble.ilmari.org
1 parent 258f48f commit 550bc0a

File tree

1 file changed

+74
-16
lines changed

1 file changed

+74
-16
lines changed

contrib/auto_explain/t/001_auto_explain.pl

+74-16
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,42 @@
88
use PostgreSQL::Test::Utils;
99
use Test::More;
1010

11+
# Runs the specified query and returns the emitted server log.
12+
# If any parameters are specified, these are set in postgresql.conf,
13+
# and reset after the query is run.
14+
sub query_log
15+
{
16+
my ($node, $sql, $params) = @_;
17+
$params ||= {};
18+
19+
if (keys %$params)
20+
{
21+
for my $key (keys %$params)
22+
{
23+
$node->append_conf('postgresql.conf', "$key = $params->{$key}\n");
24+
}
25+
$node->reload;
26+
}
27+
28+
my $log = $node->logfile();
29+
my $offset = -s $log;
30+
31+
$node->safe_psql("postgres", $sql);
32+
33+
my $log_contents = slurp_file($log, $offset);
34+
35+
if (keys %$params)
36+
{
37+
for my $key (keys %$params)
38+
{
39+
$node->adjust_conf('postgresql.conf', $key, undef);
40+
}
41+
$node->reload;
42+
}
43+
44+
return $log_contents;
45+
}
46+
1147
my $node = PostgreSQL::Test::Cluster->new('main');
1248
$node->init;
1349
$node->append_conf('postgresql.conf',
@@ -16,39 +52,61 @@
1652
$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
1753
$node->start;
1854

19-
# run a couple of queries
20-
$node->safe_psql("postgres", "SELECT * FROM pg_class;");
21-
$node->safe_psql("postgres",
22-
"SELECT * FROM pg_proc WHERE proname = 'int4pl';");
23-
24-
# emit some json too
25-
$node->append_conf('postgresql.conf', "auto_explain.log_format = json");
26-
$node->reload;
27-
$node->safe_psql("postgres", "SELECT * FROM pg_proc;");
28-
$node->safe_psql("postgres",
29-
"SELECT * FROM pg_class WHERE relname = 'pg_class';");
30-
31-
$node->stop('fast');
55+
# Simple query.
56+
my $log_contents = query_log($node, "SELECT * FROM pg_class;");
3257

33-
my $log = $node->logfile();
34-
35-
my $log_contents = slurp_file($log);
58+
like(
59+
$log_contents,
60+
qr/Query Text: SELECT \* FROM pg_class;/,
61+
"query text logged, text mode");
3662

3763
like(
3864
$log_contents,
3965
qr/Seq Scan on pg_class/,
4066
"sequential scan logged, text mode");
4167

68+
# Prepared query.
69+
$log_contents = query_log($node,
70+
q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');}
71+
);
72+
73+
like(
74+
$log_contents,
75+
qr/Query Text: PREPARE get_proc\(name\) AS SELECT \* FROM pg_proc WHERE proname = \$1;/,
76+
"prepared query text logged, text mode");
77+
4278
like(
4379
$log_contents,
4480
qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
4581
"index scan logged, text mode");
4682

83+
# JSON format.
84+
$log_contents = query_log(
85+
$node,
86+
"SELECT * FROM pg_proc;",
87+
{ "auto_explain.log_format" => "json" });
88+
89+
like(
90+
$log_contents,
91+
qr/"Query Text": "SELECT \* FROM pg_proc;"/,
92+
"query text logged, json mode");
93+
4794
like(
4895
$log_contents,
4996
qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_proc"/s,
5097
"sequential scan logged, json mode");
5198

99+
# Prepared query in JSON format.
100+
$log_contents = query_log(
101+
$node,
102+
q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
103+
{ "auto_explain.log_format" => "json" });
104+
105+
like(
106+
$log_contents,
107+
qr/"Query Text": "PREPARE get_class\(name\) AS SELECT \* FROM pg_class WHERE relname = \$1;"/,
108+
"prepared query text logged, json mode");
109+
52110
like(
53111
$log_contents,
54112
qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,

0 commit comments

Comments
 (0)