Thread: Why did commit 6271fceb8 enable debug logging for all TAP tests?

I've been trying to trace down a slowdown in HEAD's regression tests
compared to the v10 branch, and one thing I discovered is that there was
a noticeable across-the-board slowdown in the TAP tests as a result of
commit 6271fceb8; as much as 10% for the "scripts" tests, though less in
other places.  The changes it made in xlog.c cannot explain that; it has
to be down to this:

diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
index 93faadc20e..80f68df246 100644
--- a/src/test/perl/PostgresNode.pm
+++ b/src/test/perl/PostgresNode.pm
@@ -419,6 +419,7 @@ sub init
     print $conf "restart_after_crash = off\n";
     print $conf "log_line_prefix = '%m [%p] %q%a '\n";
     print $conf "log_statement = all\n";
+    print $conf "log_min_messages = debug1\n";
     print $conf "log_replication_commands = on\n";
     print $conf "wal_retrieve_retry_interval = '500ms'\n";
     print $conf "port = $port\n";

Now, that was neither mentioned in the commit message nor justified
by any added test cases or scaffolding, so I'm assuming it was simply a
mistake and should be reverted.  Please confirm.

            regards, tom lane

On Sun, May 06, 2018 at 09:49:46PM -0400, Tom Lane wrote:
> Now, that was neither mentioned in the commit message nor justified
> by any added test cases or scaffolding, so I'm assuming it was simply a
> mistake and should be reverted.  Please confirm.

That was around to check that the debug messages generated when parsing
the backup_label file are correctly happening when running recovery
tests and made the patch validation handy.  Let's remove it.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Sun, May 06, 2018 at 09:49:46PM -0400, Tom Lane wrote:
>> Now, that was neither mentioned in the commit message nor justified
>> by any added test cases or scaffolding, so I'm assuming it was simply a
>> mistake and should be reverted.  Please confirm.

> That was around to check that the debug messages generated when parsing
> the backup_label file are correctly happening when running recovery
> tests and made the patch validation handy.  Let's remove it.

Thanks for the info.  The thing that led me to this was noticing that the
src/bin/scripts/t/102_vacuumdb_stages.pl test case was taking a ridiculous
amount of time: 24 seconds on my workstation, and several minutes on a
slower test machine, all spent in the Perl script itself.  After a bit of
staring at the test case, I noticed that it was checking the expected
server log output with a regex that had several occurrences of ".*.*".
That makes the match formally underdetermined (i.e, you could divide the
match between the first .* and the second .* arbitrarily).  It's not
really surprising that an NFA regex engine like Perl's might have
exponentially bad behavior when trying to identify a match to such a
pattern.  But then I got confused again: that test pattern is the same
for several releases back, but only HEAD is showing bad performance.

Now the explanation is clear.  Addition of DEBUG1 to the server
configuration increases the amount of log text that needs to be matched
against, and so the exponential match behavior crosses the threshold of
being obvious.  It's not increasing the amount of text all that much: on
my machine, the postmaster log for this test case goes from 2914 bytes
without DEBUG1 to 5382 bytes with it.  I tried it at DEBUG5, and gave
up after waiting about 15 minutes, by which time it had not finished
the first and simpler of the two problematic regexes :-(

The attached patch gets rid of the nonlinear match behavior by removing
redundant occurrences of ".*".  I think we should apply it not just to
HEAD but to the relevant back branches, in case anyone tries to run this
test with higher-than-default log levels.  In the spirit of not breaking
things right before a release, though, I'll hold off till after the wrap.

            regards, tom lane

diff --git a/src/bin/scripts/t/102_vacuumdb_stages.pl b/src/bin/scripts/t/102_vacuumdb_stages.pl
index 3929441..17a7fc7 100644
*** a/src/bin/scripts/t/102_vacuumdb_stages.pl
--- b/src/bin/scripts/t/102_vacuumdb_stages.pl
*************** $node->start;
*** 10,35 ****

  $node->issues_sql_like(
      [ 'vacuumdb', '--analyze-in-stages', 'postgres' ],
!     qr/.*statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ RESET\ default_statistics_target;
                     .*statement:\ ANALYZE/sx,
      'analyze three times');

  $node->issues_sql_like(
      [ 'vacuumdb', '--analyze-in-stages', '--all' ],
!     qr/.*statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ RESET\ default_statistics_target;
!                    .*statement:\ ANALYZE.*
                     .*statement:\ RESET\ default_statistics_target;
                     .*statement:\ ANALYZE/sx,
      'analyze more than one database in stages');
--- 10,35 ----

  $node->issues_sql_like(
      [ 'vacuumdb', '--analyze-in-stages', 'postgres' ],
!     qr/statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE
                     .*statement:\ RESET\ default_statistics_target;
                     .*statement:\ ANALYZE/sx,
      'analyze three times');

  $node->issues_sql_like(
      [ 'vacuumdb', '--analyze-in-stages', '--all' ],
!     qr/statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE
                     .*statement:\ SET\ default_statistics_target=1;\ SET\ vacuum_cost_delay=0;
!                    .*statement:\ ANALYZE
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE
                     .*statement:\ SET\ default_statistics_target=10;\ RESET\ vacuum_cost_delay;
!                    .*statement:\ ANALYZE
                     .*statement:\ RESET\ default_statistics_target;
!                    .*statement:\ ANALYZE
                     .*statement:\ RESET\ default_statistics_target;
                     .*statement:\ ANALYZE/sx,
      'analyze more than one database in stages');