From: Alexey Kondratov <a.kondratov@postgrespro.ru>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Cc: Robert Haas <robertmhaas@gmail.com>
Subject: Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
Date: Tue, 10 Nov 2020 19:58:44 +0300
Message-ID: <01241062b6bfea2f17e32a65a4f99d61@postgrespro.ru> (raw)
In-Reply-To: <1996862.1604953516@sss.pgh.pa.us>
References: <3b1c053a21c07c1ed5e00be3b2b855ef@postgrespro.ru>
<1992985.1604948005@sss.pgh.pa.us>
<f36e95736ed8c57d61cfb054fd734194@postgrespro.ru>
<1996862.1604953516@sss.pgh.pa.us>
On 2020-11-09 23:25, Tom Lane wrote:
> Alexey Kondratov <a.kondratov@postgrespro.ru> writes:
>> On 2020-11-09 21:53, Tom Lane wrote:
>>> 0002 seems like a pretty clear bug fix, though I wonder if this is
>>> exactly
>>> what we want to do going forward. It seems like a very large
>>> fraction of
>>> the callers of TimestampDifference would like to have the value in
>>> msec,
>>> which means we're doing a whole lot of expensive and error-prone
>>> arithmetic to break down the difference to sec/usec and then put it
>>> back together again. Let's get rid of that by inventing, say
>>> TimestampDifferenceMilliseconds(...).
>
>> Yeah, I get into this problem after a bug in another extension —
>> pg_wait_sampling. I have attached 0002, which implements
>> TimestampDifferenceMilliseconds(), so 0003 just uses this new function
>> to solve the initial issues. If it looks good to you, then we can
>> switch
>> all similar callers to it.
>
> Yeah, let's move forward with that --- in fact, I'm inclined to
> back-patch it. (Not till the current release cycle is done, though.
> I don't find this important enough to justify a last-moment patch.)
>
> BTW, I wonder if we shouldn't make TimestampDifferenceMilliseconds
> round any fractional millisecond up rather than down. Rounding down
> seems to create a hazard of uselessly waking just before the delay is
> completed. Better to wake just after.
>
Yes, it make sense. I have changed TimestampDifferenceMilliseconds() to
round result up if there is a reminder.
After looking on the autoprewarm code more closely I have realised that
this 'double dump' issues was not an issues at all. I have just
misplaced a debug elog(), so its second output in the log was only
indicating that we calculated delay_in_ms one more time. Actually, even
with wrong calculation of delay_in_ms the only problem was that we were
busy looping with ~1 second interval instead of waiting on latch.
It is still a buggy behaviour, but much less harmful than I have
originally thought.
Regards
--
Alexey Kondratov
Postgres Professional https://www.postgrespro.com
Russian Postgres Company
Attachments:download all (3 files, .tar.gz)v3-0003-pg_prewarm-add-tap-test-for-autoprewarm-feature.patch (text/x-diff, 2.4K) download
From ce09103d9d58b611728b66366cd24e8a4069f7ac Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.aleksey@gmail.com>
Date: Mon, 9 Nov 2020 19:04:10 +0300
Subject: [PATCH v3 3/3] pg_prewarm: add tap test for autoprewarm feature
---
contrib/pg_prewarm/Makefile | 2 +
contrib/pg_prewarm/t/001_autoprewarm.pl | 59 +++++++++++++++++++++++++
2 files changed, 61 insertions(+)
create mode 100644 contrib/pg_prewarm/t/001_autoprewarm.pl
diff --git a/contrib/pg_prewarm/Makefile b/contrib/pg_prewarm/Makefileindex b13ac3c813..9cfde8c4e4 100644--- a/contrib/pg_prewarm/Makefile+++ b/contrib/pg_prewarm/Makefile@@ -10,6 +10,8 @@ EXTENSION = pg_prewarm
DATA = pg_prewarm--1.1--1.2.sql pg_prewarm--1.1.sql pg_prewarm--1.0--1.1.sql
PGFILEDESC = "pg_prewarm - preload relation data into system buffer cache"
+TAP_TESTS = 1+
ifdef USE_PGXS
PG_CONFIG = pg_config
PGXS := $(shell $(PG_CONFIG) --pgxs)
diff --git a/contrib/pg_prewarm/t/001_autoprewarm.pl b/contrib/pg_prewarm/t/001_autoprewarm.plnew file mode 100644index 0000000000..f55b2a5352--- /dev/null+++ b/contrib/pg_prewarm/t/001_autoprewarm.pl@@ -0,0 +1,59 @@+#+# Check that pg_prewarm can dump blocks from shared buffers+# to PGDATA/autoprewarm.blocks.+#++use strict;+use Test::More;+use TestLib;+use Time::HiRes qw(usleep);+use warnings;++use PostgresNode;++plan tests => 3;++# Wait up to 180s for pg_prewarm to dump blocks.+sub wait_for_dump+{+ my $path = shift;++ foreach my $i (0 .. 1800)+ {+ last if -e $path;+ usleep(100_000);+ }+}++my $node = get_new_node("node");+$node->init;+$node->append_conf(+ 'postgresql.conf', qq(+shared_preload_libraries = 'pg_prewarm'+pg_prewarm.autoprewarm = 'on'+pg_prewarm.autoprewarm_interval = 1+));+$node->start;++my $blocks_path = $node->data_dir . '/autoprewarm.blocks';++# Check that we can dump blocks on timeout.+wait_for_dump($blocks_path);+ok(-e $blocks_path, 'file autoprewarm.blocks should be present in the PGDATA');++# Check that we can dump blocks on shutdown.+$node->stop;+$node->append_conf(+ 'postgresql.conf', qq(+pg_prewarm.autoprewarm_interval = 0+));++# Remove autoprewarm.blocks+unlink($blocks_path) || die "$blocks_path: $!";+ok(!-e $blocks_path, 'sanity check, dump on timeout is turned off');++$node->start;+$node->stop;++wait_for_dump($blocks_path);+ok(-e $blocks_path, 'file autoprewarm.blocks should be present in the PGDATA after clean shutdown');--
2.19.1
v3-0002-pg_prewarm-fix-autoprewarm_interval-behaviour.patch (text/x-diff, 1.3K) download
From fba212ed765c8c411db1ca19c2ac991662109d99 Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.aleksey@gmail.com>
Date: Mon, 9 Nov 2020 19:12:00 +0300
Subject: [PATCH v3 2/3] pg_prewarm: fix autoprewarm_interval behaviour
Previously it misused seconds from TimestampDifference() as
milliseconds, so it was busy looping with ~1 second interval
instead of waiting on latch with default autoprewarm_interval = 300s.
---
contrib/pg_prewarm/autoprewarm.c | 8 +++-----
1 file changed, 3 insertions(+), 5 deletions(-)
diff --git a/contrib/pg_prewarm/autoprewarm.c b/contrib/pg_prewarm/autoprewarm.cindex d3dec6e3ec..e5bd130bc8 100644--- a/contrib/pg_prewarm/autoprewarm.c+++ b/contrib/pg_prewarm/autoprewarm.c@@ -222,16 +222,14 @@ autoprewarm_main(Datum main_arg)
{
long delay_in_ms = 0;
TimestampTz next_dump_time = 0;
- long secs = 0;- int usecs = 0;
/* Compute the next dump time. */
next_dump_time =
TimestampTzPlusMilliseconds(last_dump_time,
autoprewarm_interval * 1000);
- TimestampDifference(GetCurrentTimestamp(), next_dump_time,- &secs, &usecs);- delay_in_ms = secs + (usecs / 1000);+ delay_in_ms =+ TimestampDifferenceMilliseconds(GetCurrentTimestamp(),+ next_dump_time);
/* Perform a dump if it's time. */
if (delay_in_ms <= 0)
--
2.19.1
v3-0001-Implement-TimestampDifferenceMilliseconds.patch (text/x-diff, 2.6K) download
From 05329213c873dea69cbea2021e048eb814e00b4b Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.aleksey@gmail.com>
Date: Mon, 9 Nov 2020 22:29:48 +0300
Subject: [PATCH v3 1/3] Implement TimestampDifferenceMilliseconds()
Many callers of TimestampDifference() actually want a difference
in milliseconds. This new function allows them to get rid of
unnecessary (and frequently unsafe) calculations of milliseconds from
seconds and microseconds.
---
src/backend/utils/adt/timestamp.c | 32 +++++++++++++++++++++++++++++++
src/include/utils/timestamp.h | 2 ++
2 files changed, 34 insertions(+)
diff --git a/src/backend/utils/adt/timestamp.c b/src/backend/utils/adt/timestamp.cindex ea0ada704f..893fd467ba 100644--- a/src/backend/utils/adt/timestamp.c+++ b/src/backend/utils/adt/timestamp.c@@ -1666,6 +1666,38 @@ TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
}
}
+/*+ * TimestampDifferenceMilliseconds -- convert the difference between two+ * timestamps into integer milliseconds.+ *+ * Both inputs must be ordinary finite timestamps (in current usage,+ * they'll be results from GetCurrentTimestamp()).+ *+ * We expect start_time <= stop_time. If not, we return zero. We also+ * always round up result in ms, since many callers may use this function+ * to decide whether it is time to do something on timeout or not.+ * That way, let them do it just in time or 1 ms later instead of 1 ms+ * earlier.+ */+long+TimestampDifferenceMilliseconds(TimestampTz start_time, TimestampTz stop_time)+{+ TimestampTz diff = stop_time - start_time;++ if (diff <= 0)+ return 0;+ else+ {+ long msecs = (long) (diff / 1000);++ /* Round up if there is a reminder */+ if (diff % 1000 > 0)+ msecs += 1;++ return msecs;+ }+}+
/*
* TimestampDifferenceExceeds -- report whether the difference between two
* timestamps is >= a threshold (expressed in milliseconds)
diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.hindex 16c3fd8ec9..d45bf2bb7b 100644--- a/src/include/utils/timestamp.h+++ b/src/include/utils/timestamp.h@@ -72,6 +72,8 @@ extern TimestampTz GetSQLCurrentTimestamp(int32 typmod);
extern Timestamp GetSQLLocalTimestamp(int32 typmod);
extern void TimestampDifference(TimestampTz start_time, TimestampTz stop_time,
long *secs, int *microsecs);
+extern long TimestampDifferenceMilliseconds(TimestampTz start_time,+ TimestampTz stop_time);
extern bool TimestampDifferenceExceeds(TimestampTz start_time,
TimestampTz stop_time,
int msec);
base-commit: 3f16cb505d1d734674da2a2cbf2104ceae22f9b4
--
2.19.1
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: a.kondratov@postgrespro.ru, tgl@sss.pgh.pa.us, pgsql-hackers@lists.postgresql.org, robertmhaas@gmail.com
Subject: Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
In-Reply-To: <01241062b6bfea2f17e32a65a4f99d61@postgrespro.ru>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox