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: Mon, 09 Nov 2020 23:03:53 +0300
Message-ID: <f36e95736ed8c57d61cfb054fd734194@postgrespro.ru> (raw)
In-Reply-To: <1992985.1604948005@sss.pgh.pa.us>
References: <3b1c053a21c07c1ed5e00be3b2b855ef@postgrespro.ru>
<1992985.1604948005@sss.pgh.pa.us>
On 2020-11-09 21:53, Tom Lane wrote:
> Alexey Kondratov <a.kondratov@postgrespro.ru> writes:
>> After fixing this issue I have noticed that it still dumps blocks
>> twice
>> at each timeout (here I set autoprewarm_interval to 15s):
>> ...
>> This happens because at timeout time we were using continue, but
>> actually we still have to wait the entire autoprewarm_interval after
>> successful dumping.
>
> I don't think your 0001 is correct. It would be okay if apw_dump_now()
> could be counted on to take negligible time, but we shouldn't assume
> that should we?
>
Yes, it seems so, if I understand you correctly. I had a doubt about
possibility of pg_ctl to exit earlier than a dumping process. Now I
added an explicit wait for dump file into test.
> I agree that the "continue" seems a bit bogus, because it's skipping
> the ResetLatch call at the bottom of the loop; it's not quite clear
> to me whether that's a good thing or not. But the general idea of
> the existing code seems to be to loop around and make a fresh
> calculation
> of how-long-to-wait, and that doesn't seem wrong.
I have left the last patch intact, since it resolves the 'double dump'
issue, but I agree with нщгк point about existing logic of the code,
although it is a bit broken. So I have to think more about how to fix it
in a better way.
> 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.
> BTW, I see another bug of a related ilk. Look what
> postgres_fdw/connection.c is doing:
>
> TimestampDifference(now, endtime, &secs, µsecs);
>
> /* To protect against clock skew, limit sleep to one
> minute. */
> cur_timeout = Min(60000, secs * USECS_PER_SEC +
> microsecs);
>
> /* Sleep until there's something to do */
> wc = WaitLatchOrSocket(MyLatch,
> WL_LATCH_SET |
> WL_SOCKET_READABLE |
> WL_TIMEOUT |
> WL_EXIT_ON_PM_DEATH,
> PQsocket(conn),
> cur_timeout, PG_WAIT_EXTENSION);
>
> WaitLatchOrSocket's timeout is measured in msec not usec. I think the
> comment about "clock skew" is complete BS, and the Min() calculation
> was
> put in as a workaround by somebody observing that the sleep waited too
> long, but not understanding why.
I wonder how many troubles one can get with all these unit conversions.
Regards
--
Alexey Kondratov
Postgres Professional https://www.postgrespro.com
Russian Postgres Company
Attachments:download all (4 files, .tar.gz)v2-0004-pg_prewarm-refactor-autoprewarm-waits.patch (text/x-diff, 891B) download
From c79de17014753b311858b4570ca475f713328c62 Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.aleksey@gmail.com>
Date: Mon, 9 Nov 2020 19:24:55 +0300
Subject: [PATCH v2 4/4] pg_prewarm: refactor autoprewarm waits
Previously it was dumping twice at every timeout time.
---
contrib/pg_prewarm/autoprewarm.c | 4 +++-
1 file changed, 3 insertions(+), 1 deletion(-)
diff --git a/contrib/pg_prewarm/autoprewarm.c b/contrib/pg_prewarm/autoprewarm.cindex e5bd130bc8..872c7d51b1 100644--- a/contrib/pg_prewarm/autoprewarm.c+++ b/contrib/pg_prewarm/autoprewarm.c@@ -236,7 +236,9 @@ autoprewarm_main(Datum main_arg)
{
last_dump_time = GetCurrentTimestamp();
apw_dump_now(true, false);
- continue;++ /* We have to sleep even after a successful dump */+ delay_in_ms = autoprewarm_interval * 1000;
}
/* Sleep until the next dump time. */
--
2.19.1
v2-0003-pg_prewarm-fix-autoprewarm_interval-behaviour.patch (text/x-diff, 1.3K) download
From c38c07708d57d6dec5a8a1697ca9c9810ad4d7ce 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 v2 3/4] pg_prewarm: fix autoprewarm_interval behaviour.
Previously it misused seconds from TimestampDifference() as
milliseconds, so it was dumping autoprewarm.blocks ~every second
event 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
v2-0002-Implement-TimestampDifferenceMilliseconds.patch (text/x-diff, 2.2K) download
From 23a8a967e806b76f3ed2f9078d6c9afdc7a8dc48 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 v2 2/4] 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 | 20 ++++++++++++++++++++
src/include/utils/timestamp.h | 2 ++
2 files changed, 22 insertions(+)
diff --git a/src/backend/utils/adt/timestamp.c b/src/backend/utils/adt/timestamp.cindex ea0ada704f..7b28f070cc 100644--- a/src/backend/utils/adt/timestamp.c+++ b/src/backend/utils/adt/timestamp.c@@ -1666,6 +1666,26 @@ 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.+ */+long+TimestampDifferenceMilliseconds(TimestampTz start_time, TimestampTz stop_time)+{+ TimestampTz diff = stop_time - start_time;++ if (diff <= 0)+ return 0;+ else+ return (long) (diff / 1000);+}+
/*
* 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);
--
2.19.1
v2-0001-pg_prewarm-add-tap-test-for-autoprewarm-feature.patch (text/x-diff, 2.5K) download
From 52a77a5250f765c79ccda3af00906505c0163141 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 v2 1/4] 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..744c443169--- /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');
base-commit: 8f113698b63b15a4e0a4b15d3ee37238c1d1821d
--
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: <f36e95736ed8c57d61cfb054fd734194@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