Performance degradation in 324577f39bc8738ed0ec24c36c5cb2c2f81ec660

After upgrade from 9.3.1 to 9.3.5 we expirienced a slight performance degradation of all queries. Query time increased to some amount of ms, mostly in range of 100ms. Some actions in our application results in a lot of small queries and in such cases performance degradation is very significant - total action performs for a 2-3 times longer then before (15s -> 40s, etc).

Using git-bisect we've found a bad revision causes performance drop: it is 324577f39bc8738ed0ec24c36c5cb2c2f81ec660

All tests were performed on the same server with same postgresql.conf, the only load on this server is postgresql test setup.

Here is example query plan of one query: http://explain.depesz.com/s/CWA
Anecdotally, when such a query executed in psql, it shows different results than when executes as a part of application-induced batch of queries. For example, the above query takes 24ms on "fast" postgres version, and 80ms on "slow" postgres versions. But when executed in "standalone" mode from psql, it takes 9.5-13 ms independently on postgres version. So we're logged all statements from our test suite using auto_explain module.

Here is query time difference on different postgresql versions:
# grep "duration: " 9.3-fast.log |awk '{sum += $6}; END { print sum}'
8309.05
# grep "duration: " 9.3.5.log |awk '{sum += $6}; END { print sum}'
24142

Log from postgres from 1 revision before bad: http://tgt72.ru/static/tmp/9.3-fast.log
Log from 9.3.5: http://tgt72.ru/static/tmp/9.3.5.log
Database schema: http://tgt72.ru/static/tmp/gits.sql

postgresql.conf:
data_directory = '/var/lib/postgresql/9.3/main' # use data in another directory
hba_file = '/etc/postgresql/9.3/main/pg_hba.conf' # host-based authentication file
ident_file = '/etc/postgresql/9.3/main/pg_ident.conf' # ident configuration file
external_pid_file = '/var/run/postgresql/9.3-main.pid' # write an extra PID file
listen_addresses = '*' # what IP address(es) to listen on;
port = 5432 # (change requires restart)
unix_socket_directories = '/var/run/postgresql' # comma-separated list of directories
ssl = true # (change requires restart)
ssl_cert_file = '/etc/ssl/certs/ssl-cert-snakeoil.pem' # (change requires restart)
ssl_key_file = '/etc/ssl/private/ssl-cert-snakeoil.key' # (change requires restart)
vacuum_cost_delay = 50
vacuum_cost_page_hit = 0
vacuum_cost_limit = 600
fsync = on # turns forced synchronization on or off
synchronous_commit = off # synchronization level;
log_line_prefix = '%t:%r:%u(at)%d:[%p]: '
log_statement = 'none' # none, ddl, mod, all
log_timezone = 'localtime'
autovacuum_max_workers = 4
autovacuum_vacuum_scale_factor = 0.0195
autovacuum_analyze_scale_factor = 0.05
autovacuum_freeze_max_age = 1000000000
autovacuum_vacuum_cost_limit = 300
vacuum_freeze_table_age = 500000000
datestyle = 'iso, dmy'
timezone = 'localtime'
client_encoding = utf8 # actually, defaults to database
lc_messages = 'en_US.UTF-8' # locale for system error message
lc_monetary = 'ru_RU.UTF-8' # locale for monetary formatting
lc_numeric = 'ru_RU.UTF-8' # locale for number formatting
lc_time = 'ru_RU.UTF-8' # locale for time formatting
default_text_search_config = 'pg_catalog.russian'
max_locks_per_transaction = 128 # min 10
default_statistics_target = 50 # pgtune wizard 2013-11-20
maintenance_work_mem = 1GB # pgtune wizard 2013-11-20
constraint_exclusion = on # pgtune wizard 2013-11-20
checkpoint_completion_target = 0.9 # pgtune wizard 2013-11-20
effective_cache_size = 12GB # pgtune wizard 2013-11-20
work_mem = 96MB # pgtune wizard 2013-11-20
wal_buffers = 8MB # pgtune wizard 2013-11-20
checkpoint_segments = 24
shared_buffers = 4GB # pgtune wizard 2013-11-20
max_connections = 300 # pgtune wizard 2013-11-20
shared_preload_libraries = 'auto_explain'
auto_explain.log_analyze = 1
auto_explain.log_min_duration = 0
auto_explain.log_buffers = 1
auto_explain.log_nested_statements = 1

