Date: Wed, 23 Jun 2021 12:47:37 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Fabien COELHO <coelho@cri.ensmp.fr>
Cc: Andrew Dunstan <andrew@dunslane.net>,
	Thomas Munro <thomas.munro@gmail.com>,
	Alvaro Herrera <alvherre@alvh.no-ip.org>,
	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: <YNKu2RVefp1lPjv2@paquier.xyz>
References: 
 <CA+hUKGKYNgwN=f=WDQ2vGtT_De5oNZ-OfQvtXqe2hBUXKnWFvg@mail.gmail.com>
 <202106200318.gxnon4vrc7t6@alvherre.pgsql>
 <CA+hUKGKXDfQ+ukYAmsnrzNa2dGsEG+BMhMrBXGZ1fyPjP4vZUA@mail.gmail.com>
 <CA+hUKGKoUy_DDAR1EWQ8DqqfFY5ApbTTyy7nUJOL2wuNbe2pXQ@mail.gmail.com>
 <alpine.DEB.2.22.394.2106201058130.3211875@pseudo>
 <a3be3485-3a5c-7654-78f6-817749e720b3@dunslane.net>
 <YNEt9w6cDvUOK7bG@paquier.xyz>
 <alpine.DEB.2.22.394.2106221201140.883117@pseudo>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="5sELj4OZC4KLemhA"
Content-Disposition: inline
In-Reply-To: <alpine.DEB.2.22.394.2106221201140.883117@pseudo>
Archived-At: 
 <https://www.postgresql.org/message-id/YNKu2RVefp1lPjv2%40paquier.xyz>
Precedence: bulk


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

On Tue, Jun 22, 2021 at 12:06:45PM +0200, Fabien COELHO wrote:
> Attached an updated v8 patch which adds (reinstate) an improved TAP test
> which would have caught the various regressions on logs.

> Given that such tests were removed once before, I'm unsure whether they will
> be acceptable, despite that their usefulness has been clearly demonstrated.
> At least it is for the record. Sigh:-(

Thanks!

This v8 is an addition of the fix for the epoch with the adjustments
for the aggregate reports in the logs.  The maths look rather right
after a read and after some tests.

+# note: this test is time sensitive, and may fail on a very
+#       loaded host.
+# note: --progress-timestamp is not tested
+my $delay = pgbench(
+	'-T 2 -P 1 -l --aggregate-interval=1 -S -b se@2'
+	. ' --rate=20 --latency-limit=1000 -j ' . $nthreads
+	. ' -c 3 -r',
+	0,
+	[   qr{type: multiple},
+		qr{clients: 3},
+		qr{threads: $nthreads},
+		qr{duration: 2 s},
+		qr{script 1: .* select only},
+		qr{script 2: .* select only},
+		qr{statement latencies in milliseconds},
+		qr{FROM pgbench_accounts} ],
+	[ qr{vacuum}, qr{progress: 1\b} ],
+	'pgbench progress', undef,
+	"--log-prefix=$bdir/001_pgbench_log_1");
Could we make that shorter at 1s?  That will shorten the duration of
the test run.  It is easy to miss that this test is for
--aggregate-interval (aka the logAgg() path) without a comment.

+# cool check that we are around 2 seconds
+# The rate may results in an unlucky schedule which triggers
+# an early exit, hence the loose bound.
+ok(0.0 < $delay && $delay < 4.0, "-T 2 run around 2 seconds");

The command itself would not fail, but we would just fail on a machine
where the difference in start/stop time is higher than 4 seconds,
right?  On RPI-level machines, this could fail reliably.  I am not
completely sure what's the additional value we can get from that extra
test, to be honest.

+# $nthreads threads, 2 seconds, but due to timing imprecision we might get
+# only 1 or as many as 3 progress reports per thread.
+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+$});
+
Now this one is good and actually stable thanks to the fact that we'd
get at least the final logs, and the main complain we got to discuss
about on this thread was the format of the logs.  I would say to give
up on the first test, and keep the second.  But, is this regex
correct?  Shouldn't we check for six integer fields only with the
first one having a minimal number of digits for the epoch?
--
Michael

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

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmDSrtgACgkQnvQgOdby
QH22UBAAmyhrDLkubNCBb19Ym5uXG5LK5Cb7OkKJXmOd5Q7DJAxQZo7U4tKNKHNu
Wb/GRBVxg02embDjU0ZnND+aEKCbqok9CNY7T231fK3MX2oPm6XmIMz7K3aXR5qE
oa+/jkS3vGipQj9qAioi4eGH8N+P68iDM2gPzNO/uP2SJYUqp57ZL/U+PDf81BFS
51DGOhf4sKcmmxMrQX3J1r9bVdVS5cevSq0+Mg8g3wvmvhlR9uCUust8wlnNCCYr
GJfW1k6UWXivu76ezTaa8UchIBswSQD7rPFDv2DrGqB/k4RFWblpseYdYOz6W82i
EOPWraKQ3NviMtmqWH2klFil2ToMu9J17ZPKA6GC1oIhoURYHs5gqeGV2WpBjkIj
7VCnWgzdl6RqG4BF6D/eGmyOG3x3aHbey+aBS49jBb8KomHqzdrQYqD3AOT3NoGN
vohGx9o+cLYB1PUkXD5+0NLMt42R8VeohHxqwuU85a7ecakL4ZsFDPv2fQZiQKxK
qgHazs16iAW2iC6D6zgIO2ELWAHSPYOxPk4NIx8cGyUKnoywQLRSblcvNB6Q+xO6
niax5iiyeHjEUdK6xbZXtDBx2ALc+6mqJr3tZ0btJUd556qBlxc1UGRxfvO1AMPc
5f8fAbLshWgavYjvOsyhY1x5c1yznX6tTWkchP5z5M5OgmqFtTE=
=IwvU
-----END PGP SIGNATURE-----

--5sELj4OZC4KLemhA--