Date: Thu, 24 Jun 2021 11:21:48 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Fabien COELHO <coelho@cri.ensmp.fr>
Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>,
	Andrew Dunstan <andrew@dunslane.net>,
	Thomas Munro <thomas.munro@gmail.com>,
	Gregory Smith <gregsmithpgsql@gmail.com>,
	PostgreSQL-development <pgsql-hackers@postgresql.org>,
	david.christensen@crunchydata.com
Subject: Re: pgbench logging broken by time logic changes
Message-ID: <YNPsPAUoVDCpPOGk@paquier.xyz>
References: <202106231308.lxr26cahwxuc@alvherre.pgsql>
 <alpine.DEB.2.22.394.2106232158120.1601973@pseudo>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="nkZLiGfws8WioM09"
Content-Disposition: inline
In-Reply-To: <alpine.DEB.2.22.394.2106232158120.1601973@pseudo>
Archived-At: 
 <https://www.postgresql.org/message-id/YNPsPAUoVDCpPOGk%40paquier.xyz>
Precedence: bulk


--nkZLiGfws8WioM09
Content-Type: multipart/mixed; boundary="bMulltpajNfWo92U"
Content-Disposition: inline


--bMulltpajNfWo92U
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Wed, Jun 23, 2021 at 10:01:28PM +0200, Fabien COELHO wrote:
> Thanks for the hint! Why not, having the ability to collect data is a good
> thing, so attached v10 does that. If something go wrong, the TODO section
> could be extended around all calls.

+check_pgbench_logs($bdir, '001_pgbench_log_1', $nthreads, 1, 3,
+   qr{^\d{10,} \d{1,2} \d+ \d+ \d+ \d+ \d+ \d+ \d+ \d+ \d+$});
FWIW, I am still seeing problems with the regex pattern you are using
here, because this fails to detect the number of fields we should have
generated here, for one.  If you are not convinced, just run your new
test and extend or reduce the amount of data generated by logAgg() in
your patch: the tests will still pass.

So I have investigated this stuff in details.  The regular expressions
are correctly shaped, but the use of grep() in check_pgbench_logs()
seems to be incorrect.

For example, let's take an aggregate report generated by your new
test:
"1624498086 13 27632 60597490 1683 2853 3227 883179 120 386 123"
Here are some extra ones, shorter and longer:
"1624498086 13 27632 60597490 1683 2853 3227 8831";
"1624498086 13 27632 60597490 1683 2853 3227 883179 120 386 123 123";

Using grep() with "$re" results in all the fields matching.  Using on
the contrary "/$re/" in grep(), like list_files(), would only match
the first one, which is correct.  Please see attached a small script
to show my point, called perl_grep.pl.

With this issue fixed, I have bumped into what looks like a different
bug in the tests.  001_pgbench_log_2 uses pgbench with 2 clients, but
expects only patterns in the logs where the first column value uses
only 0.  With two clients, those first values can be either 0 or 1 due
to the client ID set.

It seems to me that we had better fix this issue and back-patch where
this has been introduced so as we have exact match checks with the log
formarts, no?  Please see the attached.

Thoughts?
--
Michael

--bMulltpajNfWo92U
Content-Type: text/x-perl; charset=us-ascii
Content-Disposition: attachment; filename="perl_grep.pl"

use strict;
use warnings;
use Test::More;

my $field_correct = "1624498086 13 27632 60597490 1683 2853 3227 883179 120 386 123";
my $field_broken_short = "1624498086 13 27632 60597490 1683 2853 3227 8831";
my $field_broken_long = "1624498086 13 27632 60597490 1683 2853 3227 883179 120 386 123 123";
my $re = qr{^\d{10,} \d{1,2} \d+ \d+ \d+ \d+ \d+ \d+ \d+ \d+ \d+$};
my @array_broken = ($field_correct, $field_broken_short, $field_broken_long);
my @array_correct = ($field_correct, $field_correct);

# All the element should match here.
ok(grep($re, @array_correct) == @array_correct, 're+array_correct');
ok(grep(/$re/, @array_correct) == @array_correct, '/re/+array_correct');

# Only one element should match here.
ok(grep($re, @array_broken) == 1, 're+array_broken');
ok(grep(/$re/, @array_broken) == 1, '/re/+array_broken');

--bMulltpajNfWo92U
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="pgbench-tap-fix.patch"
Content-Transfer-Encoding: quoted-printable

diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench=
/t/001_pgbench_with_server.pl
index 923203ea51..ef8e40240b 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -1194,7 +1194,7 @@ sub check_pgbench_logs
 			my $clen     =3D @contents;
 			ok( $min <=3D $clen && $clen <=3D $max,
 				"transaction count for $log ($clen)");
-			ok( grep($re, @contents) =3D=3D $clen,
+			ok( grep(/$re/, @contents) =3D=3D $clen,
 				"transaction format for $prefix");
 			close $fh or die "$@";
 		};
@@ -1213,7 +1213,7 @@ pgbench(
 	"--log-prefix=3D$bdir/001_pgbench_log_2");
=20
 check_pgbench_logs($bdir, '001_pgbench_log_2', 1, 8, 92,
-	qr{^0 \d{1,2} \d+ \d \d+ \d+$});
+	qr{^{0,1} \d{1,2} \d+ \d \d+ \d+$});
=20
 # check log file in some detail
 pgbench(

--bMulltpajNfWo92U--

--nkZLiGfws8WioM09
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmDT7DwACgkQnvQgOdby
QH0apRAAgMFwmYrP1478CtZKiJeCbkgPOQuad2i7NmrS8bGH0IfLuC/PXeYGN6Hp
DPNhfUVsYizEEOlzF39WNu2/XRNInKlUUUL9mIruV3/Ymo3Sc2k3/5hTcV2uTSRA
siSYVpFDDjyW1susfe8hr7JkiRv7PFewPXsjoYxYQOvt9cu65TzZ7mOVC0Da8j86
fFs//P79oSvSXVtZZz+VLMZ8iQUPJbEhaCQkhUdByeJsiT1B4LV2qDTUrf3jv1n1
ay2sEhYVTlwnDX/sATIUlcCfB2V1NjLnOR/c5Q5bV/yyaUEnYfo1BUb1vF35y2X/
PTeKcB2I7uEnbdwMbXGPpQTIQner74C8EiPNN2QyB8mNUUofT0TDhDn35fg+EohK
k1QoR9X+LCfgl146Kfh9xZw30zvxu6zLLJz4/6kpu3bctsOTaUV3eYqUq9O4Szi/
2Ln3xeQbHcYoBuTS0HONdUJ6uB9GqesPhIflrFcpTxPMpKPPLlts6Dw0ouVyNdWZ
fzBMT+KIYhEsZZOS1OzPkJP2ifIOge1TQV0YHNBwvyquzexWuPtWTY/NT5nGZMCT
Mb0WmiiSqZERkUjcoEoYVfnb0UsPuw3ot0LEvfATDZ1+ZD15eln3zZQMnFOlgJGF
p+cAyXCbLl5t/FdJbwReLB4CU+xdBbK0ky+Nqi8+3voKOl61DxI=
=Wf6Z
-----END PGP SIGNATURE-----

--nkZLiGfws8WioM09--