aio: wal: extend pg_stat_wal.
authorAndres Freund <andres@anarazel.de>
Thu, 31 Dec 2020 04:47:45 +0000 (20:47 -0800)
committerAndres Freund <andres@anarazel.de>
Mon, 11 Jan 2021 23:09:15 +0000 (15:09 -0800)
Author:
Reviewed-By:
Discussion: https://postgr.es/m/
Backpatch:

src/backend/access/transam/xlog.c
src/backend/catalog/system_views.sql
src/backend/commands/explain.c
src/backend/executor/instrument.c
src/backend/postmaster/pgstat.c
src/backend/utils/adt/pgstatfuncs.c
src/include/catalog/pg_proc.dat
src/include/executor/instrument.h
src/include/pgstat.h
src/test/regress/expected/rules.out

index cd7ad390de6f19be486a43d59d9a03385daaf475..7456ed536ab7673c9d62a3504bb6752692060567 100644 (file)
@@ -1600,6 +1600,8 @@ PadPartialPage(XLogRecPtr upto, XLogRecPtr *final_pad)
    if (padded)
    {
        pgWalUsage.wal_bytes += pad_size;
+       pgWalUsage.wal_partial_pad++;
+       pgWalUsage.wal_partial_pad_bytes += pad_size;
 
        *final_pad = XLogBytePosToEndRecPtr(endbytepos);
        return true;
@@ -3031,6 +3033,7 @@ XLogWriteCheckPending(XLogWritePos *write_pos)
                               (uint32)(write_pos->write_init_min >> 32), (uint32) write_pos->write_init_min),
                        errhidestmt(true),
                        errhidecontext(true));
+               pgWalUsage.wal_partial_wait++;
                pgaio_io_wait_ref(&partial_aio_ref, false);
            }
            else
@@ -3048,6 +3051,7 @@ XLogWriteCheckPending(XLogWritePos *write_pos)
                        errhidestmt(true),
                        errhidecontext(true));
 
+               pgWalUsage.wal_partial_wait++;
                pgaio_io_wait_ref(&partial_aio_ref, false);
 
                goto write_out_wait;
@@ -3662,6 +3666,7 @@ XLogWrite(XLogwrtRqst WriteRqstTmp, bool flexible)
    bool        performed_io = false;
    bool        holding_lock = false;
    XLogWritePos write_pos = {0};
+   bool        statted = false;
    bool        did_wait_for_insert = false;
 
    /* normalize request */
@@ -3702,6 +3707,12 @@ xlogwrite_again:
        write_pos.flush_done_min <= LogwrtResult.FlushDone)
    {
        END_CRIT_SECTION();
+
+       if (!statted)
+       {
+           pgWalUsage.wal_already_done_unlocked++;
+           statted = true;
+       }
        return performed_io;
    }
 
@@ -3730,6 +3741,12 @@ xlogwrite_again:
                 (uint32) (LogwrtResult.WriteInit >> 32), (uint32) LogwrtResult.WriteInit);
        }
 
+       if (!statted)
+       {
+           pgWalUsage.wal_just_wait++;
+           statted = true;
+       }
+
        //elog(DEBUG1, "just needed to wait for IO");
        return performed_io;
    }
@@ -3789,10 +3806,12 @@ xlogwrite_again:
    if (!LWLockAcquireOrWait(WALWriteLock, LW_EXCLUSIVE))
    {
        holding_lock = false;
+       pgWalUsage.wal_lock_wait++;
        goto xlogwrite_again;
    }
    else
    {
+       pgWalUsage.wal_lock_immed++;
        holding_lock = true;
    }
 
@@ -3819,6 +3838,8 @@ xlogwrite_again:
 
        }
 
+       pgWalUsage.wal_already_done_locked++;
+
        END_CRIT_SECTION();
        return performed_io;
    }
@@ -3915,6 +3936,8 @@ xlogwrite_again:
        }
 #endif
 