Here is number of tuples estimation:
SELECT relname,reltuples::numeric FROM pg_class order by reltuples DESC limit 100;
relname | reltuples
-----------------------------------------------------------+-----------
schedule_line_audit_2013_06_time_fact_idx | 80649500
schedule_line_audit_2013_06_checkpoint_idx | 80649500
schedule_line_audit_2013_06_audit_timestamp_idx | 80649500
schedule_line_audit_2013_06_time_plan_idx | 80649500
schedule_line_audit_2013_06_pk | 80649500
schedule_line_audit_2013_06 | 80649500
schedule_line_audit_2013_06_schedule_end_datetime_idx | 80649500
schedule_line_audit_2013_06_id_idx | 80649500
tl_detector_zone_history_zone_id | 38235000
tl_detector_zone_history | 38235000
tl_detector_zone_history_pkey | 38235000
tl_detector_zone_history_datetime | 38235000
matching_matchingevent_2014_07_pk | 36870100
matching_matchingevent_2014_07 | 36870100
matching_matchingevent_2014_07_start_datetime_idx | 36870100
matching_matchingevent_2014_07_user_ignored_idx | 36870100
matching_matchingevent_2014_07_device_datetime_unique_idx | 36870100
matching_matchingevent_2014_07_device_idx | 36870100
matching_matchingevent_2014_09_start_datetime_idx | 36453900
matching_matchingevent_2014_09_user_ignored_idx | 36453900
matching_matchingevent_2014_09_device_datetime_unique_idx | 36453900
matching_matchingevent_2014_09_pk | 36453900
matching_matchingevent_2014_09 | 36453900
matching_matchingevent_2014_09_device_idx | 36453900
matching_matchingevent_2014_08_device_datetime_unique_idx | 36102100
matching_matchingevent_2014_08_device_idx | 36102100
matching_matchingevent_2014_08 | 36102100
matching_matchingevent_2014_08_start_datetime_idx | 36102100
matching_matchingevent_2014_08_user_ignored_idx | 36102100
matching_matchingevent_2014_08_pk | 36102100
schedule_line_audit_2013_03_schedule_end_datetime_idx | 30608400
schedule_line_audit_2013_03 | 30608400
schedule_line_audit_2013_03_audit_timestamp_idx | 30608400
schedule_line_audit_2013_03_time_fact_idx | 30608400
schedule_line_audit_2013_03_checkpoint_idx | 30608400
schedule_line_audit_2013_03_pk | 30608400
schedule_line_audit_2013_03_id_idx | 30608400
schedule_line_audit_2013_03_time_plan_idx | 30608400
schedule_line_audit_2014_07_checkpoint_idx | 29604500
schedule_line_audit_2014_07_time_plan_idx | 29604500
schedule_line_audit_2014_07_time_fact_idx | 29604500
schedule_line_audit_2014_07_pk | 29604500
schedule_line_audit_2014_07 | 29604500
schedule_line_audit_2014_07_id_idx | 29604500
schedule_line_audit_2014_07_audit_timestamp_idx | 29604500
schedule_line_audit_2014_07_schedule_end_datetime_idx | 29604500
schedule_line_audit_2014_09_id_idx | 28739900
schedule_line_audit_2014_09_audit_timestamp_idx | 28739900
schedule_line_audit_2014_09_schedule_end_datetime_idx | 28739900
schedule_line_audit_2014_09_time_fact_idx | 28739900
schedule_line_audit_2014_09_checkpoint_idx | 28739900
schedule_line_audit_2014_09_pk | 28739900
schedule_line_audit_2014_09_time_plan_idx | 28739900
schedule_line_audit_2014_09 | 28739900
matching_matchingevent_2014_06 | 27963800
matching_matchingevent_2014_06_user_ignored_idx | 27963800
matching_matchingevent_2014_06_device_idx | 27963800
matching_matchingevent_2014_06_pk | 27963800
matching_matchingevent_2014_06_start_datetime_idx | 27963800
matching_matchingevent_2014_06_device_datetime_unique_idx | 27963800
schedule_line_audit_2014_08 | 27197700
schedule_line_audit_2014_08_checkpoint_idx | 27197700
schedule_line_audit_2014_08_schedule_end_datetime_idx | 27197700
schedule_line_audit_2014_08_pk | 27197700
schedule_line_audit_2014_08_time_plan_idx | 27197700
schedule_line_audit_2014_08_time_fact_idx | 27197700
schedule_line_audit_2014_08_id_idx | 27197700
schedule_line_audit_2014_08_audit_timestamp_idx | 27197700
matching_matchingevent_2014_05_user_ignored_idx | 26968500
matching_matchingevent_2014_05_pk | 26968500
matching_matchingevent_2014_05_device_idx | 26968500
matching_matchingevent_2014_05_device_datetime_unique_idx | 26968500
matching_matchingevent_2014_05 | 26968500
matching_matchingevent_2014_05_start_datetime_idx | 26968500
schedule_line_audit_2014_06_audit_timestamp_idx | 25498800
schedule_line_audit_2014_06_time_plan_idx | 25498800
schedule_line_audit_2014_06_schedule_end_datetime_idx | 25498800
schedule_line_audit_2014_06_time_fact_idx | 25498800
schedule_line_audit_2014_06_id_idx | 25498800
schedule_line_audit_2014_06_pk | 25498800
schedule_line_audit_2014_06 | 25498800
schedule_line_audit_2014_06_checkpoint_idx | 25498800
schedule_line_audit_2013_08_audit_timestamp_idx | 25396100
schedule_line_audit_2013_08_pk | 25396100
schedule_line_audit_2013_08_time_plan_idx | 25396100
schedule_line_audit_2013_08_schedule_end_datetime_idx | 25396100
schedule_line_audit_2013_08_id_idx | 25396100
schedule_line_audit_2013_08_time_fact_idx | 25396100
schedule_line_audit_2013_08_checkpoint_idx | 25396100
schedule_line_audit_2013_08 | 25396100
schedule_line_audit_2014_05_id_idx | 24859700
schedule_line_audit_2014_05_pk | 24859700
schedule_line_audit_2014_05_checkpoint_idx | 24859700
schedule_line_audit_2014_05 | 24859700
schedule_line_audit_2014_05_time_fact_idx | 24859700
schedule_line_audit_2014_05_audit_timestamp_idx | 24859700
schedule_line_audit_2014_05_schedule_end_datetime_idx | 24859700
schedule_line_audit_2014_05_time_plan_idx | 24859700
matching_matchingevent_2014_04_device_idx | 24449500
matching_matchingevent_2014_04_start_datetime_idx | 24449500
(100 rows)