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