Re: About to add WAL write/fsync statistics to pg_stat_wal view

On 2021/03/08 19:42, Masahiro Ikeda wrote:
> On 2021-03-08 13:44, Fujii Masao wrote:
>> On 2021/03/05 19:54, Masahiro Ikeda wrote:
>>> On 2021-03-05 12:47, Fujii Masao wrote:
>>>> On 2021/03/05 8:38, Masahiro Ikeda wrote:
>>>>> On 2021-03-05 01:02, Fujii Masao wrote:
>>>>>> On 2021/03/04 16:14, Masahiro Ikeda wrote:
>>>>>>> On 2021-03-03 20:27, Masahiro Ikeda wrote:
>>>>>>>> On 2021-03-03 16:30, Fujii Masao wrote:
>>>>>>>>> On 2021/03/03 14:33, Masahiro Ikeda wrote:
>>>>>>>>>> On 2021-02-24 16:14, Fujii Masao wrote:
>>>>>>>>>>> On 2021/02/15 11:59, Masahiro Ikeda wrote:
>>>>>>>>>>>> On 2021-02-10 00:51, David G. Johnston wrote:
>>>>>>>>>>>>> On Thu, Feb 4, 2021 at 4:45 PM Masahiro Ikeda
>>>>>>>>>>>>> <ikedamsh(at)oss(dot)nttdata(dot)com> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> I pgindented the patches.
>>>>>>>>>>>>>
>>>>>>>>>>>>> ... <function>XLogWrite</function>, which is invoked during an
>>>>>>>>>>>>> <function>XLogFlush</function> request (see ...).  This is also
>>>>>>>>>>>>> incremented by the WAL receiver during replication.
>>>>>>>>>>>>>
>>>>>>>>>>>>> ("which normally called" should be "which is normally called" or
>>>>>>>>>>>>> "which normally is called" if you want to keep true to the original)
>>>>>>>>>>>>> You missed the adding the space before an opening parenthesis here and
>>>>>>>>>>>>> elsewhere (probably copy-paste)
>>>>>>>>>>>>>
>>>>>>>>>>>>> is ether -> is either
>>>>>>>>>>>>> "This parameter is off by default as it will repeatedly query the
>>>>>>>>>>>>> operating system..."
>>>>>>>>>>>>> ", because" -> "as"
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks, I fixed them.
>>>>>>>>>>>>
>>>>>>>>>>>>> wal_write_time and the sync items also need the note: "This is also
>>>>>>>>>>>>> incremented by the WAL receiver during replication."
>>>>>>>>>>>>
>>>>>>>>>>>> I skipped changing it since I separated the stats for the WAL receiver
>>>>>>>>>>>> in pg_stat_wal_receiver.
>>>>>>>>>>>>
>>>>>>>>>>>>> "The number of times it happened..." -> " (the tally of this event is
>>>>>>>>>>>>> reported in wal_buffers_full in....) This is undesirable because ..."
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks, I fixed it.
>>>>>>>>>>>>
>>>>>>>>>>>>> I notice that the patch for WAL receiver doesn't require explicitly
>>>>>>>>>>>>> computing the sync statistics but does require computing the write
>>>>>>>>>>>>> statistics.  This is because of the presence of issue_xlog_fsync but
>>>>>>>>>>>>> absence of an equivalent pg_xlog_pwrite.  Additionally, I observe that
>>>>>>>>>>>>> the XLogWrite code path calls pgstat_report_wait_*() while the WAL
>>>>>>>>>>>>> receiver path does not.  It seems technically straight-forward to
>>>>>>>>>>>>> refactor here to avoid the almost-duplicated logic in the two places,
>>>>>>>>>>>>> though I suspect there may be a trade-off for not adding another
>>>>>>>>>>>>> function call to the stack given the importance of WAL processing
>>>>>>>>>>>>> (though that seems marginalized compared to the cost of actually
>>>>>>>>>>>>> writing the WAL).  Or, as Fujii noted, go the other way and don't have
>>>>>>>>>>>>> any shared code between the two but instead implement the WAL receiver
>>>>>>>>>>>>> one to use pg_stat_wal_receiver instead.  In either case, this
>>>>>>>>>>>>> half-and-half implementation seems undesirable.
>>>>>>>>>>>>
>>>>>>>>>>>> OK, as Fujii-san mentioned, I separated the WAL receiver stats.
>>>>>>>>>>>> (v10-0002-Makes-the-wal-receiver-report-WAL-statistics.patch)
>>>>>>>>>>>
>>>>>>>>>>> Thanks for updating the patches!
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>> I added the infrastructure code to communicate the WAL receiver stats messages between the WAL receiver and the stats collector, and
>>>>>>>>>>>> the stats for WAL receiver is counted in pg_stat_wal_receiver.
>>>>>>>>>>>> What do you think?
>>>>>>>>>>>
>>>>>>>>>>> On second thought, this idea seems not good. Because those stats are
>>>>>>>>>>> collected between multiple walreceivers, but other values in
>>>>>>>>>>> pg_stat_wal_receiver is only related to the walreceiver process running
>>>>>>>>>>> at that moment. IOW, it seems strange that some values show dynamic
>>>>>>>>>>> stats and the others show collected stats, even though they are in
>>>>>>>>>>> the same view pg_stat_wal_receiver. Thought?
>>>>>>>>>>
>>>>>>>>>> OK, I fixed it.
>>>>>>>>>> The stats collected in the WAL receiver is exposed in pg_stat_wal view in v11 patch.
>>>>>>>>>
>>>>>>>>> Thanks for updating the patches! I'm now reading 001 patch.
>>>>>>>>>
>>>>>>>>> +    /* Check whether the WAL file was synced to disk right now */
>>>>>>>>> +    if (enableFsync &&
>>>>>>>>> +        (sync_method == SYNC_METHOD_FSYNC ||
>>>>>>>>> +         sync_method == SYNC_METHOD_FSYNC_WRITETHROUGH ||
>>>>>>>>> +         sync_method == SYNC_METHOD_FDATASYNC))
>>>>>>>>> +    {
>>>>>>>>>
>>>>>>>>> Isn't it better to make issue_xlog_fsync() return immediately
>>>>>>>>> if enableFsync is off, sync_method is open_sync or open_data_sync,
>>>>>>>>> to simplify the code more?
>>>>>>>>
>>>>>>>> Thanks for the comments.
>>>>>>>> I added the above code in v12 patch.
>>>>>>>>
>>>>>>>>>
>>>>>>>>> +        /*
>>>>>>>>> +         * Send WAL statistics only if WalWriterDelay has elapsed to minimize
>>>>>>>>> +         * the overhead in WAL-writing.
>>>>>>>>> +         */
>>>>>>>>> +        if (rc & WL_TIMEOUT)
>>>>>>>>> +            pgstat_send_wal();
>>>>>>>>>
>>>>>>>>> On second thought, this change means that it always takes wal_writer_delay
>>>>>>>>> before walwriter's WAL stats is sent after XLogBackgroundFlush() is called.
>>>>>>>>> For example, if wal_writer_delay is set to several seconds, some values in
>>>>>>>>> pg_stat_wal would be not up-to-date meaninglessly for those seconds.
>>>>>>>>> So I'm thinking to withdraw my previous comment and it's ok to send
>>>>>>>>> the stats every after XLogBackgroundFlush() is called. Thought?
>>>>>>>>
>>>>>>>> Thanks, I didn't notice that.
>>>>>>>>
>>>>>>>> Although PGSTAT_STAT_INTERVAL is 500msec, wal_writer_delay's
>>>>>>>> default value is 200msec and it may be set shorter time.
>>>>>>
>>>>>> Yeah, if wal_writer_delay is set to very small value, there is a risk
>>>>>> that the WAL stats are sent too frequently. I agree that's a problem.
>>>>>>
>>>>>>>>
>>>>>>>> Why don't to make another way to check the timestamp?
>>>>>>>>
>>>>>>>> +               /*
>>>>>>>> +                * Don't send a message unless it's been at least
>>>>>>>> PGSTAT_STAT_INTERVAL
>>>>>>>> +                * msec since we last sent one
>>>>>>>> +                */
>>>>>>>> +               now = GetCurrentTimestamp();
>>>>>>>> +               if (TimestampDifferenceExceeds(last_report, now,
>>>>>>>> PGSTAT_STAT_INTERVAL))
>>>>>>>> +               {
>>>>>>>> +                       pgstat_send_wal();
>>>>>>>> +                       last_report = now;
>>>>>>>> +               }
>>>>>>>> +
>>>>>>>>
>>>>>>>> Although I worried that it's better to add the check code in pgstat_send_wal(),
>>>>>>
>>>>>> Agreed.
>>>>>>
>>>>>>>> I didn't do so because to avoid to double check PGSTAT_STAT_INTERVAL.
>>>>>>>> pgstat_send_wal() is invoked pg_report_stat() and it already checks the
>>>>>>>> PGSTAT_STAT_INTERVAL.
>>>>>>
>>>>>> I think that we can do that. What about the attached patch?
>>>>>
>>>>> Thanks, I thought it's better.
>>>>>
>>>>>
>>>>>>> I forgot to remove an unused variable.
>>>>>>> The attached v13 patch is fixed.
>>>>>>
>>>>>> Thanks for updating the patch!
>>>>>>
>>>>>> +        w.wal_write,
>>>>>> +        w.wal_write_time,
>>>>>> +        w.wal_sync,
>>>>>> +        w.wal_sync_time,
>>>>>>
>>>>>> It's more natural to put wal_write_time and wal_sync_time next to
>>>>>> each other? That is, what about the following order of columns?
>>>>>>
>>>>>> wal_write
>>>>>> wal_sync
>>>>>> wal_write_time
>>>>>> wal_sync_time
>>>>>
>>>>> Yes, I fixed it.
>>>>>
>>>>>> -        case SYNC_METHOD_OPEN:
>>>>>> -        case SYNC_METHOD_OPEN_DSYNC:
>>>>>> -            /* write synced it already */
>>>>>> -            break;
>>>>>>
>>>>>> IMO it's better to add Assert(false) here to ensure that we never reach
>>>>>> here, as follows. Thought?
>>>>>>
>>>>>> +        case SYNC_METHOD_OPEN:
>>>>>> +        case SYNC_METHOD_OPEN_DSYNC:
>>>>>> +            /* not reachable */
>>>>>> +            Assert(false);
>>>>>
>>>>> I agree.
>>>>>
>>>>>
>>>>>> Even when a backend exits, it sends the stats via pgstat_beshutdown_hook().
>>>>>> On the other hand, walwriter doesn't do that. Walwriter also should send
>>>>>> the stats even at its exit? Otherwise some stats can fail to be collected.
>>>>>> But ISTM that this issue existed from before, for example checkpointer
>>>>>> doesn't call pgstat_send_bgwriter() at its exit, so it's overkill to fix
>>>>>> this issue in this patch?
>>>>>
>>>>> Thanks, I thought it's better to do so.
>>>>> I added the shutdown hook for the walwriter and the checkpointer in v14-0003 patch.
>>>>
>>>> Thanks!
>>>>
>>>> Seems you forgot to include the changes of expected/rules.out in 0001 patch,
>>>> and which caused the regression test to fail. Attached is the updated version
>>>> of the patch. I included expected/rules.out in it.
>>>
>>> Sorry.
>>>
>>>> +    PgStat_Counter m_wal_write_time;    /* time spend writing wal records in
>>>> +                                         * micro seconds */
>>>> +    PgStat_Counter m_wal_sync_time; /* time spend syncing wal records in micro
>>>> +                                     * seconds */
>>>>
>>>> IMO "spend" should be "spent". Also "micro seconds" should be "microseconds"
>>>> in sake of consistent with other comments in pgstat.h. I fixed them.
>>>
>>> Thanks.
>>>
>>>> Regarding pgstat_report_wal() and pgstat_send_wal(), I found one bug. Even
>>>> when pgstat_send_wal() returned without sending any message,
>>>> pgstat_report_wal() saved current pgWalUsage and that counter was used for
>>>> the subsequent calculation of WAL usage. This caused some counters not to
>>>> be sent to the collector. This is a bug that I added. I fixed this bug.
>>>
>>> Thanks.
>>>
>>>
>>>> +    walStats.wal_write += msg->m_wal_write;
>>>> +    walStats.wal_write_time += msg->m_wal_write_time;
>>>> +    walStats.wal_sync += msg->m_wal_sync;
>>>> +    walStats.wal_sync_time += msg->m_wal_sync_time;
>>>>
>>>> I changed the order of the above in pgstat.c so that wal_write_time and
>>>> wal_sync_time are placed in next to each other.
>>>
>>> I forgot to fix them, thanks.
>>>
>>>
>>>> The followings are the comments for the docs part. I've not updated this
>>>> in the patch yet because I'm not sure how to change them for now.
>>>> +       Number of times WAL buffers were written out to disk via
>>>> +       <function>XLogWrite</function>, which is invoked during an
>>>> +       <function>XLogFlush</function> request (see <xref
>>>> linkend="wal-configuration"/>)
>>>> +      </para></entry>
>>>>
>>>> XLogWrite() can be invoked during the functions other than XLogFlush().
>>>> For example, XLogBackgroundFlush(). So the above description might be
>>>> confusing?
>>>>
>>>> +       Number of times WAL files were synced to disk via
>>>> +       <function>issue_xlog_fsync</function>, which is invoked during an
>>>> +       <function>XLogFlush</function> request (see <xref
>>>> linkend="wal-configuration"/>)
>>>>
>>>> Same as above.
>>>
>>> Yes, why don't you remove "XLogFlush" in the above comments
>>> because XLogWrite() description is covered in wal.sgml?
>>>
>>> But, now it's mentioned only for backend,
>>> I added the comments for the wal writer in the attached patch.
>>>
>>>
>>>> +       while <xref linkend="guc-wal-sync-method"/> was set to one of the
>>>> +       "sync at commit" options (i.e., <literal>fdatasync</literal>,
>>>> +       <literal>fsync</literal>, or <literal>fsync_writethrough</literal>).
>>>>
>>>> Even open_sync and open_datasync do the sync at commit. No? I'm not sure
>>>> if "sync at commit" is right term to indicate fdatasync, fsync and
>>>> fsync_writethrough.
>>>
>>> Yes, why don't you change to the following comments?
>>>
>>> ```
>>>         while <xref linkend="guc-wal-sync-method"/> was set to one of the
>>>         options which specific fsync method is called (i.e., <literal>fdatasync</literal>,
>>>         <literal>fsync</literal>, or <literal>fsync_writethrough</literal>)
>>> ```
>>>
>>>> +       <literal>open_sync</literal>. Units are in milliseconds with
>>>> microsecond resolution.
>>>>
>>>> "with microsecond resolution" part is really necessary?
>>>
>>> I removed it because blk_read_time in pg_stat_database is the same above,
>>> but it doesn't mention it.
>>>
>>>
>>>> +   transaction records are flushed to permanent storage.
>>>> +   <function>XLogFlush</function> calls <function>XLogWrite</function> to write
>>>> +   and <function>issue_xlog_fsync</function> to flush them, which are
>>>> counted as
>>>> +   <literal>wal_write</literal> and <literal>wal_sync</literal> in
>>>> +   <xref linkend="pg-stat-wal-view"/>. On systems with high log output,
>>>>
>>>> This description might cause users to misread that XLogFlush() calls
>>>> issue_xlog_fsync(). Since issue_xlog_fsync() is called by XLogWrite(),
>>>> ISTM that this description needs to be updated.
>>>
>>> I understood. I fixed to mention that XLogWrite()
>>> calls issue_xlog_fsync().
>>>
>>>
>>>> Each line in the above seems to end with a space character.
>>>> This space character should be removed.
>>>
>>> Sorry for that. I removed it.
>>
>> Thanks for updating the patch! I think it's getting good shape!
>> - pid  | wait_event_type | wait_event
>> + pid  | wait_event_type | wait_event
>>
>> This change is not necessary?
>
> No, sorry.
> I removed it by mistake when I remove trailing space characters.
>
>
>> -   every <xref linkend="guc-wal-writer-delay"/> milliseconds.
>> +   every <xref linkend="guc-wal-writer-delay"/> milliseconds, which calls
>> +   <function>XLogWrite</function> to write and <function>XLogWrite</function>
>> +   <function>issue_xlog_fsync</function> to flush them. They are counted as
>> +   <literal>wal_write</literal> and <literal>wal_sync</literal> in
>> +   <xref linkend="pg-stat-wal-view"/>.
>>
>> Isn't it better to avoid using the terms like XLogWrite or issue_xlog_fsync
>> before explaining what they are? They are explained later. At least for me
>> I'm ok without this change.
>
> OK. I removed them and add a new paragraph.
>
>
>> -   to write (move to kernel cache) a few filled <acronym>WAL</acronym>
>> -   buffers. This is undesirable because <function>XLogInsertRecord</function>
>> +   to call <function>XLogWrite</function> to write (move to kernel cache) a
>> +   few filled <acronym>WAL</acronym> buffers (the tally of this event
>> is reported in
>> +   <literal>wal_buffers_full</literal> in <xref linkend="pg-stat-wal-view"/>).
>> +   This is undesirable because <function>XLogInsertRecord</function>
>>
>> This paragraph explains the relationshp between WAL writes and WAL
>> buffers. I don't think it's good to add different context to this
>> paragraph. Instead, what about adding new paragraph like the follwing?
>>
>> ----------------------------------
>> When track_wal_io_timing is enabled, the total amounts of time
>> XLogWrite writes and issue_xlog_fsync syncs WAL data to disk are
>> counted as wal_write_time and wal_sync_time in pg_stat_wal view,
>> respectively. XLogWrite is normally called by XLogInsertRecord (when
>> there is no space for the new record in WAL buffers), XLogFlush and
>> the WAL writer, to write WAL buffers to disk and call
>> issue_xlog_fsync. If wal_sync_method is either open_datasync or
>> open_sync, a write operation in XLogWrite guarantees to sync written
>> WAL data to disk and issue_xlog_fsync does nothing. If wal_sync_method
>> is either fdatasync, fsync, or fsync_writethrough, the write operation
>> moves WAL buffer to kernel cache and issue_xlog_fsync syncs WAL files
>> to disk. Regardless of the setting of track_wal_io_timing, the numbers
>> of times XLogWrite writes and issue_xlog_fsync syncs WAL data to disk
>> are also counted as wal_write and wal_sync in pg_stat_wal,
>> respectively.
>> ----------------------------------
>
> Thanks, I agree it's better.
>
>
>> +       <function>issue_xlog_fsync</function> (see <xref
>> linkend="wal-configuration"/>)
>>
>> "request" should be place just before "(see"?
>
> Yes, thanks.
>
>
>
>> +       Number of times WAL files were synced to disk via
>> +       <function>issue_xlog_fsync</function> (see <xref
>> linkend="wal-configuration"/>)
>> +       while <xref linkend="guc-wal-sync-method"/> was set to one of the
>> +       options which specific fsync method is called (i.e.,
>> <literal>fdatasync</literal>,
>> +       <literal>fsync</literal>, or <literal>fsync_writethrough</literal>).
>>
>> Isn't it better to mention the case of fsync=off? What about the following?
>>
>> ----------------------------------
>> Number of times WAL files were synced to disk via issue_xlog_fsync
>> (see ...). This is zero when fsync is off or wal_sync_method is either
>> open_datasync or open_sync.
>> ----------------------------------
>
> Yes.
>
>
>> +       Total amount of time spent writing WAL buffers were written
>> out to disk via
>>
>> "were written out" is not necessary?
>
> Yes, removed it.
>
>> +       Total amount of time spent syncing WAL files to disk via
>> +       <function>issue_xlog_fsync</function> request (see <xref
>> linkend="wal-configuration"/>)
>> +       while <xref linkend="guc-wal-sync-method"/> was set to one of the
>> +       options which specific fsync method is called (i.e.,
>> <literal>fdatasync</literal>,
>> +       <literal>fsync</literal>, or <literal>fsync_writethrough</literal>).
>> +       Units are in milliseconds.
>> +       This is zero when <xref linkend="guc-track-wal-io-timing"/> is disabled.
>>
>> Isn't it better to explain the case where this counter is zero a bit
>> more clearly as follows?
>>
>> ---------------------
>> This is zero when track_wal_io_timing is disabled, fsync is off, or
>> wal_sync_method is either open_datasync or open_sync.
>> ---------------------
>
> Yes, thanks.

Thanks for updating the patch! I applied cosmetic changes to that.
Patch attached. Barring any objection, I will commit this version.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION