public inbox for [email protected]  
help / color / mirror / Atom feed
[PATCH 4/6] TAP test for the slot limit feature
20+ messages / 6 participants
[nested] [flat]

* [PATCH 4/6] TAP test for the slot limit feature
@ 2017-12-21 08:33  Kyotaro Horiguchi <[email protected]>
  0 siblings, 0 replies; 20+ messages in thread

From: Kyotaro Horiguchi @ 2017-12-21 08:33 UTC (permalink / raw)

---
 src/test/recovery/t/016_replslot_limit.pl | 184 ++++++++++++++++++++++
 1 file changed, 184 insertions(+)
 create mode 100644 src/test/recovery/t/016_replslot_limit.pl

diff --git a/src/test/recovery/t/016_replslot_limit.pl b/src/test/recovery/t/016_replslot_limit.pl
new file mode 100644
index 0000000000..e150ca7a54
--- /dev/null
+++ b/src/test/recovery/t/016_replslot_limit.pl
@@ -0,0 +1,184 @@
+# Test for replication slot limit
+# Ensure that max_slot_wal_keep_size limits the number of WAL files to
+# be kept by replication slots.
+
+use strict;
+use warnings;
+use File::Path qw(rmtree);
+use PostgresNode;
+use TestLib;
+use Test::More tests => 11;
+use Time::HiRes qw(usleep);
+
+$ENV{PGDATABASE} = 'postgres';
+
+# Initialize master node, setting wal-segsize to 1MB
+my $node_master = get_new_node('master');
+$node_master->init(allows_streaming => 1, extra => ['--wal-segsize=1']);
+$node_master->append_conf('postgresql.conf', qq(
+min_wal_size = 2MB
+max_wal_size = 3MB
+));
+$node_master->start;
+$node_master->safe_psql('postgres', "SELECT pg_create_physical_replication_slot('rep1')");
+
+# The slot state should be the state "unknown" before the first connection
+my $result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "|unknown|0", 'check the state of non-reserved slot is "unknown"');
+
+
+# Take backup
+my $backup_name = 'my_backup';
+$node_master->backup($backup_name);
+
+# Create a standby linking to it using the replication slot
+my $node_standby = get_new_node('standby_1');
+$node_standby->init_from_backup($node_master, $backup_name, has_streaming => 1, primary_slot_name => 'rep1');
+
+$node_standby->start;
+
+# Wait until standby has replayed enough data
+my $start_lsn = $node_master->lsn('write');
+$node_master->wait_for_catchup($node_standby, 'replay', $start_lsn);
+
+# Stop standby
+$node_standby->stop;
+
+
+# Preparation done, the slot is the state "streaming" now
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|streaming|0", 'check the catching-up state');
+
+# Advance WAL by five segments (= 5MB) on master
+advance_wal($node_master, 5);
+$node_master->safe_psql('postgres', "CHECKPOINT;");
+
+# The slot is always "safe" when max_slot_wal_keep_size is not set
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|streaming|0", 'check that slot is working');
+
+# The standby can connect to master
+$node_standby->start;
+
+$start_lsn = $node_master->lsn('write');
+$node_master->wait_for_catchup($node_standby, 'replay', $start_lsn);
+
+$node_standby->stop;
+
+# Set max_slot_wal_keep_size on master
+my $max_slot_wal_keep_size_mb = 3;
+$node_master->append_conf('postgresql.conf', qq(
+max_slot_wal_keep_size = ${max_slot_wal_keep_size_mb}MB
+));
+$node_master->reload;
+
+# The slot is in safe state. The remaining bytes should be as almost
+# (max_slot_wal_keep_size + 1) times large as the segment size
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, pg_size_pretty(remain) as remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|streaming|4096 kB", 'check that max_slot_wal_keep_size is working');
+
+# Advance WAL again then checkpoint
+advance_wal($node_master, 2);
+$node_master->safe_psql('postgres', "CHECKPOINT;");
+
+# The slot is still working.
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, pg_size_pretty(remain) as remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|streaming|2048 kB", 'check that remaining byte is calculated correctly');
+
+# wal_keep_segments overrides max_slot_wal_keep_size
+$result = $node_master->safe_psql('postgres', "ALTER SYSTEM SET wal_keep_segments to 6; SELECT pg_reload_conf();");
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, pg_size_pretty(remain) as remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|streaming|5120 kB", 'check that wal_keep_segments overrides max_slot_wal_keep_size');
+
+# restore wal_keep_segments
+$result = $node_master->safe_psql('postgres', "ALTER SYSTEM SET wal_keep_segments to 0; SELECT pg_reload_conf();");
+
+# Advance WAL again without checkpoint
+advance_wal($node_master, 2);
+
+# Slot gets to 'keeping' state
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, pg_size_pretty(remain) as remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|keeping|0 bytes", 'check that the slot state changes to "keeping"');
+
+# The standby still can connect to master
+$node_standby->start;
+
+$start_lsn = $node_master->lsn('write');
+$node_master->wait_for_catchup($node_standby, 'replay', $start_lsn);
+
+$node_standby->stop;
+
+ok(!find_in_log($node_standby,
+				"requested WAL segment [0-9A-F]+ has already been removed"),
+   'check that required WAL segments are still available');
+
+# Advance WAL again, the slot loses some segments.
+my $logstart = get_log_size($node_master);
+advance_wal($node_master, 5);
+$node_master->safe_psql('postgres', "CHECKPOINT;");
+
+# WARNING should be issued
+ok(find_in_log($node_master,
+			   "some replication slots have lost required WAL segments\n".
+			   ".*Slot rep1 lost 2 segment\\(s\\)\\.",
+			   $logstart),
+   'check that the warning is logged');
+
+# This slot should be broken
+$result = $node_master->safe_psql('postgres', "SELECT restart_lsn, wal_status, pg_size_pretty(remain) as remain FROM pg_replication_slots WHERE slot_name = 'rep1'");
+is($result, "$start_lsn|lost|0 bytes", 'check that the slot state changes to "lost"');
+
+# The standby no longer can connect to the master
+$logstart = get_log_size($node_standby);
+$node_standby->start;
+
+my $failed = 0;
+for (my $i = 0 ; $i < 10000 ; $i++)
+{
+	if (find_in_log($node_standby,
+					"requested WAL segment [0-9A-F]+ has already been removed",
+					$logstart))
+	{
+		$failed = 1;
+		last;
+	}
+	usleep(100_000);
+}
+ok($failed, 'check that replication has been broken');
+
+$node_standby->stop;
+
+#####################################
+# Advance WAL of $node by $n segments
+sub advance_wal
+{
+	my ($node, $n) = @_;
+
+	# Advance by $n segments (= (16 * $n) MB) on master
+	for (my $i = 0 ; $i < $n ; $i++)
+	{
+		$node->safe_psql('postgres', "CREATE TABLE t (); DROP TABLE t; SELECT pg_switch_wal();");
+	}
+}
+
+# return the size of logfile of $node in bytes
+sub get_log_size
+{
+	my ($node) = @_;
+
+	return (stat $node->logfile)[7];
+}
+
+# find $pat in logfile of $node after $off-th byte
+sub find_in_log
+{
+	my ($node, $pat, $off) = @_;
+
+	$off = 0 unless defined $off;
+	my $log = TestLib::slurp_file($node->logfile);
+	return 0 if (length($log) <= $off);
+
+	$log = substr($log, $off);
+
+	return $log =~ m/$pat/;
+}
-- 
2.20.1


--MP_/68vU=6Ib.yoYOTdA.M=EVne
Content-Type: text/x-patch
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename=v14-0005-Documentation-for-slot-limit-feature.patch



^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-10 15:36  Nathan Bossart <[email protected]>
  0 siblings, 2 replies; 20+ messages in thread

From: Nathan Bossart @ 2024-06-10 15:36 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Mon, Jun 10, 2024 at 06:05:13AM +0000, Bertrand Drouvot wrote:
> During the last pgconf.dev I attended Robert´s presentation about autovacuum and
> it made me remember of an idea I had some time ago: $SUBJECT

This sounds like useful information to me.  I wonder if we should also
surface the effective cost limit for each autovacuum worker.

> Currently one can change [autovacuum_]vacuum_cost_delay and
> [auto vacuum]vacuum_cost_limit but has no reliable way to measure the impact of
> the changes on the vacuum duration: one could observe the vacuum duration
> variation but the correlation to the changes is not accurate (as many others
> factors could impact the vacuum duration (load on the system, i/o latency,...)).

IIUC you'd need to get information from both pg_stat_progress_vacuum and
pg_stat_activity in order to know what percentage of time was being spent
in cost delay.  Is that how you'd expect for this to be used in practice?

>  		pgstat_report_wait_start(WAIT_EVENT_VACUUM_DELAY);
>  		pg_usleep(msec * 1000);
>  		pgstat_report_wait_end();
> +		/* Report the amount of time we slept */
> +		if (VacuumSharedCostBalance != NULL)
> +			pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);
> +		else
> +			pgstat_progress_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);

Hm.  Should we measure the actual time spent sleeping, or is a rough
estimate good enough?  I believe pg_usleep() might return early (e.g., if
the process is signaled) or late, so this field could end up being
inaccurate, although probably not by much.  If we're okay with millisecond
granularity, my first instinct is that what you've proposed is fine, but I
figured I'd bring it up anyway.

-- 
nathan






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-10 17:48  Bertrand Drouvot <[email protected]>
  parent: Nathan Bossart <[email protected]>
  1 sibling, 2 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-10 17:48 UTC (permalink / raw)
  To: Nathan Bossart <[email protected]>; +Cc: [email protected]

Hi,

On Mon, Jun 10, 2024 at 10:36:42AM -0500, Nathan Bossart wrote:
> On Mon, Jun 10, 2024 at 06:05:13AM +0000, Bertrand Drouvot wrote:
> > During the last pgconf.dev I attended Robert´s presentation about autovacuum and
> > it made me remember of an idea I had some time ago: $SUBJECT
> 
> This sounds like useful information to me.

Thanks for looking at it!

> I wonder if we should also
> surface the effective cost limit for each autovacuum worker.

I'm not sure about it as I think that it could be misleading: one could query
pg_stat_progress_vacuum and conclude that the time_delayed he is seeing is
due to _this_ cost_limit. But that's not necessary true as the cost_limit could
have changed multiple times since the vacuum started. So, unless there is
frequent sampling on pg_stat_progress_vacuum, displaying the time_delayed and
the cost_limit could be misleadind IMHO.

> > Currently one can change [autovacuum_]vacuum_cost_delay and
> > [auto vacuum]vacuum_cost_limit but has no reliable way to measure the impact of
> > the changes on the vacuum duration: one could observe the vacuum duration
> > variation but the correlation to the changes is not accurate (as many others
> > factors could impact the vacuum duration (load on the system, i/o latency,...)).
> 
> IIUC you'd need to get information from both pg_stat_progress_vacuum and
> pg_stat_activity in order to know what percentage of time was being spent
> in cost delay.  Is that how you'd expect for this to be used in practice?

Yeah, one could use a query such as:

select p.*, now() - a.xact_start as duration from pg_stat_progress_vacuum p JOIN pg_stat_activity a using (pid)

for example. Worth to provide an example somewhere in the doc?

> >  		pgstat_report_wait_start(WAIT_EVENT_VACUUM_DELAY);
> >  		pg_usleep(msec * 1000);
> >  		pgstat_report_wait_end();
> > +		/* Report the amount of time we slept */
> > +		if (VacuumSharedCostBalance != NULL)
> > +			pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);
> > +		else
> > +			pgstat_progress_incr_param(PROGRESS_VACUUM_TIME_DELAYED, msec);
> 
> Hm.  Should we measure the actual time spent sleeping, or is a rough
> estimate good enough?  I believe pg_usleep() might return early (e.g., if
> the process is signaled) or late, so this field could end up being
> inaccurate, although probably not by much.  If we're okay with millisecond
> granularity, my first instinct is that what you've proposed is fine, but I
> figured I'd bring it up anyway.

Thanks for bringing that up! I had the same thought when writing the code and
came to the same conclusion. I think that's a good enough estimation and specially
during a long running vacuum (which is probably the case where users care the 
most).

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-10 19:20  Nathan Bossart <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  1 sibling, 1 reply; 20+ messages in thread

From: Nathan Bossart @ 2024-06-10 19:20 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Mon, Jun 10, 2024 at 05:48:22PM +0000, Bertrand Drouvot wrote:
> On Mon, Jun 10, 2024 at 10:36:42AM -0500, Nathan Bossart wrote:
>> I wonder if we should also
>> surface the effective cost limit for each autovacuum worker.
> 
> I'm not sure about it as I think that it could be misleading: one could query
> pg_stat_progress_vacuum and conclude that the time_delayed he is seeing is
> due to _this_ cost_limit. But that's not necessary true as the cost_limit could
> have changed multiple times since the vacuum started. So, unless there is
> frequent sampling on pg_stat_progress_vacuum, displaying the time_delayed and
> the cost_limit could be misleadind IMHO.

Well, that's true for the delay, too, right (at least as of commit
7d71d3d)?

-- 
nathan






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-10 20:12  Imseih (AWS), Sami <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  1 sibling, 1 reply; 20+ messages in thread

From: Imseih (AWS), Sami @ 2024-06-10 20:12 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; Nathan Bossart <[email protected]>; +Cc: [email protected] <[email protected]>

>> This sounds like useful information to me.

> Thanks for looking at it!

The  VacuumDelay is the only visibility available to
gauge the cost_delay. Having this information
advertised by pg_stat_progress_vacuum as is being proposed
is much better. However, I also think that the
"number of times"  the vacuum went into delay will be needed
as well. Both values will be useful to tune cost_delay and cost_limit. 

It may also make sense to accumulate the total_time in delay
and the number of times delayed in a cumulative statistics [0]
view to allow a user to trend this information overtime.
I don't think this info fits in any of the existing views, i.e.
pg_stat_database, so maybe a new view for cumulative
vacuum stats may be needed. This is likely a separate
discussion, but calling it out here.

>> IIUC you'd need to get information from both pg_stat_progress_vacuum and
>> pg_stat_activity in order to know what percentage of time was being spent
>> in cost delay.  Is that how you'd expect for this to be used in practice?

