small improvement of the elapsed time for truncating heap in vacuum

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
7 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


Reply | Threaded
Open this post in threaded view
|

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

Kasahara Tatsuhito
Hi,

On Fri, Feb 14, 2020 at 4:50 PM Fujii Masao <[hidden email]> 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

reset_usage_v2.patch (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Masahiko Sawada-2
On Mon, 17 Feb 2020 at 12:44, Kasahara Tatsuhito
<[hidden email]> wrote:

>
> Hi,
>
> On Fri, Feb 14, 2020 at 4:50 PM Fujii Masao <[hidden email]> 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


Reply | Threaded
Open this post in threaded view
|

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

Kasahara Tatsuhito
Hi,

On Mon, Feb 17, 2020 at 1:07 PM Masahiko Sawada
<[hidden email]> 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

reset_usage_v3.patch (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Fujii Masao-4


On 2020/02/17 14:28, Kasahara Tatsuhito wrote:
> Hi,
>
> On Mon, Feb 17, 2020 at 1:07 PM Masahiko Sawada
> <[hidden email]> 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


Reply | Threaded
Open this post in threaded view
|

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

Fujii Masao-4


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
>> <[hidden email]> 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