difference in query plan when db is restored - Mailing list pgsql-general

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)