Skip to content

Commit 093e5c5

Browse files
anarazelanarazel
committed
Add writeback to pg_stat_io
28e626b added the concept of IOOps but neglected to include writeback operations. ac8d53d added time spent doing these I/O operations. Without counting writeback, checkpointer write time in the log often differed substantially from that in pg_stat_io. To fix this, add IOOp IOOP_WRITEBACK and track writeback in pg_stat_io. Bumps catversion. Author: Melanie Plageman <melanieplageman@gmail.com> Reviewed-by: Kyotaro Horiguchi <horikyota.ntt@gmail.com> Reported-by: Andres Freund <andres@anarazel.de> Discussion: https://postgr.es/m/20230419172326.dhgyo4wrrhulovt6%40awork3.anarazel.de
1 parent 52676dc commit 093e5c5

File tree

12 files changed

+82
-25
lines changed

12 files changed

+82
-25
lines changed

‎doc/src/sgml/monitoring.sgml

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3867,6 +3867,32 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
38673867
</entry>
38683868
</row>
38693869

3870+
<row>
3871+
<entry role="catalog_table_entry">
3872+
<para role="column_definition">
3873+
<structfield>writebacks</structfield> <type>bigint</type>
3874+
</para>
3875+
<para>
3876+
Number of units of size <varname>op_bytes</varname> which the process
3877+
requested the kernel write out to permanent storage.
3878+
</para>
3879+
</entry>
3880+
</row>
3881+
3882+
<row>
3883+
<entry role="catalog_table_entry">
3884+
<para role="column_definition">
3885+
<structfield>writeback_time</structfield> <type>double precision</type>
3886+
</para>
3887+
<para>
3888+
Time spent in writeback operations in milliseconds (if
3889+
<xref linkend="guc-track-io-timing"/> is enabled, otherwise zero). This
3890+
includes the time spent queueing write-out requests and, potentially,
3891+
the time spent to write out the dirty data.
3892+
</para>
3893+
</entry>
3894+
</row>
3895+
38703896
<row>
38713897
<entry role="catalog_table_entry">
38723898
<para role="column_definition">

‎src/backend/catalog/system_views.sql

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1131,6 +1131,8 @@ SELECT
11311131
b.read_time,
11321132
b.writes,
11331133
b.write_time,
1134+
b.writebacks,
1135+
b.writeback_time,
11341136
b.extends,
11351137
b.extend_time,
11361138
b.op_bytes,

‎src/backend/storage/buffer/bufmgr.c

Lines changed: 25 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1685,7 +1685,7 @@ GetVictimBuffer(BufferAccessStrategy strategy, IOContext io_context)
16851685
FlushBuffer(buf_hdr, NULL, IOOBJECT_RELATION, io_context);
16861686
LWLockRelease(content_lock);
16871687

1688-
ScheduleBufferTagForWriteback(&BackendWritebackContext,
1688+
ScheduleBufferTagForWriteback(&BackendWritebackContext, io_context,
16891689
&buf_hdr->tag);
16901690
}
16911691

@@ -2725,8 +2725,11 @@ BufferSync(int flags)
27252725
CheckpointWriteDelay(flags, (double) num_processed / num_to_scan);
27262726
}
27272727

2728-
/* issue all pending flushes */
2729-
IssuePendingWritebacks(&wb_context);
2728+
/*
2729+
* Issue all pending flushes. Only checkpointer calls BufferSync(), so
2730+
* IOContext will always be IOCONTEXT_NORMAL.
2731+
*/
2732+
IssuePendingWritebacks(&wb_context, IOCONTEXT_NORMAL);
27302733

27312734
pfree(per_ts_stat);
27322735
per_ts_stat = NULL;
@@ -3110,7 +3113,11 @@ SyncOneBuffer(int buf_id, bool skip_recently_used, WritebackContext *wb_context)
31103113

31113114
UnpinBuffer(bufHdr);
31123115

3113-
ScheduleBufferTagForWriteback(wb_context, &tag);
3116+
/*
3117+
* SyncOneBuffer() is only called by checkpointer and bgwriter, so
3118+
* IOContext will always be IOCONTEXT_NORMAL.
3119+
*/
3120+
ScheduleBufferTagForWriteback(wb_context, IOCONTEXT_NORMAL, &tag);
31143121

31153122
return result | BUF_WRITTEN;
31163123
}
@@ -5445,7 +5452,8 @@ WritebackContextInit(WritebackContext *context, int *max_pending)
54455452
* Add buffer to list of pending writeback requests.
54465453
*/
54475454
void
5448-
ScheduleBufferTagForWriteback(WritebackContext *wb_context, BufferTag *tag)
5455+
ScheduleBufferTagForWriteback(WritebackContext *wb_context, IOContext io_context,
5456+
BufferTag *tag)
54495457
{
54505458
PendingWriteback *pending;
54515459

@@ -5471,7 +5479,7 @@ ScheduleBufferTagForWriteback(WritebackContext *wb_context, BufferTag *tag)
54715479
* is now disabled.
54725480
*/
54735481
if (wb_context->nr_pending >= *wb_context->max_pending)
5474-
IssuePendingWritebacks(wb_context);
5482+
IssuePendingWritebacks(wb_context, io_context);
54755483
}
54765484

54775485
#define ST_SORT sort_pending_writebacks
@@ -5489,8 +5497,9 @@ ScheduleBufferTagForWriteback(WritebackContext *wb_context, BufferTag *tag)
54895497
* error out - it's just a hint.
54905498
*/
54915499
void
5492-
IssuePendingWritebacks(WritebackContext *wb_context)
5500+
IssuePendingWritebacks(WritebackContext *wb_context, IOContext io_context)
54935501
{
5502+
instr_time io_start;
54945503
int i;
54955504

54965505
if (wb_context->nr_pending == 0)
@@ -5503,6 +5512,8 @@ IssuePendingWritebacks(WritebackContext *wb_context)
55035512
sort_pending_writebacks(wb_context->pending_writebacks,
55045513
wb_context->nr_pending);
55055514

5515+
io_start = pgstat_prepare_io_time();
5516+
55065517
/*
55075518
* Coalesce neighbouring writes, but nothing else. For that we iterate
55085519
* through the, now sorted, array of pending flushes, and look forward to
@@ -5556,6 +5567,13 @@ IssuePendingWritebacks(WritebackContext *wb_context)
55565567
smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);
55575568
}
55585569

5570+
/*
5571+
* Assume that writeback requests are only issued for buffers containing
5572+
* blocks of permanent relations.
5573+
*/
5574+
pgstat_count_io_op_time(IOOBJECT_RELATION, io_context,
5575+
IOOP_WRITEBACK, io_start, wb_context->nr_pending);
5576+
55595577
wb_context->nr_pending = 0;
55605578
}
55615579

‎src/backend/utils/activity/pgstat_io.c

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -424,6 +424,14 @@ pgstat_tracks_io_op(BackendType bktype, IOObject io_object,
424424
bktype == B_CHECKPOINTER) && io_op == IOOP_EXTEND)
425425
return false;
426426

427+
/*
428+
* Temporary tables are not logged and thus do not require fsync'ing.
429+
* Writeback is not requested for temporary tables.
430+
*/
431+
if (io_object == IOOBJECT_TEMP_RELATION &&
432+
(io_op == IOOP_FSYNC || io_op == IOOP_WRITEBACK))
433+
return false;
434+
427435
/*
428436
* Some IOOps are not valid in certain IOContexts and some IOOps are only
429437
* valid in certain contexts.
@@ -448,12 +456,6 @@ pgstat_tracks_io_op(BackendType bktype, IOObject io_object,
448456
if (strategy_io_context && io_op == IOOP_FSYNC)
449457
return false;
450458

451-
/*
452-
* Temporary tables are not logged and thus do not require fsync'ing.
453-
*/
454-
if (io_context == IOCONTEXT_NORMAL &&
455-
io_object == IOOBJECT_TEMP_RELATION && io_op == IOOP_FSYNC)
456-
return false;
457459

458460
return true;
459461
}

‎src/backend/utils/adt/pgstatfuncs.c

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1268,6 +1268,8 @@ typedef enum io_stat_col
12681268
IO_COL_READ_TIME,
12691269
IO_COL_WRITES,
12701270
IO_COL_WRITE_TIME,
1271+
IO_COL_WRITEBACKS,
1272+
IO_COL_WRITEBACK_TIME,
12711273
IO_COL_EXTENDS,
12721274
IO_COL_EXTEND_TIME,
12731275
IO_COL_CONVERSION,
@@ -1303,6 +1305,8 @@ pgstat_get_io_op_index(IOOp io_op)
13031305
return IO_COL_REUSES;
13041306
case IOOP_WRITE:
13051307
return IO_COL_WRITES;
1308+
case IOOP_WRITEBACK:
1309+
return IO_COL_WRITEBACKS;
13061310
}
13071311

13081312
elog(ERROR, "unrecognized IOOp value: %d", io_op);
@@ -1322,6 +1326,7 @@ pgstat_get_io_time_index(IOOp io_op)
13221326
{
13231327
case IOOP_READ:
13241328
case IOOP_WRITE:
1329+
case IOOP_WRITEBACK:
13251330
case IOOP_EXTEND:
13261331
case IOOP_FSYNC:
13271332
return pgstat_get_io_op_index(io_op) + 1;

‎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 202305172
60+
#define CATALOG_VERSION_NO 202305173
6161

6262
#endif

‎src/include/catalog/pg_proc.dat

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5734,9 +5734,9 @@
57345734
proname => 'pg_stat_get_io', provolatile => 'v',
57355735
prorows => '30', proretset => 't',
57365736
proparallel => 'r', prorettype => 'record', proargtypes => '',
5737-
proallargtypes => '{text,text,text,int8,float8,int8,float8,int8,float8,int8,int8,int8,int8,int8,float8,timestamptz}',
5738-
proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
5739-
proargnames => '{backend_type,object,context,reads,read_time,writes,write_time,extends,extend_time,op_bytes,hits,evictions,reuses,fsyncs,fsync_time,stats_reset}',
5737+
proallargtypes => '{text,text,text,int8,float8,int8,float8,int8,float8,int8,float8,int8,int8,int8,int8,int8,float8,timestamptz}',
5738+
proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
5739+
proargnames => '{backend_type,object,context,reads,read_time,writes,write_time,writebacks,writeback_time,extends,extend_time,op_bytes,hits,evictions,reuses,fsyncs,fsync_time,stats_reset}',
57405740
prosrc => 'pg_stat_get_io' },
57415741

