Re: small improvement of the elapsed time for truncating heap in vacuum

On Tue, Aug 13, 2019 at 1:16 PM Kasahara Tatsuhito
<kasahara(dot)tatsuhito(at)gmail(dot)com> wrote:
>
> Hi,
>
> I got following log messages when measured the heap truncating
> duration in a vacuum.
>
> =====================================================
> INFO: "dst": suspending truncate due to conflicting lock request
> INFO: "dst": truncated 550073 to 101472 pages
> DETAIL: CPU: user: 0.35 s, system: 4.92 s, elapsed: 6.96 s
> INFO: "dst": truncated 101472 to 164 pages
> DETAIL: CPU: user: 0.35 s, system: 11.02 s, elapsed: 13.46 s
> =====================================================
>
> Above message shows that postgres detected a access to the table
> during heap truncating so suspend the truncating,
> and then resumed truncating after the access finish. The messages were
> no-problem.
> But "usage" and "elapsed (time)" were bit confusing.
> Total truncating duration was about 13.5s, but log said 6.96s (before
> suspend) + 13.46s (remain).
> # I confirmed the total truncating duration by elog debugging.
>
> In lazy_truncate_heap() pg_rusage_init is only called once at the
> truncating start.
> So the last-truncating-phase-log shows the total truncating-phase
> usages and elapsed time.
> Attached patch make pg_rusage_init would be called after each
> ereport() of heap-truncating,
> so log messages will change like following.
>
> =====================================================
> INFO: "dst": suspending truncate due to conflicting lock request
> INFO: "dst": truncated 550073 to 108288 pages
> DETAIL: CPU: user: 0.20 s, system: 4.88 s, elapsed: 7.41 s
> INFO: "dst": truncated 108288 to 164 pages
> DETAIL: CPU: user: 0.00 s, system: 7.36 s, elapsed: 7.92 s
> =====================================================
> (Total truncating time was about 15.3s in above case)
>
> Any thoughts ?

+1. I observed this issue and found this thread.

Regarding the patch, isn't it better to put pg_rusage_init() at the
top of do loop block? If we do this, as a side-effect, we can get
rid of pg_rusage_init() at the top of lazy_truncate_heap().

Regards,

--
Fujii Masao