small improvement of the elapsed time for truncating heap in vacuum
Kasahara Tatsuhito <kasahara.tatsuhito@gmail.com>
From: Kasahara Tatsuhito <kasahara.tatsuhito@gmail.com>
To: pgsql-hackers@postgresql.org
Date: 2019-08-13T04:15:44Z
Lists: pgsql-hackers
Attachments
- reset_usage.patch (application/octet-stream) patch
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
Commits
-
Fix mesurement of elapsed time during truncating heap in VACUUM.
- 4a3f164b74f5 9.5.22 landed
- 307c27037444 9.6.18 landed
- 79f344d52bd5 10.13 landed
- 414ed1ca2321 11.8 landed
- 16e6c968be64 12.3 landed
- 007491979461 13.0 landed