Horton

Thread

Commits

  1. Improve inefficient regexes in vacuumdb TAP test.

  2. Undo extra chattiness of postmaster logs in TAP tests.

  3. Add TIMELINE to backup_label file

  1. Why did commit 6271fceb8 enable debug logging for all TAP tests?

    Tom Lane <tgl@sss.pgh.pa.us> — 2018-05-07T01:49:46Z

    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

  2. Re: Why did commit 6271fceb8 enable debug logging for all TAP tests?

    Michael Paquier <michael@paquier.xyz> — 2018-05-07T01:56:19Z

    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

  3. Re: Why did commit 6271fceb8 enable debug logging for all TAP tests?

    Tom Lane <tgl@sss.pgh.pa.us> — 2018-05-07T02:46:02Z

    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