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
From 6d4bab7f21c3661dd4dd5a0de7e097b1de3f642c Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.alek...@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
From 8793b8beb6a5c1ae730f1fffb09dff64c83bc631 Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.alek...@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
From 31dc30c97861afae9c34852afc5a5b1c91bbeadc Mon Sep 17 00:00:00 2001
From: Alexey Kondratov <kondratov.alek...@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
