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

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@oss.nttdata.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.


Regards,
-- 
Masahiro Ikeda
NTT DATA CORPORATION