+       pgWalUsage.wal_writes++;
+
        if (XLogWriteIssueWrites(&write_pos, flexible))
        {
            //elog(LOG, "issued writes false: ");
index ceae1d79c502bf7e4b576048409ef1690054e4cc..e040771f5c2f83365eefe973fe16f75cdae97a64 100644 (file)
@@ -992,12 +992,8 @@ CREATE VIEW pg_stat_bgwriter AS
         pg_stat_get_bgwriter_stat_reset_time() AS stats_reset;
 
 CREATE VIEW pg_stat_wal AS
-    SELECT
-        w.wal_records,
-        w.wal_fpi,
-        w.wal_bytes,
-        w.wal_buffers_full,
-        w.stats_reset
+    /* FIXME: easier to maintain without column names during development */
+    SELECT w.*
     FROM pg_stat_get_wal() w;
 
 CREATE VIEW pg_stat_aio_backends AS
index 5d7eb3574c8237844496006ec84fc41de70b8e34..bcc7be252c6e5f186cc56d9cb6bd810b490419f0 100644 (file)
@@ -3458,6 +3458,9 @@ show_wal_usage(ExplainState *es, const WalUsage *usage)
            if (usage->wal_bytes > 0)
                appendStringInfo(es->str, " bytes=" UINT64_FORMAT,
                                 usage->wal_bytes);
+           if (usage->wal_partial_pad_bytes > 0)
+               appendStringInfo(es->str, " pad_bytes=" UINT64_FORMAT,
+                                usage->wal_partial_pad_bytes);
            appendStringInfoChar(es->str, '\n');
        }
    }
index 3849c12e969c87b0d6e5a48d0ba9752ddd7d4f8b..79d2760cfeaf33b261413eab1c1911a00796e14d 100644 (file)
@@ -271,6 +271,15 @@ WalUsageAdd(WalUsage *dst, WalUsage *add)
    dst->wal_records += add->wal_records;
    dst->wal_fpi += add->wal_fpi;
    dst->wal_buffers_full += add->wal_buffers_full;
+   dst->wal_writes += add->wal_writes;
+   dst->wal_already_done_unlocked += add->wal_already_done_unlocked;
+   dst->wal_already_done_locked += add->wal_already_done_locked;
+   dst->wal_just_wait += add->wal_just_wait;
+   dst->wal_lock_immed += add->wal_lock_immed;
+   dst->wal_lock_wait += add->wal_lock_wait;
+   dst->wal_partial_wait += add->wal_partial_wait;
+   dst->wal_partial_pad += add->wal_partial_pad;
+   dst->wal_partial_pad_bytes += add->wal_partial_pad_bytes;
 }
 
 void
@@ -280,4 +289,13 @@ WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
    dst->wal_records += add->wal_records - sub->wal_records;
    dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
    dst->wal_buffers_full += add->wal_buffers_full - sub->wal_buffers_full;
+   dst->wal_writes += add->wal_writes - sub->wal_writes;
+   dst->wal_already_done_unlocked += add->wal_already_done_unlocked - sub->wal_already_done_unlocked;
+   dst->wal_already_done_locked += add->wal_already_done_locked - sub->wal_already_done_locked;
+   dst->wal_just_wait += add->wal_just_wait - sub->wal_just_wait;
+   dst->wal_lock_immed += add->wal_lock_immed - sub->wal_lock_immed;
+   dst->wal_lock_wait += add->wal_lock_wait - sub->wal_lock_wait;
+   dst->wal_partial_wait += add->wal_partial_wait - sub->wal_partial_wait;
+   dst->wal_partial_pad += add->wal_partial_pad - sub->wal_partial_pad;
+   dst->wal_partial_pad_bytes += add->wal_partial_pad_bytes - sub->wal_partial_pad_bytes;
 }
index 7a0947f10eb3963670caa89769e9832e66877580..954afcf3862559c196ef703ff5f386ae3fcd12b0 100644 (file)
@@ -4639,6 +4639,15 @@ pgstat_send_wal(void)
    WalStats.m_wal_fpi = walusage.wal_fpi;
    WalStats.m_wal_bytes = walusage.wal_bytes;
    WalStats.m_wal_buffers_full = walusage.wal_buffers_full;
