Hi,
On Mon, Jun 10, 2024 at 05:58:13PM -0400, Robert Haas wrote:
> I'm always suspicious of this sort of thing. I tend to find nothing
> gives me the right answer unless I assume that the actual sleep times
> are randomly and systematically different from the intended sleep
> times but arbitrarily large amounts. I think we should at least do
> some testing: if we measure both the intended sleep time and the
> actual sleep time, how close are they? Does it change if the system is
> under crushing load (which might elongate sleeps) or if we spam
> SIGUSR1 against the vacuum process (which might shorten them)?
Though I (now) think that it would make sense to record the actual delay time
instead (see [1]), I think it's interesting to do some testing as you suggested.
With record_actual_time.txt (attached) applied on top of v1, we can see the
intended and actual wait time.
On my system, "no load at all" except the vacuum running, I see no diff:
Tue Jun 11 09:22:06 2024 (every 1s)
pid | relid | phase | time_delayed | actual_time_delayed |
duration
-------+-------+---------------+--------------+---------------------+-----------------
54754 | 16385 | scanning heap | 41107 | 41107 |
00:00:42.301851
(1 row)
Tue Jun 11 09:22:07 2024 (every 1s)
pid | relid | phase | time_delayed | actual_time_delayed |
duration
-------+-------+---------------+--------------+---------------------+-----------------
54754 | 16385 | scanning heap | 42076 | 42076 |
00:00:43.301848
(1 row)
Tue Jun 11 09:22:08 2024 (every 1s)
pid | relid | phase | time_delayed | actual_time_delayed |
duration
-------+-------+---------------+--------------+---------------------+-----------------
54754 | 16385 | scanning heap | 43045 | 43045 |
00:00:44.301854
(1 row)
But if I launch pg_reload_conf() 10 times in a row, I can see:
Tue Jun 11 09:22:09 2024 (every 1s)
pid | relid | phase | time_delayed | actual_time_delayed |
duration
-------+-------+---------------+--------------+---------------------+-----------------
54754 | 16385 | scanning heap | 44064 | 44034 |
00:00:45.302965
(1 row)
Tue Jun 11 09:22:10 2024 (every 1s)
pid | relid | phase | time_delayed | actual_time_delayed |
duration
-------+-------+---------------+--------------+---------------------+-----------------
54754 | 16385 | scanning heap | 45033 | 45003 |
00:00:46.301858
As we can see the actual wait time is 30ms less than the intended wait time with
this simple test. So I still think we should go with 1) actual wait time and 2)
report the number of waits (as mentioned in [1]). Does that make sense to you?
[1]:
https://www.postgresql.org/message-id/Zmf712A5xcOM9Hlg%40ip-10-97-1-34.eu-west-3.compute.internal
Regards,
--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com
diff --git a/src/backend/catalog/system_views.sql
b/src/backend/catalog/system_views.sql
index 1345e99dcb..e4ba8de00a 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1222,7 +1222,7 @@ CREATE VIEW pg_stat_progress_vacuum AS
S.param4 AS heap_blks_vacuumed, S.param5 AS index_vacuum_count,
S.param6 AS max_dead_tuple_bytes, S.param7 AS dead_tuple_bytes,
S.param8 AS indexes_total, S.param9 AS indexes_processed,
- S.param10 AS time_delayed
+ S.param10 AS time_delayed, S.param11 AS actual_time_delayed
FROM pg_stat_get_progress_info('VACUUM') AS S
LEFT JOIN pg_database D ON S.datid = D.oid;
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index 2551408a86..bbb5002efe 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -2381,18 +2381,29 @@ vacuum_delay_point(void)
/* Nap if appropriate */
if (msec > 0)
{
+ instr_time delay_start;
+ instr_time delay_time;
+
if (msec > vacuum_cost_delay * 4)
msec = vacuum_cost_delay * 4;
pgstat_report_wait_start(WAIT_EVENT_VACUUM_DELAY);
+ INSTR_TIME_SET_CURRENT(delay_start);
pg_usleep(msec * 1000);
+ INSTR_TIME_SET_CURRENT(delay_time);
pgstat_report_wait_end();
/* Report the amount of time we slept */
+ INSTR_TIME_SUBTRACT(delay_time, delay_start);
if (VacuumSharedCostBalance != NULL)
+ {
pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);
+
pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_ACTUAL_TIME_DELAYED,
INSTR_TIME_GET_MILLISEC(delay_time));
+ }
else
+ {
pgstat_progress_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);
-
+
pgstat_progress_incr_param(PROGRESS_VACUUM_ACTUAL_TIME_DELAYED,
INSTR_TIME_GET_MILLISEC(delay_time));
+ }
/*
* We don't want to ignore postmaster death during very long
vacuums
* with vacuum_cost_delay configured. We can't use the usual
diff --git a/src/include/commands/progress.h b/src/include/commands/progress.h
index 1fcefe9436..ec0efeec64 100644
--- a/src/include/commands/progress.h
+++ b/src/include/commands/progress.h
@@ -28,6 +28,7 @@
#define PROGRESS_VACUUM_INDEXES_TOTAL 7
#define PROGRESS_VACUUM_INDEXES_PROCESSED 8
#define PROGRESS_VACUUM_TIME_DELAYED 9
+#define PROGRESS_VACUUM_ACTUAL_TIME_DELAYED 10
/* Phases of vacuum (as advertised via PROGRESS_VACUUM_PHASE) */
#define PROGRESS_VACUUM_PHASE_SCAN_HEAP 1
diff --git a/src/test/regress/expected/rules.out
b/src/test/regress/expected/rules.out
index a499e44df1..9dcc98e685 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -2054,7 +2054,8 @@ pg_stat_progress_vacuum| SELECT s.pid,
s.param7 AS dead_tuple_bytes,
s.param8 AS indexes_total,
s.param9 AS indexes_processed,
- s.param10 AS time_delayed
+ s.param10 AS time_delayed,
+ s.param11 AS actual_time_delayed
FROM (pg_stat_get_progress_info('VACUUM'::text) s(pid, datid, relid,
param1, param2, param3, param4, param5, param6, param7, param8, param9,
param10, param11, param12, param13, param14, param15, param16, param17,
param18, param19, param20)
LEFT JOIN pg_database d ON ((s.datid = d.oid)));
pg_stat_recovery_prefetch| SELECT stats_reset,
