300 seconds in less than 1 second with pg_autovacuum - Mailing list pgsql-hackers-win32
From | Harald Massa |
---|---|
Subject | 300 seconds in less than 1 second with pg_autovacuum |
Date | |
Msg-id | 16265.1106312096@www40.gmx.net Whole thread Raw |
List | pgsql-hackers-win32 |
With all the patches from Dave I finally made pg_autovacuum run. And it runs, and runs ... quicker than I want it to. Some extract from my logfile: [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: Printing command_args [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->host=(null) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->port=(null) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->username=postgres [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->password=SuperSuperSuperSecret [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->logfile=c:\ghum\data\pg_log\autovacuum.log [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->install_as_service=0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->remove_as_service=0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->service_dependencies=(null) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->service_user=(null) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->service_password=(null) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->sleep_base_value=300 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->sleep_scaling_factor=2.000000 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->vacuum_base_threshold=1000 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->vacuum_scaling_factor=2.000000 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->analyze_base_threshold=500 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->analyze_scaling_factor=1.000000 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->av_vacuum_cost_delay=(default) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->av_vacuum_cost_page_hit=(default) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->av_vacuum_cost_page_miss=(default) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->av_vacuum_cost_page_dirty=(default) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->av_vacuum_cost_limit=(default) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: args->debug=4 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: pg_autovacuum starting in Windows Service mode [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: select oid,age(datfrozenxid) from pg_database where datname = 'template1' [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: dbname: template1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: oid: 1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: username: postgres [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: password: faghimwyo [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: conn is valid, (connected) [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: default_analyze_threshold: 1000 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: default_vacuum_threshold: 500 [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: SHOW stats_row_level [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: updating the database list [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: select oid,datname,age(datfrozenxid) from pg_database where datname!='template0' [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: added database: jds [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: added database: handbuch [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: dbname: template1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: oid: 1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: username: postgres [....... lots of lines for every table ....] [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: added table: jds."public"."formularfeld" [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: table name: jds."pg_catalog"."pg_database" [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: relid: 1262; relisshared: 1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: reltuples: 3.000000; relpages: 1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: curr_analyze_count: 0; curr_vacuum_count: 0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: last_analyze_count: 0; last_vacuum_count: 0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: analyze_threshold: 503; vacuum_threshold: 1006 [2005-01-21 13:41:51 Westeuropäische Normalzeit] DEBUG: added table: jds."pg_catalog"."pg_database" [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: table name: jds."public"."dbmodis" [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: relid: 17325; relisshared: 0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: reltuples: 16.000000; relpages: 1 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: curr_analyze_count: 0; curr_vacuum_count: 0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: last_analyze_count: 0; last_vacuum_count: 0 [2005-01-21 13:41:51 Westeuropäische Normalzeit] INFO: analyze_threshold: 516; vacuum_threshold: 1032 [... many more similar lines ...] [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: table name: handbuch."public"."hbart" [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: relid: 97071; relisshared: 0 [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: reltuples: 0.000000; relpages: 0 [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: curr_analyze_count: 28; curr_vacuum_count: 21 [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: last_analyze_count: 28; last_vacuum_count: 21 [2005-01-21 13:41:52 Westeuropäische Normalzeit] INFO: analyze_threshold: 500; vacuum_threshold: 1000 [2005-01-21 13:41:52 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:52 Westeuropäische Normalzeit] DEBUG: 3 All DBs checked in: 250000 usec, will sleep for 300 secs. now... 1 second passes .... [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: 4 All DBs checked in: 156000 usec, will sleep for 300 secs. that was quick ... and 300 secs. will pass before 1 second is over.... [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: updating the database list [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: select oid,datname,age(datfrozenxid) from pg_database where datname!='template0' [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: dbname: template1 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: oid: 1 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: username: postgres [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: password: xxxxxxxxx [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: conn is valid, (connected) [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_analyze_threshold: 1000 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_vacuum_threshold: 500 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: dbname: jds [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: oid: 17254 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: username: postgres [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: password: xxxxxxxx [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: conn is null, (not connected) [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_analyze_threshold: 1000 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_vacuum_threshold: 500 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: dbname: handbuch [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: oid: 96986 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: username: postgres [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: password: faghimwyo [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: conn is null, (not connected) [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_analyze_threshold: 1000 [2005-01-21 13:41:53 Westeuropäische Normalzeit] INFO: default_vacuum_threshold: 500 [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [ ..... lots of similiar lines ....] [2005-01-21 13:41:53 Westeuropäische Normalzeit] DEBUG: 5 All DBs checked in: 266000 usec, will sleep for 300 secs. [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: 6 All DBs checked in: 140000 usec, will sleep for 300 secs. [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: updating the database list [2005-01-21 13:41:54 Westeuropäische Normalzeit] DEBUG: 7 All DBs checked in: 234000 usec, will sleep for 300 secs. [2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:55 Westeuropäische Normalzeit] DEBUG: 8 All DBs checked in: 156000 usec, will sleep for 300 secs. again... 300 secs pass in one second.... ] DEBUG: 9 All DBs checked in: 250000 usec, will sleep for 300 secs. [2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG: select a.oid,a.relname,a.relnamespace,a.relpages,a.relisshared,a.reltuples,b.schemaname,b.n_tup_ins,b.n_tup_upd,b.n_tup_del from pg_class a, pg_stat_all_tables b where a.oid=b.relid and a.relkind = 'r' [2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG: 10 All DBs checked in: 140000 usec, will sleep for 300 secs. [2005-01-21 13:41:56 Westeuropäische Normalzeit] DEBUG: updating the database list [.... yeah, I know, time passes fast when you are in love or having fun. But... that is WAY TO FAST for 300secs, isn't it??? ...] [2005-01-21 13:42:42 Westeuropäische Normalzeit] DEBUG: 39 All DBs checked in: 235000 usec, will sleep for 300 secs. [2005-01-21 13:42:42 Westeuropäische Normalzeit] INFO: pg_autovacuum service stopping... That said, my logfile with -d 4 went up to 4 Gig in no time at all ... bad idea of me trying to open it within an editor :))) (read it as 4 Meg) What is going wrong? I did not fiddle with the "Sleep-Period", just left it on default. (this error happens with pg_autovacuum from 8.0 Release and with the second patch Dave sent me via email) Harald
pgsql-hackers-win32 by date: