Skip to content

Commit bb8dff9

Browse files
nathan-bossartnathan-bossart
committed
Add cost-based vacuum delay time to progress views.
This commit adds the amount of time spent sleeping due to cost-based delay to the pg_stat_progress_vacuum and pg_stat_progress_analyze system views. A new configuration parameter named track_cost_delay_timing, which is off by default, controls whether this information is gathered. For vacuum, the reported value includes the sleep time of any associated parallel workers. However, parallel workers only report their sleep time once per second to avoid overloading the leader process. Bumps catversion. Author: Bertrand Drouvot <bertranddrouvot.pg@gmail.com> Co-authored-by: Nathan Bossart <nathandbossart@gmail.com> Reviewed-by: Sami Imseih <samimseih@gmail.com> Reviewed-by: Robert Haas <robertmhaas@gmail.com> Reviewed-by: Masahiko Sawada <sawada.mshk@gmail.com> Reviewed-by: Masahiro Ikeda <ikedamsh@oss.nttdata.com> Reviewed-by: Dilip Kumar <dilipbalaut@gmail.com> Reviewed-by: Sergei Kornilov <sk@zsrv.org> Discussion: https://postgr.es/m/ZmaXmWDL829fzAVX%40ip-10-97-1-34.eu-west-3.compute.internal
1 parent e5b0b0c commit bb8dff9

File tree

11 files changed

+144
-5
lines changed

11 files changed

+144
-5
lines changed

‎doc/src/sgml/config.sgml

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8252,6 +8252,30 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
82528252
</listitem>
82538253
</varlistentry>
82548254

8255+
<varlistentry id="guc-track-cost-delay-timing" xreflabel="track_cost_delay_timing">
8256+
<term><varname>track_cost_delay_timing</varname> (<type>boolean</type>)
8257+
<indexterm>
8258+
<primary><varname>track_cost_delay_timing</varname> configuration parameter</primary>
8259+
</indexterm>
8260+
</term>
8261+
<listitem>
8262+
<para>
8263+
Enables timing of cost-based vacuum delay (see
8264+
<xref linkend="runtime-config-resource-vacuum-cost"/>). This parameter
8265+
is off by default, as it will repeatedly query the operating system for
8266+
the current time, which may cause significant overhead on some
8267+
platforms. You can use the <xref linkend="pgtesttiming"/> tool to
8268+
measure the overhead of timing on your system. Cost-based vacuum delay
8269+
timing information is displayed in
8270+
<link linkend="vacuum-progress-reporting"><structname>pg_stat_progress_vacuum</structname></link>
8271+
and
8272+
<link linkend="analyze-progress-reporting"><structname>pg_stat_progress_analyze</structname></link>.
8273+
Only superusers and users with the appropriate <literal>SET</literal>
8274+
privilege can change this setting.
8275+
</para>
8276+
</listitem>
8277+
</varlistentry>
8278+
82558279
<varlistentry id="guc-track-io-timing" xreflabel="track_io_timing">
82568280
<term><varname>track_io_timing</varname> (<type>boolean</type>)
82578281
<indexterm>

