RE: autovacuum failing on pg_largeobject and disk usage of the pg_largeobject growing unchecked

Magnus Hagander <magnus(at)hagander(dot)net> wrote on 06/22/2020 04:44:33 PM:
> Yes, that's how VACUUM FULL works (more or less).

Thanks for the confirmation and further explanation Magnus! I'm definitely
getting a better idea of how the vacuum and autovacuum facilities work.

> And for autovacuum, with a cost_delay of 20ms and a cost_limit of
> 200, autovacuum would spend about 55 hours just on vacuum delay for
> the reads...

Ah, very interesting. That explains (at least in part) why the autovacuums
seem to be taking a long time. We'll consider adjusting the cost_delay and
cost_limit settings. Is there any downsides to setting a very low
cost_delay (maybe even 0ms), or to setting a large cost_limit (such as
100,000)?

> The logs you posted originally seem to be excluding the actual
> autovacuum details -- can you include those?

Sure! Below are more of the details from the same set of logs. Looking at
them myself, I see that there is always some percentage of tuples that are
dead but are not yet removable. And that number increases on every vacuum,
which might explain in part why autovacuum elapsed times keep increasing.

What causes a dead tuple to be unremovable?

-- LOGS --
2020-06-12T19:41:58.335881879Z stderr F 2020-06-12 19:41:58 UTC [528141]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 0
2020-06-12T19:41:58.335899718Z stderr F pages: 0 removed, 8649
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:41:58.335908658Z stderr F tuples: 0 removed, 30445
remain, 17410 are dead but not yet removable, oldest xmin: 1942750826
2020-06-12T19:41:58.335917078Z stderr F buffer usage: 17444 hits,
0 misses, 0 dirtied
2020-06-12T19:41:58.335925217Z stderr F avg read rate: 0.000 MB/s,
avg write rate: 0.000 MB/s
2020-06-12T19:41:58.335931494Z stderr F system usage: CPU: user:
0.02 s, system: 0.00 s, elapsed: 1.77 s
2020-06-12T19:42:59.704833148Z stderr F 2020-06-12 19:42:59 UTC [528231]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T19:42:59.704852755Z stderr F pages: 0 removed, 14951
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:42:59.704861911Z stderr F tuples: 2 removed, 53054
remain, 27127 are dead but not yet removable, oldest xmin: 1942751009
2020-06-12T19:42:59.704870553Z stderr F buffer usage: 30144 hits,
0 misses, 3 dirtied
2020-06-12T19:42:59.704878195Z stderr F avg read rate: 0.000 MB/s,
avg write rate: 0.008 MB/s
2020-06-12T19:42:59.704884752Z stderr F system usage: CPU: user:
0.02 s, system: 0.02 s, elapsed: 3.06 s
2020-06-12T19:44:01.928225496Z stderr F 2020-06-12 19:44:01 UTC [528326]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 0
2020-06-12T19:44:01.928265589Z stderr F pages: 0 removed, 22395
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:44:01.928276366Z stderr F tuples: 0 removed, 76562
remain, 37235 are dead but not yet removable, oldest xmin: 1942751009
2020-06-12T19:44:01.9282856Z stderr F buffer usage: 45131 hits, 0
misses, 433 dirtied
2020-06-12T19:44:01.928293976Z stderr F avg read rate: 0.000 MB/s,
avg write rate: 0.621 MB/s
2020-06-12T19:44:01.928300512Z stderr F system usage: CPU: user:
0.06 s, system: 0.01 s, elapsed: 5.44 s
2020-06-12T19:45:14.124140716Z stderr F 2020-06-12 19:45:14 UTC [528433]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 0
2020-06-12T19:45:14.124178864Z stderr F pages: 0 removed, 31029
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:45:14.124187376Z stderr F tuples: 0 removed, 104441
remain, 65915 are dead but not yet removable, oldest xmin: 1942751009
2020-06-12T19:45:14.124196608Z stderr F buffer usage: 57692 hits,
4834 misses, 2095 dirtied
2020-06-12T19:45:14.124203046Z stderr F avg read rate: 2.204 MB/s,
avg write rate: 0.955 MB/s
2020-06-12T19:45:14.124209167Z stderr F system usage: CPU: user:
0.11 s, system: 0.05 s, elapsed: 17.13 s
2020-06-12T19:46:16.287517553Z stderr F 2020-06-12 19:46:16 UTC [528529]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 0
2020-06-12T19:46:16.287558376Z stderr F pages: 0 removed, 36257
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:46:16.287567454Z stderr F tuples: 0 removed, 122273
remain, 81080 are dead but not yet removable, oldest xmin: 1942751009
2020-06-12T19:46:16.287575752Z stderr F buffer usage: 62700 hits,
10366 misses, 76 dirtied
2020-06-12T19:46:16.287582866Z stderr F avg read rate: 4.252 MB/s,
avg write rate: 0.031 MB/s
2020-06-12T19:46:16.28758936Z stderr F system usage: CPU: user: 0.13 s,
system: 0.08 s, elapsed: 19.04 s
2020-06-12T19:47:34.264816546Z stderr F 2020-06-12 19:47:34 UTC [528615]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 0
2020-06-12T19:47:34.264850177Z stderr F pages: 0 removed, 46373
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:47:34.264860322Z stderr F tuples: 0 removed, 154605
remain, 107134 are dead but not yet removable, oldest xmin: 1942751009
2020-06-12T19:47:34.264869028Z stderr F buffer usage: 67990 hits,
25507 misses, 51 dirtied
2020-06-12T19:47:34.264876424Z stderr F avg read rate: 5.501 MB/s,
avg write rate: 0.011 MB/s
2020-06-12T19:47:34.264882626Z stderr F system usage: CPU: user:
0.20 s, system: 0.19 s, elapsed: 36.22 s
2020-06-12T19:49:15.383346478Z stderr F 2020-06-12 19:49:15 UTC [528730]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T19:49:15.383401164Z stderr F pages: 0 removed, 59435
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:49:15.383411744Z stderr F tuples: 27 removed, 196652
remain, 147872 are dead but not yet removable, oldest xmin: 1942751033
2020-06-12T19:49:15.383422329Z stderr F buffer usage: 75546 hits,
44396 misses, 3587 dirtied
2020-06-12T19:49:15.3834291Z stderr F avg read rate: 4.683 MB/s, avg
write rate: 0.378 MB/s
2020-06-12T19:49:15.383436343Z stderr F system usage: CPU: user:
0.28 s, system: 0.38 s, elapsed: 74.06 s
2020-06-12T19:53:47.229279118Z stderr F 2020-06-12 19:53:47 UTC [529009]:
[2-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T19:53:47.229328267Z stderr F pages: 0 removed, 83155
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T19:53:47.229337568Z stderr F tuples: 370 removed,
277040 remain, 235763 are dead but not yet removable, oldest xmin:
1942751716
2020-06-12T19:53:47.229346494Z stderr F buffer usage: 85923 hits,
82515 misses, 23329 dirtied
2020-06-12T19:53:47.229354327Z stderr F avg read rate: 3.011 MB/s,
avg write rate: 0.851 MB/s
2020-06-12T19:53:47.229361981Z stderr F system usage: CPU: user:
0.66 s, system: 1.06 s, elapsed: 214.12 s
2020-06-12T20:19:39.619667488Z stderr F 2020-06-12 20:19:39 UTC [529747]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T20:19:39.619715627Z stderr F pages: 0 removed, 163425
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-12T20:19:39.619725381Z stderr F tuples: 269281 removed,
264998 remain, 264357 are dead but not yet removable, oldest xmin:
1942829786
2020-06-12T20:19:39.619733911Z stderr F buffer usage: 168166 hits,
251776 misses, 238753 dirtied
2020-06-12T20:19:39.619740781Z stderr F avg read rate: 1.346 MB/s,
avg write rate: 1.277 MB/s
2020-06-12T20:19:39.619748109Z stderr F system usage: CPU: user:
4.13 s, system: 5.30 s, elapsed: 1461.16 s
2020-06-12T21:30:31.634549669Z stderr F 2020-06-12 21:30:31 UTC [532994]:
[5-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T21:30:31.634595582Z stderr F pages: 0 removed, 538082
remain, 2 skipped due to pins, 36681 skipped frozen
2020-06-12T21:30:31.634606752Z stderr F tuples: 1531965 removed,
153799 remain, 80305 are dead but not yet removable, oldest xmin:
1943217115
2020-06-12T21:30:31.634616083Z stderr F buffer usage: 580519 hits,
953897 misses, 934221 dirtied
2020-06-12T21:30:31.634627566Z stderr F avg read rate: 1.764 MB/s,
avg write rate: 1.727 MB/s
2020-06-12T21:30:31.634637945Z stderr F system usage: CPU: user:
13.73 s, system: 19.59 s, elapsed: 4225.61 s
2020-06-12T23:54:32.51093334Z stderr F 2020-06-12 23:54:32 UTC [542595]:
[5-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-12T23:54:32.510977347Z stderr F pages: 0 removed, 1389179
remain, 0 skipped due to pins, 267855 skipped frozen
2020-06-12T23:54:32.510988778Z stderr F tuples: 3292911 removed,
515165 remain, 505391 are dead but not yet removable, oldest xmin:
1944778837
2020-06-12T23:54:32.510998568Z stderr F buffer usage: 1258882
hits, 2096188 misses, 2108207 dirtied
2020-06-12T23:54:32.51100648Z stderr F avg read rate: 1.923 MB/s, avg
write rate: 1.934 MB/s
2020-06-12T23:54:32.511015886Z stderr F system usage: CPU: user:
33.57 s, system: 41.90 s, elapsed: 8514.23 s
2020-06-13T04:23:32.230860795Z stderr F 2020-06-13 04:23:32 UTC [559963]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-13T04:23:32.230910901Z stderr F pages: 0 removed, 2465148
remain, 0 skipped due to pins, 0 skipped frozen
2020-06-13T04:23:32.230925263Z stderr F tuples: 5248384 removed,
2733516 remain, 2705020 are dead but not yet removable, oldest xmin:
1946587052
2020-06-13T04:23:32.230936603Z stderr F buffer usage: 2644322
hits, 4162765 misses, 4133675 dirtied
2020-06-13T04:23:32.230949056Z stderr F avg read rate: 2.031 MB/s,
avg write rate: 2.017 MB/s
2020-06-13T04:23:32.230960572Z stderr F system usage: CPU: user:
66.09 s, system: 82.95 s, elapsed: 16011.25 s
2020-06-13T12:00:37.434270463Z stderr F 2020-06-13 12:00:37 UTC [595111]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-13T12:00:37.434307457Z stderr F pages: 0 removed, 4131164
remain, 0 skipped due to pins, 207424 skipped frozen
2020-06-13T12:00:37.434317487Z stderr F tuples: 8179570 removed,
4165421 remain, 4086602 are dead but not yet removable, oldest xmin:
1948480803
2020-06-13T12:00:37.43432695Z stderr F buffer usage: 4243615 hits,
6654785 misses, 6619302 dirtied
2020-06-13T12:00:37.434334494Z stderr F avg read rate: 1.905 MB/s,
avg write rate: 1.894 MB/s
2020-06-13T12:00:37.43434175Z stderr F system usage: CPU: user: 99.42 s,
system: 130.48 s, elapsed: 27296.71 s
2020-06-14T02:40:25.191125478Z stderr F 2020-06-14 02:40:25 UTC [654970]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-14T02:40:25.191163972Z stderr F pages: 0 removed, 7782633
remain, 0 skipped due to pins, 5975 skipped frozen
2020-06-14T02:40:25.191204642Z stderr F tuples: 17589483 removed,
8269831 remain, 8231465 are dead but not yet removable, oldest xmin:
1956222447
2020-06-14T02:40:25.191214917Z stderr F buffer usage: 8456598
hits, 13571633 misses, 13500595 dirtied
2020-06-14T02:40:25.19122207Z stderr F avg read rate: 2.014 MB/s, avg
write rate: 2.003 MB/s
2020-06-14T02:40:25.19122979Z stderr F system usage: CPU: user: 202.96 s,
system: 263.66 s, elapsed: 52653.66 s
2020-06-15T01:55:09.037552909Z stderr F 2020-06-15 01:55:09 UTC [767824]:
[4-1] user=,db=,client= LOG: automatic vacuum of table
"ibmclouddb.pg_catalog.pg_largeobject": index scans: 1
2020-06-15T01:55:09.037624876Z stderr F pages: 0 removed, 13496086
remain, 0 skipped due to pins, 1212853 skipped frozen
2020-06-15T01:55:09.037635971Z stderr F tuples: 28059058 removed,
12115915 remain, 12074335 are dead but not yet removable, oldest xmin:
1973686598
2020-06-15T01:55:09.037647754Z stderr F buffer usage: 13308114
hits, 21188624 misses, 20841540 dirtied
2020-06-15T01:55:09.03765574Z stderr F avg read rate: 1.981 MB/s, avg
write rate: 1.949 MB/s
2020-06-15T01:55:09.03766272Z stderr F system usage: CPU: user: 317.54 s,
system: 544.48 s, elapsed: 83550.21 s