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
Description: Binary data