‎doc/src/sgml/monitoring.sgml

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5606,6 +5606,18 @@ FROM pg_stat_get_backend_idset() AS backendid;
56065606
<literal>acquiring inherited sample rows</literal>.
56075607
</para></entry>
56085608
</row>
5609+
5610+
<row>
5611+
<entry role="catalog_table_entry"><para role="column_definition">
5612+
<structfield>delay_time</structfield> <type>double precision</type>
5613+
</para>
5614+
<para>
5615+
Total time spent sleeping due to cost-based delay (see
5616+
<xref linkend="runtime-config-resource-vacuum-cost"/>, in milliseconds
5617+
(if <xref linkend="guc-track-cost-delay-timing"/> is enabled, otherwise
5618+
zero).
5619+
</para></entry>
5620+
</row>
56095621
</tbody>
56105622
</tgroup>
56115623
</table>
@@ -6531,6 +6543,21 @@ FROM pg_stat_get_backend_idset() AS backendid;
65316543
<literal>cleaning up indexes</literal>.
65326544
</para></entry>
65336545
</row>
6546+
6547+
<row>
6548+
<entry role="catalog_table_entry"><para role="column_definition">
6549+
<structfield>delay_time</structfield> <type>double precision</type>
6550+
</para>
6551+
<para>
6552+
Total time spent sleeping due to cost-based delay (see
6553+
<xref linkend="runtime-config-resource-vacuum-cost"/>), in milliseconds
6554+
(if <xref linkend="guc-track-cost-delay-timing"/> is enabled, otherwise
6555+
zero). This includes the time that any associated parallel workers have
6556+
slept. However, parallel workers report their sleep time no more
6557+
frequently than once per second, so the reported value may be slightly
6558+
stale.
6559+
</para></entry>
6560+
</row>
65346561
</tbody>
65356562
</tgroup>
65366563
</table>

‎src/backend/catalog/system_views.sql

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1213,7 +1213,8 @@ CREATE VIEW pg_stat_progress_analyze AS
12131213
S.param5 AS ext_stats_computed,
12141214
S.param6 AS child_tables_total,
12151215
S.param7 AS child_tables_done,
1216-
CAST(S.param8 AS oid) AS current_child_table_relid
1216+
CAST(S.param8 AS oid) AS current_child_table_relid,
1217+
S.param9 / 1000000::double precision AS delay_time
12171218
FROM pg_stat_get_progress_info('ANALYZE') AS S
12181219
LEFT JOIN pg_database D ON S.datid = D.oid;
12191220

@@ -1233,7 +1234,8 @@ CREATE VIEW pg_stat_progress_vacuum AS
12331234
S.param4 AS heap_blks_vacuumed, S.param5 AS index_vacuum_count,
12341235
S.param6 AS max_dead_tuple_bytes, S.param7 AS dead_tuple_bytes,
12351236
S.param8 AS num_dead_item_ids, S.param9 AS indexes_total,
1236-
S.param10 AS indexes_processed
1237+
S.param10 AS indexes_processed,
1238+
S.param11 / 1000000::double precision AS delay_time
12371239
FROM pg_stat_get_progress_info('VACUUM') AS S
12381240
LEFT JOIN pg_database D ON S.datid = D.oid;
12391241

‎src/backend/commands/vacuum.c

Lines changed: 64 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@
3939
#include "catalog/pg_inherits.h"
4040
#include "commands/cluster.h"
4141
#include "commands/defrem.h"
42+
#include "commands/progress.h"
4243
#include "commands/vacuum.h"
4344
#include "miscadmin.h"
4445
#include "nodes/makefuncs.h"
@@ -59,6 +60,12 @@
5960
#include "utils/snapmgr.h"
6061
#include "utils/syscache.h"
6162

63+
/*
64+
* Minimum interval for cost-based vacuum delay reports from a parallel worker.
65+
* This aims to avoid sending too many messages and waking up the leader too
66+
* frequently.
67+
*/
68+
#define PARALLEL_VACUUM_DELAY_REPORT_INTERVAL_NS (NS_PER_S)
6269

6370
/*
6471
* GUC parameters
@@ -70,6 +77,7 @@ int vacuum_multixact_freeze_table_age;
7077
int vacuum_failsafe_age;
7178
int vacuum_multixact_failsafe_age;
7279
double vacuum_max_eager_freeze_failure_rate;
80+
bool track_cost_delay_timing;
7381

7482
/*
7583
* Variables for cost-based vacuum delay. The defaults differ between
@@ -80,6 +88,9 @@ double vacuum_max_eager_freeze_failure_rate;
8088
double vacuum_cost_delay = 0;
8189
int vacuum_cost_limit = 200;
8290

91+
/* Variable for reporting cost-based vacuum delay from parallel workers. */
92+
int64 parallel_vacuum_worker_delay_ns = 0;
93+
8394
/*
8495
* VacuumFailsafeActive is a defined as a global so that we can determine
8596
* whether or not to re-enable cost-based vacuum delay when vacuuming a table.
@@ -2416,13 +2427,66 @@ vacuum_delay_point(bool is_analyze)
24162427
/* Nap if appropriate */
24172428
if (msec > 0)
24182429
{
2430+
instr_time delay_start;
2431+
24192432
if (msec > vacuum_cost_delay * 4)
24202433
msec = vacuum_cost_delay * 4;
24212434

2435+
if (track_cost_delay_timing)
2436+
INSTR_TIME_SET_CURRENT(delay_start);
2437+
24222438
pgstat_report_wait_start(WAIT_EVENT_VACUUM_DELAY);
24232439
pg_usleep(msec * 1000);
24242440
pgstat_report_wait_end();
24252441

2442+
if (track_cost_delay_timing)
2443+
{
2444+
instr_time delay_end;
2445+
instr_time delay;
2446+
2447+
INSTR_TIME_SET_CURRENT(delay_end);
2448+
INSTR_TIME_SET_ZERO(delay);
2449+
INSTR_TIME_ACCUM_DIFF(delay, delay_end, delay_start);
2450+
2451+
/*
2452+
* For parallel workers, we only report the delay time every once
2453+
* in a while to avoid overloading the leader with messages and
2454+
* interrupts.
2455+
*/
2456+
if (IsParallelWorker())
2457+
{
2458+
static instr_time last_report_time;
2459+
instr_time time_since_last_report;
2460+
2461+
Assert(!is_analyze);
2462+
2463+
/* Accumulate the delay time */
2464+
parallel_vacuum_worker_delay_ns += INSTR_TIME_GET_NANOSEC(delay);
2465+
2466+
/* Calculate interval since last report */
2467+
INSTR_TIME_SET_ZERO(time_since_last_report);
2468+
INSTR_TIME_ACCUM_DIFF(time_since_last_report, delay_end, last_report_time);
2469+
2470+
/* If we haven't reported in a while, do so now */
2471+
if (INSTR_TIME_GET_NANOSEC(time_since_last_report) >=
2472+
PARALLEL_VACUUM_DELAY_REPORT_INTERVAL_NS)
2473+
{
2474+
pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_DELAY_TIME,
2475+
parallel_vacuum_worker_delay_ns);
2476+
2477+
/* Reset variables */
2478+
last_report_time = delay_end;
2479+
parallel_vacuum_worker_delay_ns = 0;
2480+
}
2481+
}
2482+
else if (is_analyze)
2483+
pgstat_progress_incr_param(PROGRESS_ANALYZE_DELAY_TIME,
2484+
INSTR_TIME_GET_NANOSEC(delay));
2485+
else
2486+
pgstat_progress_incr_param(PROGRESS_VACUUM_DELAY_TIME,
2487+
INSTR_TIME_GET_NANOSEC(delay));
2488+
}
2489+
24262490
/*
24272491
* We don't want to ignore postmaster death during very long vacuums
24282492
* with vacuum_cost_delay configured. We can't use the usual

‎src/backend/commands/vacuumparallel.c

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1094,6 +1094,11 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc)
10941094
InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber],
10951095
&wal_usage[ParallelWorkerNumber]);
10961096

1097+
/* Report any remaining cost-based vacuum delay time */
1098+
if (track_cost_delay_timing)
1099+
pgstat_progress_parallel_incr_param(PROGRESS_VACUUM_DELAY_TIME,
1100+
parallel_vacuum_worker_delay_ns);
1101+
10971102
TidStoreDetach(dead_items);
10981103

10991104
/* Pop the error context stack */

‎src/backend/utils/misc/guc_tables.c

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1471,6 +1471,15 @@ struct config_bool ConfigureNamesBool[] =
14711471
true,
14721472
NULL, NULL, NULL
14731473
},
1474+
{
1475+
{"track_cost_delay_timing", PGC_SUSET, STATS_CUMULATIVE,
1476+
gettext_noop("Collects timing statistics for cost-based vacuum delay."),
1477+
NULL
1478+
},
1479+
&track_cost_delay_timing,
1480+
false,
1481+
NULL, NULL, NULL
1482+
},
14741483
{
14751484
{"track_io_timing", PGC_SUSET, STATS_CUMULATIVE,
14761485
gettext_noop("Collects timing statistics for database I/O activity."),

‎src/backend/utils/misc/postgresql.conf.sample

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -635,6 +635,7 @@
635635
#track_activities = on
636636
#track_activity_query_size = 1024 # (change requires restart)
637637
#track_counts = on
638+
#track_cost_delay_timing = off
638639
#track_io_timing = off
639640
#track_wal_io_timing = off
640641
#track_functions = none # none, pl, all

‎src/include/catalog/catversion.h

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,6 @@
5757
*/
5858

5959
/* yyyymmddN */
60-
#define CATALOG_VERSION_NO 202502111
60+
#define CATALOG_VERSION_NO 202502112
6161

6262
#endif

‎src/include/commands/progress.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
#define PROGRESS_VACUUM_NUM_DEAD_ITEM_IDS 7
2929
#define PROGRESS_VACUUM_INDEXES_TOTAL 8
3030
#define PROGRESS_VACUUM_INDEXES_PROCESSED 9
31+
#define PROGRESS_VACUUM_DELAY_TIME 10
3132

3233
/* Phases of vacuum (as advertised via PROGRESS_VACUUM_PHASE) */
3334
#define PROGRESS_VACUUM_PHASE_SCAN_HEAP 1
@@ -46,6 +47,7 @@
4647
#define PROGRESS_ANALYZE_CHILD_TABLES_TOTAL 5
4748
#define PROGRESS_ANALYZE_CHILD_TABLES_DONE 6
4849
#define PROGRESS_ANALYZE_CURRENT_CHILD_TABLE_RELID 7
50+
#define PROGRESS_ANALYZE_DELAY_TIME 8
4951

5052
/* Phases of analyze (as advertised via PROGRESS_ANALYZE_PHASE) */
5153
#define PROGRESS_ANALYZE_PHASE_ACQUIRE_SAMPLE_ROWS 1

‎src/include/commands/vacuum.h

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -303,6 +303,7 @@ extern PGDLLIMPORT int vacuum_multixact_freeze_min_age;
303303
extern PGDLLIMPORT int vacuum_multixact_freeze_table_age;
304304
extern PGDLLIMPORT int vacuum_failsafe_age;
305305
extern PGDLLIMPORT int vacuum_multixact_failsafe_age;
306+
extern PGDLLIMPORT bool track_cost_delay_timing;
306307

307308
/*
308309
* Relevant for vacuums implementing eager scanning. Normal vacuums may
@@ -330,6 +331,8 @@ extern PGDLLIMPORT bool VacuumFailsafeActive;
330331
extern PGDLLIMPORT double vacuum_cost_delay;
331332
extern PGDLLIMPORT int vacuum_cost_limit;
332333

334+
extern PGDLLIMPORT int64 parallel_vacuum_worker_delay_ns;
335+
333336
/* in commands/vacuum.c */
334337
extern void ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel);
335338
extern void vacuum(List *relations, VacuumParams *params,

‎src/test/regress/expected/rules.out

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1932,7 +1932,8 @@ pg_stat_progress_analyze| SELECT s.pid,
19321932
s.param5 AS ext_stats_computed,
19331933
s.param6 AS child_tables_total,
19341934
s.param7 AS child_tables_done,
1935-
(s.param8)::oid AS current_child_table_relid
1935+
(s.param8)::oid AS current_child_table_relid,
1936+
((s.param9)::double precision / (1000000)::double precision) AS delay_time
19361937
FROM (pg_stat_get_progress_info('ANALYZE'::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)
19371938
LEFT JOIN pg_database d ON ((s.datid = d.oid)));
19381939
pg_stat_progress_basebackup| SELECT pid,
@@ -2062,7 +2063,8 @@ pg_stat_progress_vacuum| SELECT s.pid,
20622063
s.param7 AS dead_tuple_bytes,
20632064
s.param8 AS num_dead_item_ids,
20642065
s.param9 AS indexes_total,
2065-
s.param10 AS indexes_processed
2066+
s.param10 AS indexes_processed,
2067+
((s.param11)::double precision / (1000000)::double precision) AS delay_time
20662068
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)
20672069
LEFT JOIN pg_database d ON ((s.datid = d.oid)));
20682070
pg_stat_recovery_prefetch| SELECT stats_reset,

0 commit comments

Comments
 (0)