+   WalStats.m_wal_writes = walusage.wal_writes;
+   WalStats.m_wal_already_done_unlocked = walusage.wal_already_done_unlocked;
+   WalStats.m_wal_already_done_locked = walusage.wal_already_done_locked;
+   WalStats.m_wal_just_wait = walusage.wal_just_wait;
+   WalStats.m_wal_lock_immed = walusage.wal_lock_immed;
+   WalStats.m_wal_lock_wait = walusage.wal_lock_wait;
+   WalStats.m_wal_partial_wait = walusage.wal_partial_wait;
+   WalStats.m_wal_partial_pad = walusage.wal_partial_pad;
+   WalStats.m_wal_partial_pad_bytes = walusage.wal_partial_pad_bytes;
 
    /*
     * This function can be called even if nothing at all has happened. In
@@ -6829,6 +6838,15 @@ pgstat_recv_wal(PgStat_MsgWal *msg, int len)
    walStats.wal_fpi += msg->m_wal_fpi;
    walStats.wal_bytes += msg->m_wal_bytes;
    walStats.wal_buffers_full += msg->m_wal_buffers_full;
+   walStats.wal_writes += msg->m_wal_writes;
+   walStats.wal_already_done_unlocked += msg->m_wal_already_done_unlocked;
+   walStats.wal_already_done_locked += msg->m_wal_already_done_locked;
+   walStats.wal_just_wait += msg->m_wal_just_wait;
+   walStats.wal_lock_immed += msg->m_wal_lock_immed;
+   walStats.wal_lock_wait += msg->m_wal_lock_wait;
+   walStats.wal_partial_wait += msg->m_wal_partial_wait;
+   walStats.wal_partial_pad += msg->m_wal_partial_pad;
+   walStats.wal_partial_pad_bytes += msg->m_wal_partial_pad_bytes;
 }
 
 /* ----------
index 5c12a165a1535e8d90e12d8f2d31670054b5350c..dd890328cc08d4b7050658e5203651ebf85a0419 100644 (file)
@@ -1705,7 +1705,7 @@ pg_stat_get_buf_alloc(PG_FUNCTION_ARGS)
 Datum
 pg_stat_get_wal(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_COLS   5
+#define PG_STAT_GET_WAL_COLS   14
    TupleDesc   tupdesc;
    Datum       values[PG_STAT_GET_WAL_COLS];
    bool        nulls[PG_STAT_GET_WAL_COLS];
@@ -1726,7 +1726,25 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
                       NUMERICOID, -1, 0);
    TupleDescInitEntry(tupdesc, (AttrNumber) 4, "wal_buffers_full",
                       INT8OID, -1, 0);
-   TupleDescInitEntry(tupdesc, (AttrNumber) 5, "stats_reset",
+   TupleDescInitEntry(tupdesc, (AttrNumber) 5, "wal_writes",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 6, "wal_already_done_unlocked",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 7, "wal_already_done_locked",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 8, "wal_just_wait",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 9, "wal_lock_immed",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 10, "wal_lock_wait",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 11, "wal_partial_wait",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 12, "wal_partial_pad",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 13, "wal_partial_pad_bytes",
+                      INT8OID, -1, 0);
+   TupleDescInitEntry(tupdesc, (AttrNumber) 14, "stats_reset",
                       TIMESTAMPTZOID, -1, 0);
 
    BlessTupleDesc(tupdesc);
@@ -1735,18 +1753,29 @@ pg_stat_get_wal(PG_FUNCTION_ARGS)
    wal_stats = pgstat_fetch_stat_wal();
 
    /* Fill values and NULLs */
-   values[0] = Int64GetDatum(wal_stats->wal_records);
-   values[1] = Int64GetDatum(wal_stats->wal_fpi);
+   values[ 0] = Int64GetDatum(wal_stats->wal_records);
+   values[ 1] = Int64GetDatum(wal_stats->wal_fpi);
 
    /* Convert to numeric. */
    snprintf(buf, sizeof buf, UINT64_FORMAT, wal_stats->wal_bytes);
-   values[2] = DirectFunctionCall3(numeric_in,
+   values[ 2] = DirectFunctionCall3(numeric_in,
                                    CStringGetDatum(buf),
                                    ObjectIdGetDatum(0),
                                    Int32GetDatum(-1));
 
-   values[3] = Int64GetDatum(wal_stats->wal_buffers_full);
-   values[4] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp);
+   values[ 3] = Int64GetDatum(wal_stats->wal_buffers_full);
+
+   values[ 4] = Int64GetDatum(wal_stats->wal_writes);
+   values[ 5] = Int64GetDatum(wal_stats->wal_already_done_unlocked);
+   values[ 6] = Int64GetDatum(wal_stats->wal_already_done_locked);
+   values[ 7] = Int64GetDatum(wal_stats->wal_just_wait);
+   values[ 8] = Int64GetDatum(wal_stats->wal_lock_immed);
+   values[ 9] = Int64GetDatum(wal_stats->wal_lock_wait);
+   values[10] = Int64GetDatum(wal_stats->wal_partial_wait);
+   values[11] = Int64GetDatum(wal_stats->wal_partial_pad);
+   values[12] = Int64GetDatum(wal_stats->wal_partial_pad_bytes);
+
+   values[13] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp);
 
    /* Returns the record as Datum */
    PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls)));
