Add support for {max,avg,min} autovacuum duration & fix autovacuum's system usage: CPU: ... line parsing

[franciscoreinolds]

Hello 👋🏽

I thought this would be an interesting feature to add as one can have a decent average autovacuum duration, but some of them might be running too long and one wouldn't know it.

While trying to implement this feature, I stumbled upon the fact that the parsing for autovacuum's system usage: CPU: user: ... line is broken. I hadn't noticed it thus far, but have checked a report I generated a couple of days ago and it's also missing the longest vacuum duration:

So, I fixed that, and begun implementing the chart.

To test my implementation, I generated a report from the following output:

Details

Feb 10 23:06:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:08:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:10:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:12:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:14:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:16:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:18:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:20:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:22:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:24:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28
Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "db.public.tablename": index scans: 1
									    pages: 0 removed, 1001527 remain, 0 skipped due to pins, 0 skipped frozen
									    tuples: 1346603 removed, 15288094 remain, 224598 are dead but not yet removable, oldest xmin: 736
									    buffer usage: 1104110 hits, 2210831 misses, 1716564 dirtied
									    avg read rate: 2.329 MB/s, avg write rate: 1.808 MB/s
									    system usage: CPU: user: 46.90 s, system: 60.02 s, elapsed: 7417.28

The result (I know it's missing the Key Values, I just wanted to get the biggest part out of the way) is:

This seems decent enough, but I might be forgetting something, but I guess we can cross that bridge when we cross it.

Looking forward to hear from you, Gilles!

[darold]

I think the regexp should be:

if ($line =~ /^[\s\t]*system usage: CPU: user: (.*) (?:sec|s,) system: (.*) (?:sec|s,) elapsed: ([^\s]+)/)

to avoid getting the sec or s at end of the line.

[franciscoreinolds]

Now I think this is okay!

I tested it with the following lines:

Details

Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "db.public.table1" system usage: CPU: user: 0.77 s, system: 0.90 s, elapsed: 12.36 s
Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "db.public.table2" system usage: CPU: user: 0.19 s, system: 0.03 s, elapsed: 0.57 s
Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "db.public.table3" system usage: CPU: user: 0.11 s, system: 0.01 s, elapsed: 0.63 s
Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "db.public.table4" system usage: CPU: user: 0.56 s, system: 0.07 s, elapsed: 2.29 s
Feb 10 23:26:30 test-pc postgres[10808]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "db.public.table4" system usage: CPU: user: 0.56 s, system: 0.07 s, elapsed: 20.29 

And the result: