Skip to content

Commit 40b9b95

Browse files
robertmhaasrobertmhaas
committed
New GUC, track_iotiming, to track I/O timings.
Currently, the only way to see the numbers this gathers is via EXPLAIN (ANALYZE, BUFFERS), but the plan is to add visibility through the stats collector and pg_stat_statements in subsequent patches. Ants Aasma, reviewed by Greg Smith, with some further changes by me.
1 parent 98316e2 commit 40b9b95

File tree

8 files changed

+72
-0
lines changed

8 files changed

+72
-0
lines changed

‎doc/src/sgml/config.sgml

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4284,6 +4284,21 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
42844284
</listitem>
42854285
</varlistentry>
42864286

4287+
<varlistentry id="guc-track-iotiming" xreflabel="track_iotiming">
4288+
<term><varname>track_iotiming</varname> (<type>boolean</type>)</term>
4289+
<indexterm>
4290+
<primary><varname>track_iotiming</> configuration parameter</primary>
4291+
</indexterm>
4292+
<listitem>
4293+
<para>
4294+
Enables timing of database I/O calls. This parameter is off by
4295+
default, because it will repeatedly query the operating system for
4296+
the current time, which may cause significant overhead on some
4297+
platforms. Only superusers can change this setting.
4298+
</para>
4299+
</listitem>
4300+
</varlistentry>
4301+
42874302
<varlistentry id="guc-track-functions" xreflabel="track_functions">
42884303
<term><varname>track_functions</varname> (<type>enum</type>)</term>
42894304
<indexterm>

‎src/backend/commands/explain.c

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1236,6 +1236,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
12361236
usage->local_blks_written > 0);
12371237
bool has_temp = (usage->temp_blks_read > 0 ||
12381238
usage->temp_blks_written > 0);
1239+
bool has_timing = (!INSTR_TIME_IS_ZERO(usage->time_read) ||
1240+
!INSTR_TIME_IS_ZERO(usage->time_write));
12391241

12401242
/* Show only positive counter values. */
12411243
if (has_shared || has_local || has_temp)
@@ -1291,6 +1293,20 @@ ExplainNode(PlanState *planstate, List *ancestors,
12911293
}
12921294
appendStringInfoChar(es->str, '\n');
12931295
}
1296+
1297+
/* As above, show only positive counter values. */
1298+
if (has_timing)
1299+
{
1300+
appendStringInfoSpaces(es->str, es->indent * 2);
1301+
appendStringInfoString(es->str, "I/O Timings:");
1302+
if (!INSTR_TIME_IS_ZERO(usage->time_read))
1303+
appendStringInfo(es->str, " read=%0.2f",
1304+
INSTR_TIME_GET_MILLISEC(usage->time_read));
1305+
if (!INSTR_TIME_IS_ZERO(usage->time_write))
1306+
appendStringInfo(es->str, " write=%0.2f",
1307+
INSTR_TIME_GET_MILLISEC(usage->time_write));
1308+
appendStringInfoChar(es->str, '\n');
1309+
}
12941310
}
12951311
else
12961312
{
@@ -1304,6 +1320,8 @@ ExplainNode(PlanState *planstate, List *ancestors,
13041320
ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es);
13051321
ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es);
13061322
ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es);
1323+
ExplainPropertyFloat("I/O Read Time", INSTR_TIME_GET_MILLISEC(usage->time_read), 3, es);
1324+
ExplainPropertyFloat("I/O Write Time", INSTR_TIME_GET_MILLISEC(usage->time_write), 3, es);
13071325
}
13081326
}
13091327

‎src/backend/executor/instrument.c

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -145,4 +145,6 @@ BufferUsageAccumDiff(BufferUsage *dst,
145145
dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
146146
dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
147147
dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
148+
INSTR_TIME_ACCUM_DIFF(dst->time_read, add->time_read, sub->time_read);
149+
INSTR_TIME_ACCUM_DIFF(dst->time_write, add->time_write, sub->time_write);
148150
}

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

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@
6767
bool zero_damaged_pages = false;
6868
int bgwriter_lru_maxpages = 100;
6969
double bgwriter_lru_multiplier = 2.0;
70+
bool track_iotiming = false;
7071

7172
/*
7273
* How many buffers PrefetchBuffer callers should try to stay ahead of their
@@ -437,8 +438,21 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum,
437438
MemSet((char *) bufBlock, 0, BLCKSZ);
438439
else
439440
{
441+
instr_time io_start,
442+
io_time;
443+
444+
if (track_iotiming)
445+
INSTR_TIME_SET_CURRENT(io_start);
446+
440447
smgrread(smgr, forkNum, blockNum, (char *) bufBlock);
441448

449+
if (track_iotiming)
450+
{
451+
INSTR_TIME_SET_CURRENT(io_time);
452+
INSTR_TIME_SUBTRACT(io_time, io_start);
453+
INSTR_TIME_ADD(pgBufferUsage.time_read, io_time);
454+
}
455+
442456
/* check for garbage data */
443457
if (!PageHeaderIsValid((PageHeader) bufBlock))
444458
{
@@ -1874,6 +1888,7 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
18741888
{
18751889
XLogRecPtr recptr;
18761890
ErrorContextCallback errcontext;
1891+
instr_time io_start, io_end;
18771892

18781893
/*
18791894
* Acquire the buffer's io_in_progress lock. If StartBufferIO returns
@@ -1921,12 +1936,21 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
19211936
buf->flags &= ~BM_JUST_DIRTIED;
19221937
UnlockBufHdr(buf);
19231938

1939+
if (track_iotiming)
1940+
INSTR_TIME_SET_CURRENT(io_start);
1941+
19241942
smgrwrite(reln,
19251943
buf->tag.forkNum,
19261944
buf->tag.blockNum,
19271945
(char *) BufHdrGetBlock(buf),
19281946
false);
19291947

1948+
if (track_iotiming)
1949+
{
1950+
INSTR_TIME_SET_CURRENT(io_end);
1951+
INSTR_TIME_ACCUM_DIFF(pgBufferUsage.time_write, io_end, io_start);
1952+
}
1953+
19301954
pgBufferUsage.shared_blks_written++;
19311955

19321956
/*

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

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1018,6 +1018,15 @@ static struct config_bool ConfigureNamesBool[] =
10181018
true,
10191019
NULL, NULL, NULL
10201020
},
1021+
{
1022+
{"track_iotiming", PGC_SUSET, STATS_COLLECTOR,
1023+
gettext_noop("Collects timing information for database IO activity."),
1024+
NULL
1025+
},
1026+
&track_iotiming,
1027+
false,
1028+
NULL, NULL, NULL
1029+
},
10211030

10221031
{
10231032
{"update_process_title", PGC_SUSET, STATS_COLLECTOR,

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -424,6 +424,7 @@
424424

425425
#track_activities = on
426426
#track_counts = on
427+
#track_iotiming = off
427428
#track_functions = none # none, pl, all
428429
#track_activity_query_size = 1024 # (change requires restart)
429430
#update_process_title = on

‎src/include/executor/instrument.h

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,8 @@ typedef struct BufferUsage
2828
long local_blks_written; /* # of local disk blocks written */
2929
long temp_blks_read; /* # of temp blocks read */
3030
long temp_blks_written; /* # of temp blocks written */
31+
instr_time time_read; /* time spent reading */
32+
instr_time time_write; /* time spent writing */
3133
} BufferUsage;
3234

3335
/* Flag bits included in InstrAlloc's instrument_options bitmask */

‎src/include/storage/bufmgr.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,7 @@ extern PGDLLIMPORT int NBuffers;
4848
extern bool zero_damaged_pages;
4949
extern int bgwriter_lru_maxpages;
5050
extern double bgwriter_lru_multiplier;
51+
extern bool track_iotiming;
5152
extern int target_prefetch_pages;
5253

5354
/* in buf_init.c */

0 commit comments

Comments
 (0)