pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedMisuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
8+ messages / 3 participants
[nested] [flat]
Commits from this thread:
2020-11-11 ec29427ce2 171c457cd0 afce7908d7 3a89ea0eb6 cd39c23a21 e87139b433 210564a744 Fix and simplify some usages of TimestampDifference().
* Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
@ 2020-11-09 16:45 Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:05 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Jeevan Ladhe <jeevan.ladhe@enterprisedb.com>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 2 replies; 8+ messages in thread
From: Alexey Kondratov @ 2020-11-09 16:45 UTC (permalink / raw)
To: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; +Cc: Robert Haas <robertmhaas@gmail.com>
Hi Hackers,
Today I have accidentally noticed that autoprewarm feature of pg_prewarm
used TimestampDifference()'s results in a wrong way.
First, it used *seconds* result from it as a *milliseconds*. It was
causing it to make dump file autoprewarm.blocks ~every second with
default setting of autoprewarm_interval = 300s.
Here is a log part with debug output in this case:
```
2020-11-09 19:09:00.162 MSK [85328] LOG: dumping autoprewarm.blocks
2020-11-09 19:09:01.161 MSK [85328] LOG: dumping autoprewarm.blocks
2020-11-09 19:09:02.160 MSK [85328] LOG: dumping autoprewarm.blocks
2020-11-09 19:09:03.159 MSK [85328] LOG: dumping autoprewarm.blocks
```
After fixing this issue I have noticed that it still dumps blocks twice
at each timeout (here I set autoprewarm_interval to 15s):
```
2020-11-09 19:18:59.692 MSK [85662] LOG: dumping autoprewarm.blocks
2020-11-09 19:18:59.700 MSK [85662] LOG: dumping autoprewarm.blocks
2020-11-09 19:19:14.694 MSK [85662] LOG: dumping autoprewarm.blocks
2020-11-09 19:19:14.704 MSK [85662] LOG: dumping autoprewarm.blocks
```
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 have fixed both issues in the attached patches and also added a
minimalistic tap test as a first one to verify that this automatic
damping still works after refactoring. I put Robert into CC, since he is
an author of this feature.
What do you think?
Regards
--
Alexey Kondratov
Postgres Professional https://www.postgrespro.com
Russian Postgres Company
Attachments: download all (3 files, .tar.gz)
v1-0003-pg_prewarm-refactor-autoprewarm-waits.patch (text/x-diff, 892B) download
From 6d4bab7f21c3661dd4dd5a0de7e097b1de3f642c 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 v1 3/3] 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.c
index b18a065ed5..f52c83de1e 100644
--- a/contrib/pg_prewarm/autoprewarm.c
+++ b/contrib/pg_prewarm/autoprewarm.c
@@ -238,7 +238,9 @@ autoprewarm_main(Datum main_arg)
{
last_dump_time = GetCurrentTimestamp();
apw_dump_now(true, false);
- continue;
+
+ /* We have to sleep even after a successfull dump */
+ delay_in_ms = autoprewarm_interval * 1000;
}
/* Sleep until the next dump time. */
--
2.19.1
v1-0002-pg_prewarm-fix-autoprewarm_interval-behaviour.patch (text/x-diff, 1.0K) download
From 8793b8beb6a5c1ae730f1fffb09dff64c83bc631 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 v1 2/3] 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 | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/contrib/pg_prewarm/autoprewarm.c b/contrib/pg_prewarm/autoprewarm.c
index d3dec6e3ec..b18a065ed5 100644
--- a/contrib/pg_prewarm/autoprewarm.c
+++ b/contrib/pg_prewarm/autoprewarm.c
@@ -231,7 +231,7 @@ autoprewarm_main(Datum main_arg)
autoprewarm_interval * 1000);
TimestampDifference(GetCurrentTimestamp(), next_dump_time,
&secs, &usecs);
- delay_in_ms = secs + (usecs / 1000);
+ delay_in_ms = secs * 1000 + (usecs / 1000);
/* Perform a dump if it's time. */
if (delay_in_ms <= 0)
--
2.19.1
v1-0001-pg_prewarm-add-tap-test-for-autoprewarm-feature.patch (text/x-diff, 2.4K) download
From 31dc30c97861afae9c34852afc5a5b1c91bbeadc 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 v1 1/3] pg_prewarm: add tap test for autoprewarm feature
---
contrib/pg_prewarm/Makefile | 2 +
contrib/pg_prewarm/t/001_autoprewarm.pl | 51 +++++++++++++++++++++++++
2 files changed, 53 insertions(+)
create mode 100644 contrib/pg_prewarm/t/001_autoprewarm.pl
diff --git a/contrib/pg_prewarm/Makefile b/contrib/pg_prewarm/Makefile
index 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.pl
new file mode 100644
index 0000000000..b564c29931
--- /dev/null
+++ b/contrib/pg_prewarm/t/001_autoprewarm.pl
@@ -0,0 +1,51 @@
+#
+# 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;
+
+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 up to 180s for pg_prewarm to dump blocks.
+foreach my $i (0 .. 1800)
+{
+ last if -e $blocks_path;
+ usleep(100_000);
+}
+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;
+
+ok(-e $blocks_path, 'file autoprewarm.blocks should be present in the PGDATA after clean shutdown');
base-commit: 8f113698b63b15a4e0a4b15d3ee37238c1d1821d
--
2.19.1
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
@ 2020-11-09 18:05 ` Jeevan Ladhe <jeevan.ladhe@enterprisedb.com>
1 sibling, 0 replies; 8+ messages in thread
From: Jeevan Ladhe @ 2020-11-09 18:05 UTC (permalink / raw)
To: Alexey Kondratov <a.kondratov@postgrespro.ru>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
Hi,
On Mon, Nov 9, 2020 at 10:15 PM Alexey Kondratov <a.kondratov@postgrespro.ru>
wrote:
> Hi Hackers,
>
> Today I have accidentally noticed that autoprewarm feature of pg_prewarm
> used TimestampDifference()'s results in a wrong way.
>
> First, it used *seconds* result from it as a *milliseconds*. It was
> causing it to make dump file autoprewarm.blocks ~every second with
> default setting of autoprewarm_interval = 300s.
>
>
I had a look at this, and I agree that this is an issue. I also had a look
at
the patch 0002, and the patch looks good to me.
In patch 0003 there is a typo:
+ /* We have to sleep even after a successfull dump */
s/successfull/successful
Regards,
Jeevan Ladhe
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
@ 2020-11-09 18:53 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
1 sibling, 1 reply; 8+ messages in thread
From: Tom Lane @ 2020-11-09 18:53 UTC (permalink / raw)
To: Alexey Kondratov <a.kondratov@postgrespro.ru>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
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?
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.
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(...).
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.
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
@ 2020-11-09 20:03 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 20:25 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 8+ messages in thread
From: Alexey Kondratov @ 2020-11-09 20:03 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
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.c
index 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.c
index 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.c
index 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.h
index 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/Makefile
index 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.pl
new file mode 100644
index 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
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
@ 2020-11-09 20:25 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-10 16:58 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
0 siblings, 1 reply; 8+ messages in thread
From: Tom Lane @ 2020-11-09 20:25 UTC (permalink / raw)
To: Alexey Kondratov <a.kondratov@postgrespro.ru>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
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.
I still think your 0001 is fishy, but don't have time today to stare at
it more closely.
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 20:25 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
@ 2020-11-10 16:58 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-11 03:59 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 8+ messages in thread
From: Alexey Kondratov @ 2020-11-10 16:58 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
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/Makefile
index 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.pl
new file mode 100644
index 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.c
index 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.c
index 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.h
index 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
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 20:25 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-10 16:58 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
@ 2020-11-11 03:59 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-12 10:47 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
0 siblings, 1 reply; 8+ messages in thread
From: Tom Lane @ 2020-11-11 03:59 UTC (permalink / raw)
To: Alexey Kondratov <a.kondratov@postgrespro.ru>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>; Robert Haas <robertmhaas@gmail.com>
Alexey Kondratov <a.kondratov@postgrespro.ru> writes:
> 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.
Ah --- that explains why I couldn't see a problem.
I've pushed 0001+0002 plus some followup work to fix other places
that could usefully use TimestampDifferenceMilliseconds(). I have
not done anything with 0003 (the TAP test for pg_prewarm), and will
leave that to the judgment of somebody who's worked with pg_prewarm
before. To me it looks like it's not really testing things very
carefully at all; on the other hand, we have exactly zero test
coverage of that module today, so maybe something is better than
nothing.
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:53 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 20:25 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
2020-11-10 16:58 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-11 03:59 ` Re: Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Tom Lane <tgl@sss.pgh.pa.us>
@ 2020-11-12 10:47 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
0 siblings, 0 replies; 8+ messages in thread
From: Alexey Kondratov @ 2020-11-12 10:47 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
On 2020-11-11 06:59, Tom Lane wrote:
> Alexey Kondratov <a.kondratov@postgrespro.ru> writes:
>> 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.
>
> Ah --- that explains why I couldn't see a problem.
>
> I've pushed 0001+0002 plus some followup work to fix other places
> that could usefully use TimestampDifferenceMilliseconds(). I have
> not done anything with 0003 (the TAP test for pg_prewarm), and will
> leave that to the judgment of somebody who's worked with pg_prewarm
> before. To me it looks like it's not really testing things very
> carefully at all; on the other hand, we have exactly zero test
> coverage of that module today, so maybe something is better than
> nothing.
>
Great, thank you for generalisation of the issue and working on it.
Regards
--
Alexey Kondratov
Postgres Professional https://www.postgrespro.com
Russian Postgres Company
^ permalink raw reply [nested|flat] 8+ messages in thread
end of thread, other threads:[~2020-11-12 10:47 UTC | newest]
Thread overview: 8+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-11-09 16:45 Misuse of TimestampDifference() in the autoprewarm feature of pg_prewarm Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 18:05 ` Jeevan Ladhe <jeevan.ladhe@enterprisedb.com>
2020-11-09 18:53 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-09 20:03 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-09 20:25 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-10 16:58 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
2020-11-11 03:59 ` Tom Lane <tgl@sss.pgh.pa.us>
2020-11-12 10:47 ` Alexey Kondratov <a.kondratov@postgrespro.ru>
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