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/[email protected]

diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 82e4d9d15cdef06a4e1d8b2a6adea16126e7438e..1523ac2d46e2bc68efe3d350147866886b94b012 100644 (file)
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -8,6 +8,42 @@ use PostgreSQL::Test::Cluster;
 use PostgreSQL::Test::Utils;
 use Test::More;
 
+# Runs the specified query and returns the emitted server log.
+# If any parameters are specified, these are set in postgresql.conf,
+# and reset after the query is run.
+sub query_log
+{
+   my ($node, $sql, $params) = @_;
+   $params ||= {};
+
+   if (keys %$params)
+   {
+       for my $key (keys %$params)
+       {
+           $node->append_conf('postgresql.conf', "$key = $params->{$key}\n");
+       }
+       $node->reload;
+   }
+
+   my $log    = $node->logfile();
+   my $offset = -s $log;
+
+   $node->safe_psql("postgres", $sql);
+
+   my $log_contents = slurp_file($log, $offset);
+
+   if (keys %$params)
+   {
+       for my $key (keys %$params)
+       {
+           $node->adjust_conf('postgresql.conf', $key, undef);
+       }
+       $node->reload;
+   }
+
+   return $log_contents;
+}
+
 my $node = PostgreSQL::Test::Cluster->new('main');
 $node->init;
 $node->append_conf('postgresql.conf',
@@ -16,39 +52,61 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
 $node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
 $node->start;
 
-# run a couple of queries
-$node->safe_psql("postgres", "SELECT * FROM pg_class;");
-$node->safe_psql("postgres",
-   "SELECT * FROM pg_proc WHERE proname = 'int4pl';");
-
-# emit some json too
-$node->append_conf('postgresql.conf', "auto_explain.log_format = json");
-$node->reload;
-$node->safe_psql("postgres", "SELECT * FROM pg_proc;");
-$node->safe_psql("postgres",
-   "SELECT * FROM pg_class WHERE relname = 'pg_class';");
-
-$node->stop('fast');
+# Simple query.
+my $log_contents = query_log($node, "SELECT * FROM pg_class;");
 
-my $log = $node->logfile();
-
-my $log_contents = slurp_file($log);
+like(
+   $log_contents,
+   qr/Query Text: SELECT \* FROM pg_class;/,
+   "query text logged, text mode");
 
 like(
    $log_contents,
    qr/Seq Scan on pg_class/,
    "sequential scan logged, text mode");
 
+# Prepared query.
+$log_contents = query_log($node,
+   q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');}
+);
+
+like(
+   $log_contents,
+   qr/Query Text: PREPARE get_proc\(name\) AS SELECT \* FROM pg_proc WHERE proname = \$1;/,
+   "prepared query text logged, text mode");
+
 like(
    $log_contents,
    qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
    "index scan logged, text mode");
 
+# JSON format.
+$log_contents = query_log(
+   $node,
+   "SELECT * FROM pg_proc;",
+   { "auto_explain.log_format" => "json" });
+
+like(
+   $log_contents,
+   qr/"Query Text": "SELECT \* FROM pg_proc;"/,
+   "query text logged, json mode");
+
 like(
    $log_contents,
    qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_proc"/s,
    "sequential scan logged, json mode");
 
+# Prepared query in JSON format.
+$log_contents = query_log(
+   $node,
+   q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
+   { "auto_explain.log_format" => "json" });
+
+like(
+   $log_contents,
+   qr/"Query Text": "PREPARE get_class\(name\) AS SELECT \* FROM pg_class WHERE relname = \$1;"/,
+   "prepared query text logged, json mode");
+
 like(
    $log_contents,
    qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,