Обсуждение: small improvement of the elapsed time for truncating heap in vacuum

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

On Tue, Aug 13, 2019 at 1:16 PM Kasahara Tatsuhito
<kasahara.tatsuhito@gmail.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

Hi,

On Fri, Feb 14, 2020 at 4:50 PM Fujii Masao <masao.fujii@gmail.com> wrote:
> 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().
Thanks for your reply.
Yeah, it makes sense.

Attached patch moves pg_rusage_init() to the top of do-loop-block.

Best regards,
-- 
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com

On Mon, 17 Feb 2020 at 12:44, Kasahara Tatsuhito
<kasahara.tatsuhito@gmail.com> wrote:
>
> Hi,
>
> On Fri, Feb 14, 2020 at 4:50 PM Fujii Masao <masao.fujii@gmail.com> wrote:
> > 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().
> Thanks for your reply.
> Yeah, it makes sense.
>
> Attached patch moves pg_rusage_init() to the top of do-loop-block.

+1 to reset for each truncation loops.

For the patch, we can put also the declaration of ru0 into the loop.

Regards,

-- 
Masahiko Sawada            http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Hi,

On Mon, Feb 17, 2020 at 1:07 PM Masahiko Sawada
<masahiko.sawada@2ndquadrant.com> wrote:
> For the patch, we can put also the declaration of ru0 into the loop.
Thanks for your reply.
Hmm, certainly that it may be better.

Fix the v2 patch and attached.

Best regards,

-- 
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com

On 2020/02/17 14:28, Kasahara Tatsuhito wrote:
> Hi,
> 
> On Mon, Feb 17, 2020 at 1:07 PM Masahiko Sawada
> <masahiko.sawada@2ndquadrant.com> wrote:
>> For the patch, we can put also the declaration of ru0 into the loop.
> Thanks for your reply.
> Hmm, certainly that it may be better.
> 
> Fix the v2 patch and attached.

Thanks for updating the patch!
Barring any objection, I will commit this.

As far as I check the back branches, ISTM that
this patch needs to be back-patch to v9.5.

Regards,

-- 
Fujii Masao
NTT DATA CORPORATION
Advanced Platform Technology Group
Research and Development Headquarters

On 2020/02/17 17:52, Fujii Masao wrote:
> 
> 
> On 2020/02/17 14:28, Kasahara Tatsuhito wrote:
>> Hi,
>>
>> On Mon, Feb 17, 2020 at 1:07 PM Masahiko Sawada
>> <masahiko.sawada@2ndquadrant.com> wrote:
>>> For the patch, we can put also the declaration of ru0 into the loop.
>> Thanks for your reply.
>> Hmm, certainly that it may be better.
>>
>> Fix the v2 patch and attached.
> 
> Thanks for updating the patch!
> Barring any objection, I will commit this.
> 
> As far as I check the back branches, ISTM that
> this patch needs to be back-patch to v9.5.

Pushed. Thanks!

Regards,

-- 
Fujii Masao
NTT DATA CORPORATION
Advanced Platform Technology Group
Research and Development Headquarters