Anyone? I've tried playing with GEQO on version 9.1, setting it on/off, adjusting its parameters. I've also increased default_statistics_target to 1000, set join_collapse_limit to 1, ran ANALYZE again, no progress. The query plan on the restored db remains 34 rows instead of 21 on the current production db... -----Original Message----- From: pgsql-general-owner@xxxxxxxxxxxxxx [mailto:pgsql-general-owner@xxxxxxxxxxxxxx] On Behalf Of John Watts Sent: 17 May 2012 22:43 To: pgsql-general@xxxxxxxxxxxxxx Subject: difference in query plan when db is restored Hi folks, I have a database query which executes normal (under 1s) with 21 steps according to the query paln. However, when the database is dumped and restored on the _same_ PostgreSQL server, the query plan takes 34 steps to complete and it executes in excess of 90 seconds! Why is the query plan changed and it takes ages to execute? Inceased verbosity in server log file (debug 2) does not disclose anything unusual. Set up detail following - Version PostgreSQL 8.3.0, Linux CentOS 6.2 x86_64 Please not that exactly same behaviour (enhanced) query plan is observed also with current 8.4 and 9.1 PostgreSQL servers, e.g. when restoring the database dump from the 8.3.0 PostgreSQL server. Kind regards, JW Dump and restore - $ pg_dump -U postgres mydb -C &> mydb.sql (mydb renamed to mydb_old) $ psql -U postgres -f ./mydb.sql &> mydb.log (no error|warning msgs) [...] -- -- PostgreSQL database dump -- SET client_encoding = 'SQL_ASCII'; SET standard_conforming_strings = off; SET check_function_bodies = false; SET client_min_messages = warning; SET escape_string_warning = off; -- -- Name: mydb; Type: DATABASE; Schema: -; Owner: postgres -- CREATE DATABASE mydb WITH TEMPLATE = template0 ENCODING = 'SQL_ASCII'; (changed to mydb) ALTER DATABASE mydb OWNER TO postgres; (changed to mydb) \connect mydb SET client_encoding = 'SQL_ASCII'; SET standard_conforming_strings = off; SET check_function_bodies = false; SET client_min_messages = warning; SET escape_string_warning = off; -- -- Name: plpgsql; Type: PROCEDURAL LANGUAGE; Schema: -; Owner: dbadmin -- CREATE PROCEDURAL LANGUAGE plpgsql; ALTER PROCEDURAL LANGUAGE plpgsql OWNER TO dbadmin; -- -- Name: plpythonu; Type: PROCEDURAL LANGUAGE; Schema: -; Owner: dbadmin -- CREATE PROCEDURAL LANGUAGE plpythonu; ALTER PROCEDURAL LANGUAGE plpythonu OWNER TO dbadmin; SET search_path = public, pg_catalog; SET default_tablespace = ''; SET default_with_oids = false; -- -- Name: tbluser; Type: TABLE; Schema: public; Owner: postgres; Tablespace: -- [...] Query plan against original 'mydb'. QUERY PLAN ------------------------------------------------------------------------ ------------------------------------------------------------------------ ------------------ Sort (cost=245.97..245.98 rows=3 width=373) (actual time=89.289..90.289 rows=3445 loops=1) Sort Key: tblappliccomp.idnumber2, tblappliccomp.idnumber Sort Method: quicksort Memory: 962kB -> Nested Loop Left Join (cost=0.00..245.95 rows=3 width=373) (actual time=0.160..80.279 rows=3445 loops=1) -> Nested Loop Left Join (cost=0.00..136.01 rows=3 width=175) (actual time=0.079..24.832 rows=3445 loops=1) -> Index Scan using tblappliccompindapplicid on tblappliccomp (cost=0.00..111.16 rows=3 width=180) (actual time=0.054..5.901 rows=3445 loops=1) Index Cond: (applicid = 90000872) Filter: (((otherr IS NULL) OR (otherr = 0)) AND ("inout" = 1)) -> Index Scan using tbluserindidnumber on tbluser (cost=0.00..8.27 rows=1 width=11) (actual time=0.003..0.003 rows=1 loops=3445) Index Cond: (tblappliccomp.usercrid = tbluser.idnumber) -> Index Scan using tblcompanyindidnumber on tblcompany (cost=0.00..8.40 rows=1 width=206) (actual time=0.003..0.003 rows=0 loops=3445) Index Cond: (tblappliccomp.companyid = tblcompany.idnumber) SubPlan -> Limit (cost=0.00..28.23 rows=1 width=15) (actual time=0.009..0.009 rows=1 loops=3445) -> Nested Loop Left Join (cost=0.00..28.23 rows=1 width=15) (actual time=0.008..0.008 rows=1 loops=3445) -> Index Scan using leeindapplicid on lee (cost=0.00..19.95 rows=1 width=8) (actual time=0.005..0.005 rows=1 loops=3445) Index Cond: (applicid = 70058598) Filter: ((eorg = $0) AND (eevent = $1)) -> Index Scan using tblreferralindidnumber on tblreferral (cost=0.00..8.27 rows=1 width=23) (actual time=0.002..0.002 rows=1 loops=2947) Index Cond: (lee.referralid = tblreferral.idnumber) Total runtime: 91.636 ms (21 rows) Query plan against restored 'mydb'. QUERY PLAN ------------------------------------------------------------------------ ------------------------------------------------------------------------ ------------------- Sort (cost=236436.46..236439.56 rows=1240 width=1205) (actual time=99327.436..99328.512 rows=3445 loops=1) Sort Key: tblappliccomp.idnumber2, tblappliccomp.idnumber Sort Method: quicksort Memory: 962kB -> Hash Left Join (cost=178.98..236372.75 rows=1240 width=1205) (actual time=50.351..99300.106 rows=3445 loops=1) Hash Cond: (tblappliccomp.usercrid = tbluser.idnumber) -> Nested Loop Left Join (cost=152.95..2001.27 rows=620 width=1165) (actual time=8.778..106.444 rows=3445 loops=1) -> Bitmap Heap Scan on tblappliccomp (cost=139.89..218.60 rows=1 width=988) (actual time=8.741..21.181 rows=3445 loops=1) Recheck Cond: (("inout" = 1) AND (applicid = 90000872)) Filter: ((otherr IS NULL) OR (otherr = 0)) -> BitmapAnd (cost=139.89..139.89 rows=20 width=0) (actual time=8.621..8.621 rows=0 loops=1) -> Bitmap Index Scan on tblappliccompindinout (cost=0.00..65.81 rows=3932 width=0) (actual time=7.325..7.325 rows=49426 loops=1) Index Cond: ("inout" = 1) -> Bitmap Index Scan on tblappliccompindapplicid (cost=0.00..73.83 rows=3932 width=0) (actual time=0.621..0.621 rows=3555 loops=1) Index Cond: (applicid = 90000872) -> Bitmap Heap Scan on tblcompany (cost=13.07..1774.92 rows=620 width=185) (actual time=0.013..0.013 rows=0 loops=3445) Recheck Cond: (tblappliccomp.companyid = tblcompany.idnumber) -> Bitmap Index Scan on tblcompanyindidnumber (cost=0.00..12.91 rows=620 width=0) (actual time=0.011..0.011 rows=0 loops=3445) Index Cond: (tblappliccomp.companyid = tblcompany.idnumber) -> Hash (cost=21.01..21.01 rows=401 width=56) (actual time=0.591..0.591 rows=401 loops=1) -> Seq Scan on tbluser (cost=0.00..21.01 rows=401 width=56) (actual time=0.013..0.344 rows=401 loops=1) SubPlan -> Limit (cost=157.38..188.95 rows=1 width=48) (actual time=28.779..28.779 rows=1 loops=3445) -> Nested Loop Left Join (cost=157.38..252.10 rows=3 width=48) (actual time=28.777..28.777 rows=1 loops=3445) -> Bitmap Heap Scan on lee (cost=157.38..235.76 rows=1 width=8) (actual time=28.689..28.689 rows=1 loops=3445) Recheck Cond: ((eorg = $0) AND (eevent = $1)) Filter: (applicid = 70058598) -> BitmapAnd (cost=157.38..157.38 rows=20 width=0) (actual time=21.115..21.115 rows=0 loops=3445) -> Bitmap Index Scan on leeindeorg (cost=0.00..78.56 rows=4030 width=0) (actual time=9.506..9.506 rows=72654 loops=3445) Index Cond: (eorg = $0) -> Bitmap Index Scan on leeindeevent (cost=0.00..78.56 rows=4030 width=0) (actual time=11.907..11.907 rows=85776 loops=2947) Index Cond: (eevent = $1) -> Index Scan using tblreferralindidnumber on tblreferral (cost=0.00..16.30 rows=3 width=56) (actual time=0.015..0.015 rows=1 loops=2947) Index Cond: (lee.referralid = tblreferral.idnumber) Total runtime: 99330.021 ms (34 rows) Query: EXPLAIN ANALYZE SELECT tblApplicComp.IDNumber,tblApplicComp.IDNumber2,tblApplicComp.ApplicID,tb lApplicComp.eiinvnum,tblApplicComp.CompanyID,tblCompany.Descr AS Company,tblCompany.encrcontEIN, tblApplicComp.nog,tblApplicComp.compl,tblApplicComp.complto ,tblApplicComp.gsi,tblApplicComp.confid,tblApplicComp.StartDate,tblAppli cComp.invno,tblApplicComp.status,tblApplicComp.valuea,tblApplicComp.valu eb,tblApplicComp.valuec,tblApplicComp.valuecc,tblApplicComp.vatte, tblApplicComp.taxpoint,tb lApplicComp.pmntdate,tblApplicComp.suppldate,tblApplicComp.rcptdate,tblA pplicComp.compname, tbluser.code,tblApplicComp.dt,tblApplicComp.ccoo, (select tblreferral.descr from lee left outer JOIN tblreferral ON lee.referralid = tblreferral .IDNumber where applicid=70058598 and eorg=tblappliccomp.CompanyID and eevent=tblappliccomp.confid limit 1) ///// in time it became apparent this subselect leads to dramatically increased query time -- why?? as referral_ , tblApplicComp.salesl,tblApplicComp.suppltrav,tblappliccomp.netinv,tblApp licComp.vatt,tblApplicComp.add1,tblAppli cComp.add2,tblApplicComp.add3,tblApplicComp.add4,tblApplicComp.add5,tblA pplicComp.add6 , tblApplicComp.countryid ,tblappliccomp.fstatus From tblApplicComp LEFT OUTER JOIN tblCompany ON tblApplicComp.CompanyID = tblCompany.IDNumber LE FT OUTER JOIN tbluser ON tblApplicComp.usercrid = tbluser.IDNumber WHERE tblApplicComp.ApplicID = 90000872 and tblApplicComp.inout=1 and (tblApplicComp.otherr is null or tblappliccomp.otherr=0) order by tblApplicComp.IDNumber2,tblAppl icComp.IDNumber PostgreSQL settings: name | setting ---------------------------------+-------------------------------------- ---------------------------------+- add_missing_from | off allow_system_table_mods | off archive_command | (disabled) archive_mode | off archive_timeout | 0 array_nulls | on authentication_timeout | 60 autovacuum | off autovacuum_analyze_scale_factor | 0.1 autovacuum_analyze_threshold | 50 autovacuum_freeze_max_age | 200000000 autovacuum_max_workers | 3 autovacuum_naptime | 60 autovacuum_vacuum_cost_delay | 20 autovacuum_vacuum_cost_limit | -1 autovacuum_vacuum_scale_factor | 0.2 autovacuum_vacuum_threshold | 50 backslash_quote | safe_encoding bgwriter_delay | 200 bgwriter_lru_maxpages | 100 bgwriter_lru_multiplier | 2 block_size | 8192 bonjour_name | check_function_bodies | on checkpoint_completion_target | 0.5 checkpoint_segments | 30 checkpoint_timeout | 300 checkpoint_warning | 30 client_encoding | sql_ascii client_min_messages | error commit_delay | 0 commit_siblings | 5 config_file | /usr/local/pgsql/data/postgresql.conf constraint_exclusion | off cpu_index_tuple_cost | 0.005 cpu_operator_cost | 0.0025 cpu_tuple_cost | 0.01 custom_variable_classes | data_directory | /usr/local/pgsql/data DateStyle | ISO, MDY db_user_namespace | off deadlock_timeout | 1000 debug_assertions | off debug_pretty_print | off debug_print_parse | off debug_print_plan | off debug_print_rewritten | off default_statistics_target | 150 default_tablespace | default_text_search_config | pg_catalog.english default_transaction_isolation | read committed default_transaction_read_only | off default_with_oids | off dynamic_library_path | $libdir effective_cache_size | 917504 enable_bitmapscan | on enable_hashagg | on enable_hashjoin | on enable_indexscan | on enable_mergejoin | on enable_nestloop | on enable_seqscan | on enable_sort | on enable_tidscan | on escape_string_warning | on explain_pretty_print | on external_pid_file | extra_float_digits | 0 from_collapse_limit | 8 fsync | on full_page_writes | on geqo | on geqo_effort | 5 geqo_generations | 0 geqo_pool_size | 0 geqo_selection_bias | 2 geqo_threshold | 12 gin_fuzzy_search_limit | 0 hba_file | /usr/local/pgsql/data/pg_hba.conf ident_file | /usr/local/pgsql/data/pg_ident.conf ignore_system_indexes | off integer_datetimes | off join_collapse_limit | 8 krb_caseins_users | off krb_realm | krb_server_hostname | krb_server_keyfile | krb_srvname | postgres lc_collate | en_US.UTF-8 lc_ctype | C lc_messages | en_US.UTF-8 lc_monetary | en_US.UTF-8 lc_numeric | en_US.UTF-8 lc_time | en_US.UTF-8 listen_addresses | * local_preload_libraries | log_autovacuum_min_duration | -1 log_checkpoints | off log_connections | on log_destination | stderr log_directory | pg_log log_disconnections | off log_duration | off log_error_verbosity | default log_executor_stats | off log_filename | postgresql-%Y-%m-%d_%H%M%S.log log_hostname | off log_line_prefix | log_lock_waits | off log_min_duration_statement | -1 log_min_error_statement | error log_min_messages | notice log_parser_stats | off log_planner_stats | off log_rotation_age | 1440 log_rotation_size | 10240 log_statement | none log_statement_stats | off log_temp_files | -1 log_timezone | Europe/Sofia log_truncate_on_rotation | on logging_collector | on maintenance_work_mem | 32768 max_connections | 800 max_files_per_process | 1000 max_fsm_pages | 304800 max_fsm_relations | 10000 max_function_args | 100 max_identifier_length | 63 max_index_keys | 32 max_locks_per_transaction | 64 max_prepared_transactions | 5 max_stack_depth | 2048 password_encryption | on port | 5432 post_auth_delay | 0 pre_auth_delay | 0 random_page_cost | 4 regex_flavor | advanced search_path | "$user",public seq_page_cost | 1 server_encoding | SQL_ASCII server_version | 8.3.0 server_version_num | 80300 session_replication_role | origin shared_buffers | 131072 shared_preload_libraries | silent_mode | off sql_inheritance | on ssl | on ssl_ciphers | ALL:!ADH:!LOW:!EXP:!MD5:@STRENGTH standard_conforming_strings | off statement_timeout | 0 superuser_reserved_connections | 3 synchronize_seqscans | on synchronous_commit | on syslog_facility | LOCAL0 syslog_ident | postgres tcp_keepalives_count | 0 tcp_keepalives_idle | 0 tcp_keepalives_interval | 0 temp_buffers | 10240 temp_tablespaces | TimeZone | Europe/Sofia timezone_abbreviations | Default trace_notify | off trace_sort | off track_activities | on track_counts | on transaction_isolation | read committed transaction_read_only | off transform_null_equals | off unix_socket_directory | unix_socket_group | unix_socket_permissions | 511 update_process_title | on vacuum_cost_delay | 0 vacuum_cost_limit | 200 vacuum_cost_page_dirty | 20 vacuum_cost_page_hit | 1 vacuum_cost_page_miss | 10 vacuum_freeze_min_age | 100000000 wal_buffers | 8 wal_sync_method | open_sync wal_writer_delay | 200 work_mem | 65536 xmlbinary | base64 xmloption | content zero_damaged_pages | off (189 rows) -- Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general -- Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