57425742
{ oid => '1136', descr => 'statistics: information about WAL activity',

‎src/include/pgstat.h

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -300,9 +300,10 @@ typedef enum IOOp
300300
IOOP_READ,
301301
IOOP_REUSE,
302302
IOOP_WRITE,
303+
IOOP_WRITEBACK,
303304
} IOOp;
304305

305-
#define IOOP_NUM_TYPES (IOOP_WRITE + 1)
306+
#define IOOP_NUM_TYPES (IOOP_WRITEBACK + 1)
306307

307308
typedef struct PgStat_BktypeIO
308309
{

‎src/include/storage/buf_internals.h

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -388,8 +388,9 @@ extern PGDLLIMPORT CkptSortItem *CkptBufferIds;
388388
*/
389389
/* bufmgr.c */
390390
extern void WritebackContextInit(WritebackContext *context, int *max_pending);
391-
extern void IssuePendingWritebacks(WritebackContext *wb_context);
392-
extern void ScheduleBufferTagForWriteback(WritebackContext *wb_context, BufferTag *tag);
391+
extern void IssuePendingWritebacks(WritebackContext *wb_context, IOContext io_context);
392+
extern void ScheduleBufferTagForWriteback(WritebackContext *wb_context,
393+
IOContext io_context, BufferTag *tag);
393394

394395
/* freelist.c */
395396
extern IOContext IOContextForStrategy(BufferAccessStrategy strategy);

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

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1887,6 +1887,8 @@ pg_stat_io| SELECT backend_type,
18871887
read_time,
18881888
writes,
18891889
write_time,
1890+
writebacks,
1891+
writeback_time,
18901892
extends,
18911893
extend_time,
18921894
op_bytes,
@@ -1896,7 +1898,7 @@ pg_stat_io| SELECT backend_type,
18961898
fsyncs,
18971899
fsync_time,
18981900
stats_reset
1899-
FROM pg_stat_get_io() b(backend_type, object, context, reads, read_time, writes, write_time, extends, extend_time, op_bytes, hits, evictions, reuses, fsyncs, fsync_time, stats_reset);
1901+
FROM pg_stat_get_io() b(backend_type, object, context, reads, read_time, writes, write_time, writebacks, writeback_time, extends, extend_time, op_bytes, hits, evictions, reuses, fsyncs, fsync_time, stats_reset);
19001902
pg_stat_progress_analyze| SELECT s.pid,
19011903
s.datid,
19021904
d.datname,

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1445,15 +1445,15 @@ SELECT pg_stat_have_stats('io', 0, 0);
14451445
t
14461446
(1 row)
14471447

1448-
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(hits) AS io_stats_pre_reset
1448+
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(writebacks) + sum(hits) AS io_stats_pre_reset
14491449
FROM pg_stat_io \gset
14501450
SELECT pg_stat_reset_shared('io');
14511451
pg_stat_reset_shared
14521452
----------------------
14531453

14541454
(1 row)
14551455

1456-
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(hits) AS io_stats_post_reset
1456+
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(writebacks) + sum(hits) AS io_stats_post_reset
14571457
FROM pg_stat_io \gset
14581458
SELECT :io_stats_post_reset < :io_stats_pre_reset;
14591459
?column?

‎src/test/regress/sql/stats.sql

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -716,10 +716,10 @@ SELECT :io_sum_bulkwrite_strategy_extends_after > :io_sum_bulkwrite_strategy_ext
716716

717717
-- Test IO stats reset
718718
SELECT pg_stat_have_stats('io', 0, 0);
719-
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(hits) AS io_stats_pre_reset
719+
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(writebacks) + sum(hits) AS io_stats_pre_reset
720720
FROM pg_stat_io \gset
721721
SELECT pg_stat_reset_shared('io');
722-
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(hits) AS io_stats_post_reset
722+
SELECT sum(evictions) + sum(reuses) + sum(extends) + sum(fsyncs) + sum(reads) + sum(writes) + sum(writebacks) + sum(hits) AS io_stats_post_reset
723723
FROM pg_stat_io \gset
724724
SELECT :io_stats_post_reset < :io_stats_pre_reset;
725725

0 commit comments

Comments
 (0)