Re: Prolonged truncation phase during vacuum on toast table with repeated interruptions by lock waiters and a proposed POC patch

On Thu, May 8, 2025 at 4:58 PM Shayon Mukherjee <shayonj(at)gmail(dot)com> wrote:

> +1 for this. I'd even be happy to even just start showing the attempts as
> part of INFO or VERBOSE on conflicts & suspensions, without keeping track,
> but it is useful statistical data.
>
>

Hi hackers,

Following up on the recent discussion about prolonged VACUUM truncation
phases on busy systems, I took a stab at extending the logging to add a
little bit more visibility into the truncation process.

With this patch, when VACUUM is run with VERBOSE, it will now log the
following:

1. Individual suspension messages with attempt count and cumulative elapsed
time.
2. A summary at the end of the truncation process showing the total number
of suspensions and the total elapsed time.

Example output:
INFO: table "toast_target_table": suspending truncate due to conflicting
lock request (attempt 1, elapsed: 0.121 s)
INFO: table "toast_target_table": truncated 372096 to 370624 pages
INFO: table "toast_target_table": suspending truncate due to conflicting
lock request (attempt 2, elapsed: 6.108 s)
...
INFO: table "toast_target_table": truncation completed after 8
suspension(s), total elapsed: 58.090 s

Perhaps, this can give developers the information needed to identify
problematic truncation behavior and decide whether to use VACUUM (TRUNCATE
OFF) for specific tables.

Additionally, tracking these stats in a table would be useful as well.
Curious, if something like this is desirable by the community?

Proposal patch is attached. Some notes on the patch:

- Unclear if there is a best way to write regression tests for this, since
it can be flaky.
- There seems to be translation support for the copy. At least for the
initial patch, I have left that and happy to discuss more if the patch
feels viable.

Thank you
Shayon