Re: Autoanalyze of the autovacuum daemon ...

Hi,

Today I consulted the log of my PostgreSQL server and I saw that autovacuum tasks took to much time to do their work. I thought that ANALYZE was a fast operation ?

2012-11-09 10:52:33 CET LOG: automatic analyze of table "flows.public.agg_t20_outgoing_a41_src_net_and_dst_net_f5" system usage: CPU 0.20s/0.63u sec elapsed 137.12 sec
2012-11-09 10:52:58 CET LOG: automatic vacuum of table "flows.public.agg_t20_outgoing_a51_src_port_and_proto_f5": index scans: 0
pages: 0 removed, 36044 remain
tuples: 0 removed, 3495897 remain
system usage: CPU 0.53s/0.62u sec elapsed 307.28 sec
2012-11-09 10:53:33 CET LOG: automatic analyze of table "flows.public.agg_t387_incoming_a44_dst_port_and_proto_f5" system usage: CPU 0.24s/0.46u sec elapsed 174.73 sec
2012-11-09 10:55:50 CET LOG: automatic analyze of table "flows.public.agg_t20_outgoing_a51_src_port_and_proto_f5" system usage: CPU 0.20s/0.48u sec elapsed 152.16 sec
2012-11-09 10:55:55 CET LOG: automatic vacuum of table "flows.public.agg_t387_incoming_a41_src_net_and_dst_net_f5": index scans: 0
pages: 0 removed, 29849 remain
tuples: 0 removed, 1349327 remain
system usage: CPU 0.35s/0.28u sec elapsed 141.52 sec
2012-11-09 10:58:18 CET LOG: automatic vacuum of table "flows.public.agg_t205_incoming_a41_src_net_and_dst_net_f5": index scans: 0
pages: 0 removed, 34435 remain
tuples: 0 removed, 3339035 remain
system usage: CPU 0.66s/0.55u sec elapsed 340.06 sec
2012-11-09 10:59:32 CET LOG: automatic analyze of table "flows.public.agg_t387_incoming_a41_src_net_and_dst_net_f5" system usage: CPU 0.26s/0.54u sec elapsed 216.95 sec
2012-11-09 10:59:45 CET LOG: automatic vacuum of table "flows.public.agg_t387_incoming_a44_dst_port_and_proto_f5": index scans: 0
pages: 0 removed, 28733 remain
tuples: 0 removed, 1327333 remain
system usage: CPU 0.24s/0.23u sec elapsed 234.73 sec
2012-11-09 11:01:24 CET LOG: automatic analyze of table "flows.public.agg_t205_incoming_a41_src_net_and_dst_net_f5" system usage: CPU 0.22s/0.55u sec elapsed 186.27 sec
2012-11-09 11:01:50 CET LOG: automatic vacuum of table "flows.public.agg_t387_incoming_a41_src_net_and_dst_net_f5": index scans: 0
pages: 0 removed, 29849 remain
tuples: 0 removed, 1349527 remain
system usage: CPU 0.24s/0.23u sec elapsed 124.28 sec
2012-11-09 11:02:04 CET LOG: automatic vacuum of table "flows.public.agg_t205_incoming_a40_dst_net_f5": index scans: 0
pages: 0 removed, 19817 remain
tuples: 0 removed, 2008020 remain
system usage: CPU 0.33s/0.40u sec elapsed 151.76 sec
2012-11-09 11:03:22 CET LOG: automatic analyze of table "flows.public.agg_t205_incoming_a40_dst_net_f5" system usage: CPU 0.14s/0.37u sec elapsed 78.40 sec
2012-11-09 11:04:11 CET LOG: automatic vacuum of table "flows.public.agg_t387_incoming_a40_dst_net_f5": index scans: 0
pages: 0 removed, 26294 remain
tuples: 0 removed, 1316071 remain
system usage: CPU 0.25s/0.28u sec elapsed 140.99 sec
2012-11-09 11:05:08 CET LOG: automatic vacuum of table "flows.public.agg_t20_outgoing_a39_src_net_f5": index scans: 0
pages: 0 removed, 26821 remain
tuples: 0 removed, 2869526 remain
system usage: CPU 0.46s/0.42u sec elapsed 223.09 sec
2012-11-09 11:05:57 CET LOG: automatic analyze of table "flows.public.agg_t387_incoming_a40_dst_net_f5" system usage: CPU 0.28s/0.43u sec elapsed 105.64 sec
2012-11-09 11:06:39 CET LOG: automatic analyze of table "flows.public.agg_t20_outgoing_a39_src_net_f5" system usage: CPU 0.27s/0.44u sec elapsed 90.82 sec

Regards, Baptiste.