index bc42064bc0e02bfc553ad7b6cef52774ab36d6f1..d3bdce00ace00319a888a59a5420888e7e116029 100644 (file)
 { oid => '1136', descr => 'statistics: information about WAL activity',
   proname => 'pg_stat_get_wal', proisstrict => 'f', provolatile => 's',
   proparallel => 'r', prorettype => 'record', proargtypes => '',
-   proallargtypes => '{int8,int8,numeric,int8,timestamptz}',
-   proargmodes => '{o,o,o,o,o}',
-   proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,stats_reset}',
+   proallargtypes => '{int8,int8,numeric,int8,int8,int8,int8,int8,int8,int8,int8,int8,int8,timestamptz}',
+   proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
+   proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_writes,wal_already_done_unlocked,wal_already_done_locked,wal_just_wait,wal_lock_immed,wal_lock_wait,wal_partial_wait,wal_partial_pad,wal_partial_pad_bytes,stats_reset}',
   prosrc => 'pg_stat_get_wal' },
 
 { oid => '2306', descr => 'statistics: information about SLRU caches',
index 9d90212565dcd817fd9610e359686154fcb89950..62ca398e9d5b8cb800d986e2d1d12be0fe4f0991 100644 (file)
@@ -38,6 +38,15 @@ typedef struct WalUsage
    long        wal_fpi;        /* # of WAL full page images produced */
    uint64      wal_bytes;      /* size of WAL records produced */
    uint64      wal_buffers_full;
+   uint64      wal_writes;
+   uint64      wal_already_done_unlocked;
+   uint64      wal_already_done_locked;
+   uint64      wal_just_wait;
+   uint64      wal_lock_immed;
+   uint64      wal_lock_wait;
+   uint64      wal_partial_wait;
+   uint64      wal_partial_pad;
+   uint64      wal_partial_pad_bytes;
 } WalUsage;
 
 /* Flag bits included in InstrAlloc's instrument_options bitmask */
index f415e1988a346ee13f8a788fc1230d2227d49623..b733c75827e2c2e296e8bd471ea0a5c2d962c1c8 100644 (file)
@@ -463,6 +463,15 @@ typedef struct PgStat_MsgWal
    PgStat_Counter m_wal_fpi;
    uint64      m_wal_bytes;
    PgStat_Counter m_wal_buffers_full;
+   PgStat_Counter m_wal_writes;
+   PgStat_Counter m_wal_already_done_unlocked;
+   PgStat_Counter m_wal_already_done_locked;
+   PgStat_Counter m_wal_just_wait;
+   PgStat_Counter m_wal_lock_immed;
+   PgStat_Counter m_wal_lock_wait;
+   PgStat_Counter m_wal_partial_wait;
+   PgStat_Counter m_wal_partial_pad;
+   PgStat_Counter m_wal_partial_pad_bytes;
 } PgStat_MsgWal;
 
 /* ----------
@@ -805,6 +814,15 @@ typedef struct PgStat_WalStats
    PgStat_Counter wal_fpi;
    uint64      wal_bytes;
    PgStat_Counter wal_buffers_full;
+   PgStat_Counter wal_writes;
+   PgStat_Counter wal_already_done_unlocked;
+   PgStat_Counter wal_already_done_locked;
+   PgStat_Counter wal_just_wait;
+   PgStat_Counter wal_lock_immed;
+   PgStat_Counter wal_lock_wait;
+   PgStat_Counter wal_partial_wait;
+   PgStat_Counter wal_partial_pad;
+   PgStat_Counter wal_partial_pad_bytes;
    TimestampTz stat_reset_timestamp;
 } PgStat_WalStats;
 
index 1183bdac8976480c24e72c4bdd39531baf5f4595..b0abc69e8168c725b2566694a8c2815ad96e75cc 100644 (file)
@@ -2174,8 +2174,17 @@ pg_stat_wal| SELECT w.wal_records,
     w.wal_fpi,
     w.wal_bytes,
     w.wal_buffers_full,
+    w.wal_writes,
+    w.wal_already_done_unlocked,
+    w.wal_already_done_locked,
+    w.wal_just_wait,
+    w.wal_lock_immed,
+    w.wal_lock_wait,
+    w.wal_partial_wait,
+    w.wal_partial_pad,
+    w.wal_partial_pad_bytes,
     w.stats_reset
-   FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, stats_reset);
+   FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_writes, wal_already_done_unlocked, wal_already_done_locked, wal_just_wait, wal_lock_immed, wal_lock_wait, wal_partial_wait, wal_partial_pad, wal_partial_pad_bytes, stats_reset);
 pg_stat_wal_receiver| SELECT s.pid,
     s.status,
     s.receive_start_lsn,