> Yeah, one could use a query such as:

> select p.*, now() - a.xact_start as duration from pg_stat_progress_vacuum p JOIN pg_stat_activity a using (pid)

Maybe all  progress views should just expose the "beentry->st_activity_start_timestamp " 
to let the user know when the current operation began.


Regards,

Sami Imseih
Amazon Web Services (AWS)


[0] https://www.postgresql.org/docs/current/monitoring-stats.html






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-10 21:58  Robert Haas <[email protected]>
  parent: Nathan Bossart <[email protected]>
  1 sibling, 2 replies; 20+ messages in thread

From: Robert Haas @ 2024-06-10 21:58 UTC (permalink / raw)
  To: Nathan Bossart <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; [email protected]

On Mon, Jun 10, 2024 at 11:36 AM Nathan Bossart
<[email protected]> wrote:
> Hm.  Should we measure the actual time spent sleeping, or is a rough
> estimate good enough?  I believe pg_usleep() might return early (e.g., if
> the process is signaled) or late, so this field could end up being
> inaccurate, although probably not by much.  If we're okay with millisecond
> granularity, my first instinct is that what you've proposed is fine, but I
> figured I'd bring it up anyway.

I bet you could also sleep for longer than planned, throwing the
numbers off in the other direction.

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)?

-- 
Robert Haas
EDB: http://www.enterprisedb.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 06:24  Bertrand Drouvot <[email protected]>
  parent: Nathan Bossart <[email protected]>
  0 siblings, 0 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-11 06:24 UTC (permalink / raw)
  To: Nathan Bossart <[email protected]>; +Cc: [email protected]

On Mon, Jun 10, 2024 at 02:20:16PM -0500, Nathan Bossart wrote:
> On Mon, Jun 10, 2024 at 05:48:22PM +0000, Bertrand Drouvot wrote:
> > On Mon, Jun 10, 2024 at 10:36:42AM -0500, Nathan Bossart wrote:
> >> I wonder if we should also
> >> surface the effective cost limit for each autovacuum worker.
> > 
> > I'm not sure about it as I think that it could be misleading: one could query
> > pg_stat_progress_vacuum and conclude that the time_delayed he is seeing is
> > due to _this_ cost_limit. But that's not necessary true as the cost_limit could
> > have changed multiple times since the vacuum started. So, unless there is
> > frequent sampling on pg_stat_progress_vacuum, displaying the time_delayed and
> > the cost_limit could be misleadind IMHO.
> 
> Well, that's true for the delay, too, right (at least as of commit
> 7d71d3d)?

Yeah right, but the patch exposes the total amount of time the vacuum has
been delayed (not the cost_delay per say) which does not sound misleading to me.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 06:50  Bertrand Drouvot <[email protected]>
  parent: Imseih (AWS), Sami <[email protected]>
  0 siblings, 0 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-11 06:50 UTC (permalink / raw)
  To: Imseih (AWS), Sami <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected] <[email protected]>

Hi,

On Mon, Jun 10, 2024 at 08:12:46PM +0000, Imseih (AWS), Sami wrote:
> >> This sounds like useful information to me.
> 
> > Thanks for looking at it!
> 
> The  VacuumDelay is the only visibility available to
> gauge the cost_delay. Having this information
> advertised by pg_stat_progress_vacuum as is being proposed
> is much better.

Thanks for looking at it!

> However, I also think that the
> "number of times"  the vacuum went into delay will be needed
> as well. Both values will be useful to tune cost_delay and cost_limit. 

Yeah, I think that's a good idea. With v1 one could figure out how many times
the delay has been triggered but that does not work anymore if: 1) cost_delay
changed during the vacuum duration or 2) the patch changes the way time_delayed
is measured/reported (means get the actual wait time and not the theoritical
time as v1 does). 

> 
> It may also make sense to accumulate the total_time in delay
> and the number of times delayed in a cumulative statistics [0]
> view to allow a user to trend this information overtime.
> I don't think this info fits in any of the existing views, i.e.
> pg_stat_database, so maybe a new view for cumulative
> vacuum stats may be needed. This is likely a separate
> discussion, but calling it out here.

+1

> >> IIUC you'd need to get information from both pg_stat_progress_vacuum and
> >> pg_stat_activity in order to know what percentage of time was being spent
> >> in cost delay.  Is that how you'd expect for this to be used in practice?
> 
> > Yeah, one could use a query such as:
> 
> > select p.*, now() - a.xact_start as duration from pg_stat_progress_vacuum p JOIN pg_stat_activity a using (pid)
> 
> Maybe all  progress views should just expose the "beentry->st_activity_start_timestamp " 
> to let the user know when the current operation began.

Yeah maybe, I think this is likely a separate discussion too, thoughts?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 07:25  Bertrand Drouvot <[email protected]>
  parent: Robert Haas <[email protected]>
  1 sibling, 1 reply; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-11 07:25 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected]

