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)