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
Attachments:
reset_usage.patchapplication/octet-stream; name=reset_usage.patchDownload
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index a3c4a1d..5e04c15 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1988,6 +1988,9 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
errdetail_internal("%s",
pg_rusage_show(&ru0))));
old_rel_pages = new_rel_pages;
+ /* Reset usage for truncating remain pages */
+ pg_rusage_init(&ru0);
+
} while (new_rel_pages > vacrelstats->nonempty_pages &&
vacrelstats->lock_waiter_detected);
}
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
Attachments:
reset_usage_v2.patchapplication/octet-stream; name=reset_usage_v2.patchDownload
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index a23cdef..f204401 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -2442,8 +2442,6 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
PGRUsage ru0;
int lock_retry;
- pg_rusage_init(&ru0);
-
/* Report that we are now truncating */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
@@ -2453,6 +2451,8 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
*/
do
{
+ pg_rusage_init(&ru0);
+
/*
* We need full exclusive lock on the relation in order to do
* truncation. If we can't get it, give up rather than waiting --- we
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
Attachments:
reset_usage_v3.patchapplication/octet-stream; name=reset_usage_v3.patchDownload
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index a23cdef..c332d5a 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -2439,11 +2439,8 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
{
BlockNumber old_rel_pages = vacrelstats->rel_pages;
BlockNumber new_rel_pages;
- PGRUsage ru0;
int lock_retry;
- pg_rusage_init(&ru0);
-
/* Report that we are now truncating */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
@@ -2453,6 +2450,9 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
*/
do
{
+ PGRUsage ru0;
+ pg_rusage_init(&ru0);
+
/*
* We need full exclusive lock on the relation in order to do
* truncation. If we can't get it, give up rather than waiting --- we
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