Hi,

On Mon, Jun 10, 2024 at 05:58:13PM -0400, Robert Haas wrote:
> On Mon, Jun 10, 2024 at 11:36 AM Nathan Bossart
> <[email protected]> wrote:
> > Hm.  Should we measure the actual time spent sleeping, or is a rough
> > estimate good enough?  I believe pg_usleep() might return early (e.g., if
> > the process is signaled) or late, so this field could end up being
> > inaccurate, although probably not by much.  If we're okay with millisecond
> > granularity, my first instinct is that what you've proposed is fine, but I
> > figured I'd bring it up anyway.
> 
> I bet you could also sleep for longer than planned, throwing the
> numbers off in the other direction.

Thanks for looking at it! Agree, that's how I read "or late" from Nathan's
comment above.

> 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)?

OTOH Sami proposed in [1] to count the number of times the vacuum went into
delay. I think that's a good idea. His idea makes me think that (in addition to
the number of wait times) it would make sense to measure the "actual" sleep time
(and not the intended one) then (so that one could measure the difference between
the intended wait time (number of wait times * cost delay (if it does not change
during the vacuum duration)) and the actual measured wait time).

So I think that in v2 we could: 1) measure the actual wait time instead, 2)
count the number of times the vacuum slept. We could also 3) reports the
effective cost limit (as proposed by Nathan up-thread) (I think that 3) could
be misleading but I'll yield to majority opinion if people think it's not).

Thoughts?


[1]: https://www.postgresql.org/message-id/A0935130-7C4B-4094-B6E4-C7D5086D50EF%40amazon.com

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 09:49  Bertrand Drouvot <[email protected]>
  parent: Robert Haas <[email protected]>
  1 sibling, 1 reply; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-11 09:49 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected]

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,


Attachments:

  [text/plain] record_actual_time.txt (3.2K, ../../[email protected]/2-record_actual_time.txt)
  download | inline diff:
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,


^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 16:40  Nathan Bossart <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 20+ messages in thread

From: Nathan Bossart @ 2024-06-11 16:40 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Robert Haas <[email protected]>; [email protected]

On Tue, Jun 11, 2024 at 07:25:11AM +0000, Bertrand Drouvot wrote:
> So I think that in v2 we could: 1) measure the actual wait time instead, 2)
> count the number of times the vacuum slept. We could also 3) reports the
> effective cost limit (as proposed by Nathan up-thread) (I think that 3) could
> be misleading but I'll yield to majority opinion if people think it's not).

I still think the effective cost limit would be useful, if for no other
reason than to help reinforce that it is distributed among the autovacuum
workers.  We could document that this value may change over the lifetime of
a worker to help avoid misleading folks.

-- 
nathan






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 17:13  Robert Haas <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 3 replies; 20+ messages in thread

From: Robert Haas @ 2024-06-11 17:13 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected]

On Tue, Jun 11, 2024 at 5:49 AM Bertrand Drouvot
<[email protected]> wrote:
> 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?

I like the idea of reporting the actual wait time better, provided
that we verify that doing so isn't too expensive. I think it probably
isn't, because in a long-running VACUUM there is likely to be disk
I/O, so the CPU overhead of a few extra gettimeofday() calls should be
fairly low by comparison. I wonder if there's a noticeable hit when
everything is in-memory. I guess probably not, because with any sort
of normal configuration, we shouldn't be delaying after every block we
process, so the cost of those gettimeofday() calls should still be
getting spread across quite a bit of real work.

That said, I'm not sure this experiment shows a real problem with the
idea of showing intended wait time. It does establish the concept that
repeated signals can throw our numbers off, but 30ms isn't much of a
discrepancy. I'm worried about being off by a factor of two, or an
order of magnitude. I think we still don't know if that can happen,
but if we're going to show actual wait time anyway, then we don't need
to explore the problems with other hypothetical systems too much.

I'm not convinced that reporting the number of waits is useful. If we
were going to report a possibly-inaccurate amount of actual waiting,
then also reporting the number of waits might make it easier to figure
out when the possibly-inaccurate number was in fact inaccurate. But I
think it's way better to report an accurate amount of actual waiting,
and then I'm not sure what we gain by also reporting the number of
waits.

-- 
Robert Haas
EDB: http://www.enterprisedb.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 17:26  Jan Wieck <[email protected]>
  parent: Robert Haas <[email protected]>
  2 siblings, 0 replies; 20+ messages in thread

From: Jan Wieck @ 2024-06-11 17:26 UTC (permalink / raw)
  To: [email protected]

