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

On 2021/03/11 23:33, Fujii Masao wrote:
>
>
> On 2021/03/11 21:29, Masahiro Ikeda wrote:
>> On 2021-03-11 11:52, Fujii Masao wrote:
>>> On 2021/03/11 9:38, Masahiro Ikeda wrote:
>>>> On 2021-03-10 17:08, Fujii Masao wrote:
>>>>> On 2021/03/10 14:11, Masahiro Ikeda wrote:
>>>>>> On 2021-03-09 17:51, 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 for 0003 patch!
>>>>>>>
>>>>>>> Isn't it overkill to send the stats in the walwriter-exit-callback? IMO we can
>>>>>>> just send the stats only when ShutdownRequestPending is true in the walwriter
>>>>>>> main loop (maybe just before calling HandleMainLoopInterrupts()).
>>>>>>> If we do this, we cannot send the stats when walwriter throws FATAL error.
>>>>>>> But that's ok because FATAL error on walwriter causes the server to crash.
>>>>>>> Thought?
>>>>>>
>>>>>> Thanks for your comments!
>>>>>> Yes, I agree.
>>>>>>
>>>>>>
>>>>>>> Also ISTM that we don't need to use the callback for that purpose in
>>>>>>> checkpointer because of the same reason. That is, we can send the stats
>>>>>>> just after calling ShutdownXLOG(0, 0) in HandleCheckpointerInterrupts().
>>>>>>> Thought?
>>>>>>
>>>>>> Yes, I think so too.
>>>>>>
>>>>>> Since ShutdownXLOG() may create restartpoint or checkpoint,
>>>>>> it might generate WAL records.
>>>>>>
>>>>>>
>>>>>>> I'm now not sure how much useful these changes are. As far as I read pgstat.c,
>>>>>>> when shutdown is requested, the stats collector seems to exit even when
>>>>>>> there are outstanding stats messages. So if checkpointer and walwriter send
>>>>>>> the stats in their last cycles, those stats might not be collected.
>>>>>>>
>>>>>>> On the other hand, I can think that sending the stats in the last cycles would
>>>>>>> improve the situation a bit than now. So I'm inclined to apply those changes...
>>>>>>
>>>>>> I didn't notice that. I agree this is an important aspect.
>>>>>> I understood there is a case that the stats collector exits before the checkpointer
>>>>>> or the walwriter exits and some stats might not be collected.
>>>>>
>>>>> IIUC the stats collector basically exits after checkpointer and walwriter exit.
>>>>> But there seems no guarantee that the stats collector processes
>>>>> all the messages that other processes have sent during the shutdown of
>>>>> the server.
>>>>
>>>> Thanks, I understood the above postmaster behaviors.
>>>>
>>>> PMState manages the status and after checkpointer is exited, the postmaster sends
>>>> SIGQUIT signal to the stats collector if the shutdown mode is smart or fast.
>>>> (IIUC, although the postmaster kill the walsender, the archiver and
>>>> the stats collector at the same time, it's ok because the walsender
>>>> and the archiver doesn't send stats to the stats collector now.)
>>>>
>>>> But, there might be a corner case to lose stats sent by background workers like
>>>> the checkpointer before they exit (although this is not implemented yet.)
>>>>
>>>> For example,
>>>>
>>>> 1. checkpointer send the stats before it exit
>>>> 2. stats collector receive the signal and break before processing
>>>>     the stats message from checkpointer. In this case, 1's message is lost.
>>>> 3. stats collector writes the stats in the statsfiles and exit
>>>>
>>>> Why don't you recheck the coming message is zero just before the 2th procedure?
>>>> (v17-0004-guarantee-to-collect-last-stats-messages.patch)
>>>
>>> Yes, I was thinking the same. This is the straight-forward fix for this issue.
>>> The stats collector should process all the outstanding messages when
>>> normal shutdown is requested, as the patch does. On the other hand,
>>> if immediate shutdown is requested or emergency bailout (by postmaster death)
>>> is requested, maybe the stats collector should skip those processings
>>> and exit immediately.
>>>
>>> But if we implement that, we would need to teach the stats collector
>>> the shutdown type (i.e., normal shutdown or immediate one). Because
>>> currently SIGQUIT is sent to the collector whichever shutdown is requested,
>>> and so the collector cannot distinguish the shutdown type. I'm afraid that
>>> change is a bit overkill for now.
>>>
>>> BTW, I found that the collector calls pgstat_write_statsfiles() even at
>>> emergency bailout case, before exiting. It's not necessary to save
>>> the stats to the file in that case because subsequent server startup does
>>> crash recovery and clears that stats file. So it's better to make
>>> the collector exit immediately without calling pgstat_write_statsfiles()
>>> at emergency bailout case? Probably this should be discussed in other
>>> thread because it's different topic from the feature we're discussing here,
>>> though.
>>
>> IIUC, only the stats collector has another hander for SIGQUIT although
>> other background processes have a common hander for it and just call _exit(2).
>> I thought to guarantee when TerminateChildren(SIGTERM) is invoked, don't make stats
>> collector shutdown before other background processes are shutdown.
>>
>> I will make another thread to discuss that the stats collector should know the shutdown type or not.
>> If it should be, it's better to make the stats collector exit as soon as possible if the shutdown type
>> is an immediate, and avoid losing the remaining stats if it's normal.
>
> +1
>
>
>>
>>
>>
>>>> I measured the timing of the above in my linux laptop using v17-measure-timing.patch.
>>>> I don't have any strong opinion to handle this case since this result shows to receive and processes
>>>> the messages takes too short time (less than 1ms) although the stats collector receives the shutdown
>>>> signal in 5msec(099->104) after the checkpointer process exits.
>>>
>>> Agreed.
>>>
>>>>
>>>> ```
>>>> 1615421204.556 [checkpointer] DEBUG:  received shutdown request signal
>>>> 1615421208.099 [checkpointer] DEBUG:  proc_exit(-1): 0 callbacks to make              # exit and send the messages
>>>> 1615421208.099 [stats collector] DEBUG:  process BGWRITER stats message              # receive and process the messages
>>>> 1615421208.099 [stats collector] DEBUG:  process WAL stats message
>>>> 1615421208.104 [postmaster] DEBUG:  reaping dead processes
>>>> 1615421208.104 [stats collector] DEBUG:  received shutdown request signal             # receive shutdown request from the postmaster
>>>> ```
>>>>
>>>>>>> Of course, there is another direction; we can improve the stats collector so
>>>>>>> that it guarantees to collect all the sent stats messages. But I'm afraid
>>>>>>> this change might be big.
>>>>>>
>>>>>> For example, implement to manage background process status in shared memory and
>>>>>> the stats collector collects the stats until another background process exits?
>>>>>>
>>>>>> In my understanding, the statistics are not required high accuracy,
>>>>>> it's ok to ignore them if the impact is not big.
>>>>>>
>>>>>> If we guarantee high accuracy, another background process like autovacuum launcher
>>>>>> must send the WAL stats because it accesses the system catalog and might generate
>>>>>> WAL records due to HOT update even though the possibility is low.
>>>>>>
>>>>>> I thought the impact is small because the time uncollected stats are generated is
>>>>>> short compared to the time from startup. So, it's ok to ignore the remaining stats
>>>>>> when the process exists.
>>>>>
>>>>> I agree that it's not worth changing lots of code to collect such stats.
>>>>> But if we can implement that very simply, isn't it more worth doing
>>>>> that than current situation because we may be able to collect more
>>>>> accurate stats.
>>>>
>>>> Yes, I agree.
>>>> I attached the patch to send the stats before the wal writer and the checkpointer exit.
>>>> (v17-0001-send-stats-for-walwriter-when-shutdown.patch, v17-0002-send-stats-for-checkpointer-when-shutdown.patch)
>>>
>>> Thanks for making those patches! Firstly I'm reading 0001 and 0002 patches.
>>
>> Thanks for your comments and for making patches.
>>
>>
>>> Here is the review comments for 0001 patch.
>>>
>>> +/* Prototypes for private functions */
>>> +static void HandleWalWriterInterrupts(void);
>>>
>>> HandleWalWriterInterrupts() and HandleMainLoopInterrupts() are almost the same.
>>> So I don't think that we need to introduce HandleWalWriterInterrupts(). Instead,
>>> we can just call pgstat_send_wal(true) before HandleMainLoopInterrupts()
>>> if ShutdownRequestPending is true in the main loop. Attached is the patch
>>> I implemented that way. Thought?
>>
>> I thought there is a corner case that can't send the stats like
>
> You're right! So IMO your patch (v17-0001-send-stats-for-walwriter-when-shutdown.patch) is better.
>
>
>>
>> ```
>> // First, ShutdownRequstPending = false
>>
>>      if (ShutdownRequestPending)    // don't send the stats
>>          pgstat_send_wal(true);
>>
>> // receive signal and ShutdownRequestPending became true
>>
>>      HandleMainLoopInterrupts();   // proc exit without sending the stats
>>
>> ```
>>
>> Is it ok because it almost never occurs?
>>
>>
>>> Here is the review comments for 0002 patch.
>>>
>>> +static void pgstat_send_checkpointer(void);
>>>
>>> I'm inclined to avoid adding the function with the prefix "pgstat_" outside
>>> pgstat.c. Instead, I'm ok to just call both pgstat_send_bgwriter() and
>>> pgstat_report_wal() directly after ShutdownXLOG(). Thought? Patch attached.
>>
>> Thanks. I agree.
>
> Thanks for the review!
>
>
> So, barring any objection, I will commit the changes for
> walwriter and checkpointer. That is,
>
> v17-0001-send-stats-for-walwriter-when-shutdown.patch
> v17-0002-send-stats-for-checkpointer-when-shutdown_fujii.patch

I pushed these two patches.

Regards,

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