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
thoughtthat 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"
systemusage: 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":
indexscans: 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"
systemusage: 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"
systemusage: 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":
indexscans: 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":
indexscans: 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"
systemusage: 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":
indexscans: 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"
systemusage: 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":
indexscans: 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:
CPU0.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:
CPU0.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:
CPU0.27s/0.44u sec elapsed 90.82 sec 

Regards, Baptiste.