On 6/11/24 13:13, Robert Haas wrote:
> On Tue, Jun 11, 2024 at 5:49 AM Bertrand Drouvot
> <[email protected]> wrote:
>> 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?
> 
> I like the idea of reporting the actual wait time better, provided
> that we verify that doing so isn't too expensive. I think it probably
> isn't, because in a long-running VACUUM there is likely to be disk
> I/O, so the CPU overhead of a few extra gettimeofday() calls should be
> fairly low by comparison. I wonder if there's a noticeable hit when
> everything is in-memory. I guess probably not, because with any sort
> of normal configuration, we shouldn't be delaying after every block we
> process, so the cost of those gettimeofday() calls should still be
> getting spread across quite a bit of real work.

Does it even require a call to gettimeofday()? The code in vacuum 
calculates an msec value and calls pg_usleep(msec * 1000). I don't think 
it is necessary to measure how long that nap was.


Regards, Jan







^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 18:19  Imseih (AWS), Sami <[email protected]>
  parent: Robert Haas <[email protected]>
  2 siblings, 1 reply; 20+ messages in thread

From: Imseih (AWS), Sami @ 2024-06-11 18:19 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; Bertrand Drouvot <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected] <[email protected]>

> I'm not convinced that reporting the number of waits is useful. If we
> were going to report a possibly-inaccurate amount of actual waiting,
> then also reporting the number of waits might make it easier to figure
> out when the possibly-inaccurate number was in fact inaccurate. But I
> think it's way better to report an accurate amount of actual waiting,
> and then I'm not sure what we gain by also reporting the number of
> waits.

I think including the number of times vacuum went into sleep 
will help paint a full picture of the effect of tuning the vacuum_cost_delay 
and vacuum_cost_limit for the user, even if we are reporting accurate 
amounts of actual sleeping.

This is particularly true for autovacuum in which the cost limit is spread
across all autovacuum workers, and knowing how many times autovacuum
went to sleep will be useful along with the total time spent sleeping.

Regards,

Sami



^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 18:47  Nathan Bossart <[email protected]>
  parent: Imseih (AWS), Sami <[email protected]>
  0 siblings, 1 reply; 20+ messages in thread

From: Nathan Bossart @ 2024-06-11 18:47 UTC (permalink / raw)
  To: Imseih (AWS), Sami <[email protected]>; +Cc: Robert Haas <[email protected]>; Bertrand Drouvot <[email protected]>; [email protected] <[email protected]>

On Tue, Jun 11, 2024 at 06:19:23PM +0000, Imseih (AWS), Sami wrote:
>> I'm not convinced that reporting the number of waits is useful. If we
>> were going to report a possibly-inaccurate amount of actual waiting,
>> then also reporting the number of waits might make it easier to figure
>> out when the possibly-inaccurate number was in fact inaccurate. But I
>> think it's way better to report an accurate amount of actual waiting,
>> and then I'm not sure what we gain by also reporting the number of
>> waits.
> 
> I think including the number of times vacuum went into sleep 
> will help paint a full picture of the effect of tuning the vacuum_cost_delay 
> and vacuum_cost_limit for the user, even if we are reporting accurate 
> amounts of actual sleeping.
> 
> This is particularly true for autovacuum in which the cost limit is spread
> across all autovacuum workers, and knowing how many times autovacuum
> went to sleep will be useful along with the total time spent sleeping.

I'm struggling to think of a scenario in which the number of waits would be
useful, assuming you already know the amount of time spent waiting.  Even
if the number of waits is huge, it doesn't tell you much else AFAICT.  I'd
be much more likely to adjust the cost settings based on the percentage of
time spent sleeping.

-- 
nathan






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 18:48  Robert Haas <[email protected]>
  parent: Nathan Bossart <[email protected]>
  0 siblings, 2 replies; 20+ messages in thread

From: Robert Haas @ 2024-06-11 18:48 UTC (permalink / raw)
  To: Nathan Bossart <[email protected]>; +Cc: Imseih (AWS), Sami <[email protected]>; Bertrand Drouvot <[email protected]>; [email protected] <[email protected]>

On Tue, Jun 11, 2024 at 2:47 PM Nathan Bossart <[email protected]> wrote:
> I'm struggling to think of a scenario in which the number of waits would be
> useful, assuming you already know the amount of time spent waiting.  Even
> if the number of waits is huge, it doesn't tell you much else AFAICT.  I'd
> be much more likely to adjust the cost settings based on the percentage of
> time spent sleeping.

This is also how I see it.

-- 
Robert Haas
EDB: http://www.enterprisedb.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-11 21:04  Imseih (AWS), Sami <[email protected]>
  parent: Robert Haas <[email protected]>
  1 sibling, 0 replies; 20+ messages in thread

From: Imseih (AWS), Sami @ 2024-06-11 21:04 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; Nathan Bossart <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; [email protected] <[email protected]>

>> I'm struggling to think of a scenario in which the number of waits would be
>> useful, assuming you already know the amount of time spent waiting. Even
>> if the number of waits is huge, it doesn't tell you much else AFAICT. I'd
>> be much more likely to adjust the cost settings based on the percentage of
>> time spent sleeping.


