Changing ORDER BY column slows query dramatically

Hi,

(I have put the contents of this email at http://pastebin.com/6h49zrYE
for better readibility)

I have been circling around the following problem for a few hours and
I am wondering if anyone has any suggestions about why the the second
query is taking so much longer than the first.
Both tables have similar row counts, all tables are partitions, though
the queries are querying the partitions directly, not the parent
tables.
The 'DELIVERED' status comprises almost 100% of the rows in the
notification_xxx tables.
ANALYZE was run right before each query was issued.
This test database is on EC2. PG 9.2.4, CentOS release 5.9, 70GB RAM.
GUC changes listed at the bottom. Are there any other details I can supply?
Note that the same behaviour occurred on 9.2.3, but I cannot say for
sure for whether it occurred on 9.2.2.
Dropping the random_page_cost to 1 helped the slow query (after it is
cached, drops down to about 1.7s).
Setting enable_mergejoin to false causes the slow query to choose a
Nested Loop and shaves off about 30% of the execution time.



-- Fast query, first run, uncached, ORDER BY nearly-unique tstamp_utc
explain (analyze, buffers)
SELECT e.id,e.device,e.engine,e.form,e.device_type_id,ncbs.delivery_tstamp_utc
FROM  event_20130404 e
INNER JOIN notifications_20130404 ncbs ON (e.id = ncbs.event_id)
WHERE TRUE
AND e.date_utc = '2013-04-04'
AND e.tstamp_utc BETWEEN '2013-04-04 10:00:00' AND '2013-04-04 18:00:00'
AND e.org_id = 216471
AND ncbs.event_creation_tstamp_utc BETWEEN '2013-04-04 10:00:00' AND
'2013-04-04 18:00:00'
AND ncbs.status = 'DELIVERED'
ORDER BY e.tstamp_utc desc
offset 10000 limit 100;

 Limit  (cost=29639.24..29935.63 rows=100 width=50) (actual
time=159.103..167.637 rows=100 loops=1)
   Buffers: shared hit=46588 read=1055
   I/O Timings: read=63.416
   ->  Nested Loop  (cost=0.00..1882500.73 rows=635138 width=50)
(actual time=0.240..159.693 rows=10100 loops=1)
         Buffers: shared hit=46588 read=1055
         I/O Timings: read=63.416
         ->  Index Scan Backward using
event_20130404_tstamp_utc_org_id_idx on event_20130404 e
(cost=0.00..315412.34 rows=1876877 width=42) (actual
time=0.129..61.981 rows=10100 loops=1)
               Index Cond: ((tstamp_utc >= '2013-04-04
10:00:00'::timestamp without time zone) AND (tstamp_utc <= '2013-04-04
18:00:00'::timestamp without time zone) AND (org_id = 216471))
               Filter: (date_utc = '2013-04-04'::date)
               Buffers: shared hit=6309 read=833
               I/O Timings: read=40.380
         ->  Index Scan using
notifications_20130404_event_id_org_id_pk on notifications_20130404
ncbs  (cost=0.00..0.82 rows=1 width=16) (actual time=0.006..0.006
rows=1 loops=10100)
               Index Cond: (event_id = e.id)
               Filter: ((event_creation_tstamp_utc >= '2013-04-04
10:00:00'::timestamp without time zone) AND (event_creation_tstamp_utc
<= '2013-04-04 18:00:00'::timestamp without time zone) AND (status =
'DELIVERED'::text))
               Buffers: shared hit=40279 read=222
               I/O Timings: read=23.036
 Total runtime: 170.436 ms
(17 rows)




-- Slow query, uncached, ORDER BY primary key
explain (analyze,buffers)
SELECT e.device,e.id,e.engine,e.form,e.device_type_id,ncbs.delivery_tstamp_utc
FROM  event_20130405 e
INNER JOIN notifications_20130405 ncbs ON (e.id = ncbs.event_id)
WHERE TRUE
AND e.date_utc = '2013-04-05'
AND e.tstamp_utc BETWEEN '2013-04-05 10:00:00' AND '2013-04-05 18:00:00'
AND e.org_id = 216471
AND ncbs.event_creation_tstamp_utc BETWEEN '2013-04-05 10:00:00' AND
'2013-04-05 18:00:00'
AND ncbs.status = 'DELIVERED'
ORDER BY e.id desc
OFFSET 10000 LIMIT 100;

 Limit  (cost=14305.61..14447.99 rows=100 width=42) (actual
time=13949.028..13950.353 rows=100 loops=1)
   Buffers: shared hit=2215465 read=141796 written=12128
   I/O Timings: read=11308.341 write=116.673
   ->  Merge Join  (cost=67.31..887063.35 rows=622965 width=42)
(actual time=13761.135..13933.879 rows=10100 loops=1)
         Merge Cond: (e.id = ncbs.event_id)
         Buffers: shared hit=2215465 read=141796 written=12128
         I/O Timings: read=11308.341 write=116.673
         ->  Index Scan Backward using event_20130405_id_pk on
event_20130405 e  (cost=0.00..612732.34 rows=1889715 width=34) (actual
time=2076.812..2111.274 rows=10100 loops=1)
               Filter: ((tstamp_utc >= '2013-04-05
10:00:00'::timestamp without time zone) AND (tstamp_utc <= '2013-04-05
18:00:00'::timestamp without time zone) AND (date_utc =
'2013-04-05'::date) AND (org_id = 216471))
               Rows Removed by Filter: 1621564
               Buffers: shared hit=1176391 read=113344 written=11918
               I/O Timings: read=774.769 write=113.095
         ->  Index Scan Backward using
notifications_20130405_event_id_org_id_pk on notifications_20130405
ncbs  (cost=0.00..258079.61 rows=2135847 width=16) (actual
time=11684.312..11784.738 rows=11653 loops=1)
               Filter: ((event_creation_tstamp_utc >= '2013-04-05
10:00:00'::timestamp without time zone) AND (event_creation_tstamp_utc
<= '2013-04-05 18:00:00'::timestamp without time zone) AND (status =
'DELIVERED'::text))
               Rows Removed by Filter: 1620011
               Buffers: shared hit=1039074 read=28452 written=210
               I/O Timings: read=10533.572 write=3.578
 Total runtime: 13950.458 ms
(18 rows)


select * from admin.changed_guc_settings ;
              name               |
           current_setting

---------------------------------+---------------------------------------------------------------------------------------------------------------
 version                         | PostgreSQL 9.2.4 on
x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.1.2 20080704 (Red
Hat 4.1.2-52), 64-bit
 autovacuum_analyze_scale_factor | 0.01
 autovacuum_naptime              | 20s
 autovacuum_vacuum_cost_delay    | 5ms
 autovacuum_vacuum_cost_limit    | 1000
 autovacuum_vacuum_scale_factor  | 0.01
 autovacuum_vacuum_threshold     | 50
 bgwriter_lru_maxpages           | 400
 checkpoint_completion_target    | 0.8
 checkpoint_segments             | 64
 client_encoding                 | UTF8
 commit_delay                    | 10
 effective_cache_size            | 54GB
 effective_io_concurrency        | 4
 lc_collate                      | en_US.UTF-8
 lc_ctype                        | en_US.UTF-8
 log_autovacuum_min_duration     | 0
 log_filename                    | postgresql-%Y-%m-%d.log
 log_line_prefix                 | %t [%p]: [%l-1] (user=%u) (rhost=%h) (db=%d)
 log_lock_waits                  | on
 log_min_duration_statement      | 100ms
 log_temp_files                  | 0
 logging_collector               | on
 maintenance_work_mem            | 6GB
 max_connections                 | 200
 max_locks_per_transaction       | 100
 max_stack_depth                 | 6MB
 pg_stat_statements.max          | 1000
 pg_stat_statements.track        | all
 random_page_cost                | 1
 search_path                     | "$user",public,admin
 server_encoding                 | UTF8
 shared_buffers                  | 6GB
 shared_preload_libraries        | pg_stat_statements
 track_activity_query_size       | 6144
 track_functions                 | pl
 track_io_timing                 | on
 vacuum_cost_limit               | 2000
 wal_buffers                     | 16MB
 wal_keep_segments               | 100
 wal_level                       | minimal
 work_mem                        | 900MB




test01=# \d event_20130406
                                              Table "public.event_20130406"
        Column         |            Type             |
            Modifiers

-----------------------+-----------------------------+-------------------------------------------------------------------
 id                    | bigint                      | not null
default nextval('event_id_seq'::regclass)
 org_id                | integer                     | not null
 date_utc              | date                        | not null
default (timezone('UTC'::text, clock_timestamp()))::date
 tstamp_utc            | timestamp without time zone | not null
default timezone('UTC'::text, clock_timestamp())
 device                | text                        | not null
 provider              | text                        | not null
 form                  | text                        |
 engine                | text                        |
 user_service_provider | text                        |
 sender                | text                        |
 properties            | json                        |
 delivery_windows      | json                        |
 device_type_id        | smallint                    |
Indexes:
    "event_20130406_id_pk" PRIMARY KEY, btree (id) WITH (fillfactor=100)
    "event_20130406_date_utc_idx" btree (date_utc) WITH (fillfactor=100)
    "event_20130406_device_type_id_idx" btree (device_type_id) WITH
(fillfactor=100)
    "event_20130406_org_id_idx" btree (org_id) WITH (fillfactor=100)
    "event_20130406_tstamp_utc_org_id_idx" btree (tstamp_utc, org_id)
WITH (fillfactor=100)
Check constraints:
    "event_20130406_date_utc_check" CHECK (date_utc = '2013-04-06'::date)


test01=# \d notification_counts_by_status_20130406
        Table "public.notification_counts_by_status_20130406"
          Column           |            Type             | Modifiers
---------------------------+-----------------------------+-----------
 event_id                  | bigint                      | not null
 org_id                    | integer                     | not null
 status                    | text                        | not null
 tstamp_utc                | timestamp without time zone | not null
 event_creation_tstamp_utc | timestamp without time zone | not null
 delivery_tstamp_utc       | timestamp without time zone |
Indexes:
    "notification_counts_by_status_20130406_event_id_org_id_pk"
PRIMARY KEY, btree (event_id, org_id)
    "ncbs_20120406_delivery_tstamp_utc_pidx" btree
(delivery_tstamp_utc) WHERE delivery_tstamp_utc IS NOT NULL
    "notification_counts_by_status_20130406_ectu_idx" btree
(event_creation_tstamp_utc) WITH (fillfactor=66)
    "notification_counts_by_status_20130406_org_id_idx" btree (org_id)
WITH (fillfactor=98)
    "notification_counts_by_status_20130406_status_idx" btree (status)
WITH (fillfactor=66)
Check constraints:
    "ncbs_20130406_ectu_ck" CHECK (event_creation_tstamp_utc >=
'2013-04-06 00:00:00'::timestamp without time zone AND
event_creation_tstamp_utc < '2013-04-07 00:00:00'::timestamp without
time zone)
Inherits: notification_counts_by_status


-- Row counts, in case that is useful
test01=# select count(*) from event_20130404:
6,354,940
test01=# select count(*) from event_20130404 where tstamp_utc BETWEEN
'2013-04-04 10:00:00' AND '2013-04-04 18:00:00';
2,157,002

test01=# select count(*) from event_20130405 where tstamp_utc BETWEEN
'2013-04-05 10:00:00' AND '2013-04-05 18:00:00';
2,160,009
test01=# select count(*) from event_20130405;
6,479,278


test01=# select count(*) from notification_counts_by_status_20130404
where event_creation_tstamp_utc BETWEEN '2013-04-04 10:00:00' AND
'2013-04-04 18:00:00';
2,157,000

test01=# select count(*) from notification_counts_by_status_20130405
where event_creation_tstamp_utc BETWEEN '2013-04-05 10:00:00' AND
'2013-04-05 18:00:00';
2,160,009