small improvement of the elapsed time for truncating heap in vacuum

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

small improvement of the elapsed time for truncating heap in vacuum

Kasahara Tatsuhito
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 ?
Best regards,

--
Tatsuhito Kasahara
NTT Open Source Software Center

reset_usage.patch (774 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Fujii Masao-2
On Tue, Aug 13, 2019 at 1:16 PM Kasahara Tatsuhito
<[hidden email]> 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