> This is also how I see it.

I think it may be useful for a user to be able to answer the "average
sleep time" for a vacuum, especially because the vacuum cost 
limit and delay can be adjusted on the fly for a running vacuum.

If we only show the total sleep time, the user could make wrong
 assumptions about how long each sleep took and they might 
assume that all sleep delays for a particular vacuum run have been 
uniform in duration, when in-fact they may not have been.


Regards,

Sami 







^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-12 10:52  Bertrand Drouvot <[email protected]>
  parent: Nathan Bossart <[email protected]>
  0 siblings, 0 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-12 10:52 UTC (permalink / raw)
  To: Nathan Bossart <[email protected]>; +Cc: Robert Haas <[email protected]>; [email protected]

Hi,

On Tue, Jun 11, 2024 at 11:40:36AM -0500, Nathan Bossart wrote:
> On Tue, Jun 11, 2024 at 07:25:11AM +0000, Bertrand Drouvot wrote:
> > So I think that in v2 we could: 1) measure the actual wait time instead, 2)
> > count the number of times the vacuum slept. We could also 3) reports the
> > effective cost limit (as proposed by Nathan up-thread) (I think that 3) could
> > be misleading but I'll yield to majority opinion if people think it's not).
> 
> I still think the effective cost limit would be useful, if for no other
> reason than to help reinforce that it is distributed among the autovacuum
> workers.

I also think it can be useful, my concern is more to put this information in
pg_stat_progress_vacuum. What about Sawada-san proposal in [1]? (we could
create a new view that would contain those data: per-worker dobalance, cost_lmit,
cost_delay, active, and failsafe). 

[1]: https://www.postgresql.org/message-id/CAD21AoDOu%3DDZcC%2BPemYmCNGSwbgL1s-5OZkZ1Spd5pSxofWNCw%40mail...

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-12 11:27  Bertrand Drouvot <[email protected]>
  parent: Robert Haas <[email protected]>
  1 sibling, 0 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-12 11:27 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; +Cc: Nathan Bossart <[email protected]>; Imseih (AWS), Sami <[email protected]>; [email protected] <[email protected]>

Hi,

On Tue, Jun 11, 2024 at 02:48:30PM -0400, Robert Haas wrote:
> On Tue, Jun 11, 2024 at 2:47 PM Nathan Bossart <[email protected]> wrote:
> > I'm struggling to think of a scenario in which the number of waits would be
> > useful, assuming you already know the amount of time spent waiting.

If we provide the actual time spent waiting, providing the number of waits would
allow to see if there is a diff between the actual time and the intended time
(i.e: number of waits * cost_delay, should the cost_delay be the same during
the vacuum duration). That should trigger some thoughts if the diff is large
enough.

I think that what we are doing here is to somehow add instrumentation around the
"WAIT_EVENT_VACUUM_DELAY" wait event. If we were to add instrumentation for wait
events (generaly speaking) we'd probably also expose the number of waits per
wait event (in addition to the time waited).

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 20+ messages in thread

* Re: Track the amount of time waiting due to cost_delay
@ 2024-06-12 12:02  Bertrand Drouvot <[email protected]>
  parent: Robert Haas <[email protected]>
  2 siblings, 0 replies; 20+ messages in thread

From: Bertrand Drouvot @ 2024-06-12 12:02 UTC (permalink / raw)
  To: Robert Haas <[email protected]>; +Cc: Nathan Bossart <[email protected]>; [email protected]

Hi,

On Tue, Jun 11, 2024 at 01:13:48PM -0400, Robert Haas wrote:
> On Tue, Jun 11, 2024 at 5:49 AM Bertrand Drouvot
> <[email protected]> wrote:
> > 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?
> 
> I like the idea of reporting the actual wait time better,

+1

> provided
> that we verify that doing so isn't too expensive. I think it probably
> isn't, because in a long-running VACUUM there is likely to be disk
> I/O, so the CPU overhead of a few extra gettimeofday() calls should be
> fairly low by comparison.

Agree.

> I wonder if there's a noticeable hit when
> everything is in-memory. I guess probably not, because with any sort
> of normal configuration, we shouldn't be delaying after every block we
> process, so the cost of those gettimeofday() calls should still be
> getting spread across quite a bit of real work.

I did some testing, with:

shared_buffers = 12GB
vacuum_cost_delay = 1
autovacuum_vacuum_cost_delay = 1
max_parallel_maintenance_workers = 0
max_parallel_workers = 0

added to a default config file.

A table and all its indexes were fully in memory, the numbers are:

postgres=# SELECT n.nspname, c.relname, count(*) AS buffers
             FROM pg_buffercache b JOIN pg_class c
             ON b.relfilenode = pg_relation_filenode(c.oid) AND
                b.reldatabase IN (0, (SELECT oid FROM pg_database
                                      WHERE datname = current_database()))
             JOIN pg_namespace n ON n.oid = c.relnamespace
             GROUP BY n.nspname, c.relname
             ORDER BY 3 DESC
             LIMIT 11;

 nspname |      relname      | buffers
---------+-------------------+---------
 public  | large_tbl         |  222280
 public  | large_tbl_pkey    |    5486
 public  | large_tbl_filler7 |    1859
 public  | large_tbl_filler4 |    1859
 public  | large_tbl_filler1 |    1859
 public  | large_tbl_filler6 |    1859
 public  | large_tbl_filler3 |    1859
 public  | large_tbl_filler2 |    1859
 public  | large_tbl_filler5 |    1859
 public  | large_tbl_filler8 |    1859
 public  | large_tbl_version |    1576
(11 rows)


The observed timings when vacuuming this table are:

On master:

vacuum phase: cumulative duration
---------------------------------

scanning heap: 00:00:37.808184
vacuuming indexes: 00:00:41.808176
vacuuming heap: 00:00:54.808156

On master patched with actual time delayed:

vacuum phase: cumulative duration
---------------------------------

scanning heap: 00:00:36.502104 (time_delayed: 22202)
vacuuming indexes: 00:00:41.002103 (time_delayed: 23769)
vacuuming heap: 00:00:54.302096 (time_delayed: 34886)

As we can see there is no noticeable degradation while the vacuum entered about
34886 times in this instrumentation code path (cost_delay was set to 1).

> That said, I'm not sure this experiment shows a real problem with the
> idea of showing intended wait time. It does establish the concept that
> repeated signals can throw our numbers off, but 30ms isn't much of a
> discrepancy.

Yeah, the idea was just to show how easy it is to create a 30ms discrepancy.

> I'm worried about being off by a factor of two, or an
> order of magnitude. I think we still don't know if that can happen,
> but if we're going to show actual wait time anyway, then we don't need
> to explore the problems with other hypothetical systems too much.

Agree.

> I'm not convinced that reporting the number of waits is useful. If we
> were going to report a possibly-inaccurate amount of actual waiting,
> then also reporting the number of waits might make it easier to figure
> out when the possibly-inaccurate number was in fact inaccurate. But I
> think it's way better to report an accurate amount of actual waiting,
> and then I'm not sure what we gain by also reporting the number of
> waits.

Sami shared his thoughts in [1] and [2] and so did I in [3]. If some of us still
don't think that reporting the number of waits is useful then we can probably
start without it.

[1]: https://www.postgresql.org/message-id/0EA474B6-BF88-49AE-82CA-C1A9A3C17727%40amazon.com
[2]: https://www.postgresql.org/message-id/E12435E2-5FCA-49B0-9ADB-0E7153F95E2D%40amazon.com
[3]: https://www.postgresql.org/message-id/ZmmGG4e%2BqTBD2kfn%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






^ permalink  raw  reply  [nested|flat] 20+ messages in thread


end of thread, other threads:[~2024-06-12 12:02 UTC | newest]

Thread overview: 20+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2017-12-21 08:33 [PATCH 4/6] TAP test for the slot limit feature Kyotaro Horiguchi <[email protected]>
2024-06-10 15:36 Re: Track the amount of time waiting due to cost_delay Nathan Bossart <[email protected]>
2024-06-10 17:48 ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-10 19:20   ` Re: Track the amount of time waiting due to cost_delay Nathan Bossart <[email protected]>
2024-06-11 06:24     ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-10 20:12   ` Re: Track the amount of time waiting due to cost_delay Imseih (AWS), Sami <[email protected]>
2024-06-11 06:50     ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-10 21:58 ` Re: Track the amount of time waiting due to cost_delay Robert Haas <[email protected]>
2024-06-11 07:25   ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-11 16:40     ` Re: Track the amount of time waiting due to cost_delay Nathan Bossart <[email protected]>
2024-06-12 10:52       ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-11 09:49   ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-11 17:13     ` Re: Track the amount of time waiting due to cost_delay Robert Haas <[email protected]>
2024-06-11 17:26       ` Re: Track the amount of time waiting due to cost_delay Jan Wieck <[email protected]>
2024-06-11 18:19       ` Re: Track the amount of time waiting due to cost_delay Imseih (AWS), Sami <[email protected]>
2024-06-11 18:47         ` Re: Track the amount of time waiting due to cost_delay Nathan Bossart <[email protected]>
2024-06-11 18:48           ` Re: Track the amount of time waiting due to cost_delay Robert Haas <[email protected]>
2024-06-11 21:04             ` Re: Track the amount of time waiting due to cost_delay Imseih (AWS), Sami <[email protected]>
2024-06-12 11:27             ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>
2024-06-12 12:02       ` Re: Track the amount of time waiting due to cost_delay Bertrand Drouvot <[email protected]>

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox