Magnus Hagander <magnus@xxxxxxxxxxxx> 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
