2 Improved formatting
source | link

explain analyze SELECT DISTINCT ac.player_id, gvt.game_type, first_value(platform) over (partition by acs.start_ts, acs.account_id order by start_ts desc rows between unbounded preceding and unbounded following) platform, date_trunc('hour', ac.audit_ts), first_value(audit_ts) over (partition by platform, game_type, acs.account_id order by audit_ts desc rows between unbounded preceding and unbounded following) FROM audit_command ac JOIN table_definition td ON ac.table_id = td.table_id JOIN game_variation_template gvt ON td.game_variation_template_id = gvt.game_variation_template_id LEFT JOIN player_definition p ON ac.player_id = p.player_id LEFT JOIN account_session acs ON p.account_id = acs.account_id WHERE ac.command_type::text <> 'Leave'::text AND ac.command_type::text <> 'GetStatus'::text and start_ts < audit_ts and start_ts >= audit_ts - interval '1 day' AND ac.audit_ts between '2014-06-26T02:10:01.017+01:00' AND '2014-06-27T02:10:01.017+01:00' ;

QUERY PLAN

explain analyze SELECT DISTINCT ac.player_id, gvt.game_type,
 first_value(platform) over (partition by acs.start_ts, acs.account_id
 order by start_ts desc rows between unbounded preceding and unbounded following) platform,
 date_trunc('hour', ac.audit_ts),
 first_value(audit_ts) over
   (partition by platform, game_type, acs.account_id
  order by audit_ts desc rows between unbounded preceding and unbounded following)
 FROM audit_command ac
 JOIN table_definition td ON ac.table_id = td.table_id
 JOIN game_variation_template gvt ON td.game_variation_template_id = gvt.game_variation_template_id
 LEFT JOIN player_definition p ON ac.player_id = p.player_id
 LEFT JOIN account_session acs ON p.account_id = acs.account_id
 WHERE ac.command_type::text <> 'Leave'::text AND ac.command_type::text <> 'GetStatus'::text
 and start_ts < audit_ts and start_ts >= audit_ts - interval '1 day'
 AND ac.audit_ts between '2014-06-26T02:10:01.017+01:00' AND '2014-06-27T02:10:01.017+01:00'
;

HashAggregate (cost=4781863.47..4824152.70 rows=3383139 width=47) (actual time=1783393.417..1783412.946 rows=34251 loops=1) -> WindowAgg (cost=4646537.91..4739574.23 rows=3383139 width=47) (actual time=1735317.999..1772580.060 rows=14568155 loops=1) -> Sort (cost=4646537.91..4654995.75 rows=3383139 width=47) (actual time=1735317.969..1756145.084 rows=14568155 loops=1) Sort Key: acs.platform, gvt.game_type, acs.account_id, ac.audit_ts Sort Method: external merge Disk: 1108544kB -> WindowAgg (cost=4211974.87..4279637.65 rows=3383139 width=47) (actual time=1125155.357..1140058.023 rows=14568155 loops=1) -> Sort (cost=4211974.87..4220432.72 rows=3383139 width=47) (actual time=1125141.693..1128195.716 rows=14568155 loops=1) Sort Key: acs.start_ts, acs.account_id Sort Method: external sort Disk: 975392kB -> Hash Join (cost=1274416.28..3845074.61 rows=3383139 width=47) (actual time=1034359.154..1098242.110 rows=14568155 loops=1) Hash Cond: (td.game_variation_template_id = gvt.game_variation_template_id) -> Hash Join (cost=1274374.79..3798514.96 rows=3383139 width=42) (actual time=1034359.024..1091131.468 rows=14568155 loops=1) Hash Cond: (ac.table_id = td.table_id) -> Hash Join (cost=1217034.45..3665053.99 rows=3383139 width=46) (actual time=1033746.587..1082753.263 rows=14568157 loops=1) Hash Cond: (acs.account_id = lobby_user.account_id) Join Filter: ((acs.start_ts < ac.audit_ts) AND (acs.start_ts >= (ac.audit_ts - '1 day'::interval))) Rows Removed by Join Filter: 1953618923 -> Seq Scan on account_session acs (cost=0.00..1507571.65 rows=46583265 width=22) (actual time=0.004..56952.205 rows=43264444 loops=1) -> Hash (cost=1150844.59..1150844.59 rows=5295189 width=31) (actual time=15666.924..15666.924 rows=3835505 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 253959kB -> Hash Join (cost=691441.16..1150844.59 rows=5295189 width=31) (actual time=7817.384..13276.084 rows=3835524 loops=1) Hash Cond: (ac.player_id = lobby_user.player_id) -> Index Scan using audit_command_ts_idx on audit_command ac (cost=0.57..340262.25 rows=5295189 width=24) (actual time=0.025..2697.823 rows=3835524 loops=1) Index Cond: ((audit_ts >= '2014-06-26 02:10:01.017'::timestamp without time zone) AND (audit_ts <= '2014-06-27 02:10:01.017'::timestamp without time zone)) Filter: (((command_type)::text <> 'Leave'::text) AND ((command_type)::text <> 'GetStatus'::text)) Rows Removed by Filter: 16517 -> Hash (cost=590189.15..590189.15 rows=8100115 width=14) (actual time=7813.606..7813.606 rows=8300768 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 377469kB -> Seq Scan on lobby_user (cost=0.00..590189.15 rows=8100115 width=14) (actual time=0.020..3667.951 rows=8300768 loops=1) -> Hash (cost=32174.04..32174.04 rows=2013304 width=12) (actual time=611.500..611.500 rows=1952805 loops=1) Buckets: 262144 Batches: 1 Memory Usage: 84599kB -> Seq Scan on table_definition td (cost=0.00..32174.04 rows=2013304 width=12) (actual time=0.007..198.591 rows=1952805 loops=1) -> Hash (cost=39.55..39.55 rows=155 width=15) (actual time=0.116..0.116 rows=155 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 8kB -> Seq Scan on game_variation_template gvt (cost=0.00..39.55 rows=155 width=15) (actual time=0.009..0.067 rows=155 loops=1)


                                    QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate  (cost=4781863.47..4824152.70 rows=3383139 width=47) (actual time=1783393.417..1783412.946 rows=34251 loops=1)
 ->  WindowAgg  (cost=4646537.91..4739574.23 rows=3383139 width=47) (actual time=1735317.999..1772580.060 rows=14568155 loops=1)
   ->  Sort  (cost=4646537.91..4654995.75 rows=3383139 width=47) (actual time=1735317.969..1756145.084 rows=14568155 loops=1)
     Sort Key: acs.platform, gvt.game_type, acs.account_id, ac.audit_ts
     Sort Method: external merge  Disk: 1108544kB
     ->  WindowAgg  (cost=4211974.87..4279637.65 rows=3383139 width=47) (actual time=1125155.357..1140058.023 rows=14568155 loops=1)
       ->  Sort  (cost=4211974.87..4220432.72 rows=3383139 width=47) (actual time=1125141.693..1128195.716 rows=14568155 loops=1)
         Sort Key: acs.start_ts, acs.account_id
         Sort Method: external sort  Disk: 975392kB
         ->  Hash Join  (cost=1274416.28..3845074.61 rows=3383139 width=47) (actual time=1034359.154..1098242.110 rows=14568155 loops=1)
           Hash Cond: (td.game_variation_template_id = gvt.game_variation_template_id)
           ->  Hash Join  (cost=1274374.79..3798514.96 rows=3383139 width=42) (actual time=1034359.024..1091131.468 rows=14568155 loops=1)
             Hash Cond: (ac.table_id = td.table_id)
             ->  Hash Join  (cost=1217034.45..3665053.99 rows=3383139 width=46) (actual time=1033746.587..1082753.263 rows=14568157 loops=1)
               Hash Cond: (acs.account_id = lobby_user.account_id)
               Join Filter: ((acs.start_ts < ac.audit_ts) AND (acs.start_ts >= (ac.audit_ts - '1 day'::interval)))
               Rows Removed by Join Filter: 1953618923
               ->  Seq Scan on account_session acs  (cost=0.00..1507571.65 rows=46583265 width=22) (actual time=0.004..56952.205 rows=43264444 loops=1)
               ->  Hash  (cost=1150844.59..1150844.59 rows=5295189 width=31) (actual time=15666.924..15666.924 rows=3835505 loops=1)
                 Buckets: 1048576  Batches: 1  Memory Usage: 253959kB
                 ->  Hash Join  (cost=691441.16..1150844.59 rows=5295189 width=31) (actual time=7817.384..13276.084 rows=3835524 loops=1)
                   Hash Cond: (ac.player_id = lobby_user.player_id)
                   ->  Index Scan using audit_command_ts_idx on audit_command ac  (cost=0.57..340262.25 rows=5295189 width=24) (actual time=0.025..2697.823 rows=3835524 loops=1)
                     Index Cond: ((audit_ts >= '2014-06-26 02:10:01.017'::timestamp without time zone) AND (audit_ts <= '2014-06-27 02:10:01.017'::timestamp without time zone))
                     Filter: (((command_type)::text <> 'Leave'::text) AND ((command_type)::text <> 'GetStatus'::text))
                     Rows Removed by Filter: 16517
                   ->  Hash  (cost=590189.15..590189.15 rows=8100115 width=14) (actual time=7813.606..7813.606 rows=8300768 loops=1)
                     Buckets: 1048576  Batches: 1  Memory Usage: 377469kB
                     ->  Seq Scan on lobby_user  (cost=0.00..590189.15 rows=8100115 width=14) (actual time=0.020..3667.951 rows=8300768 loops=1)
             ->  Hash  (cost=32174.04..32174.04 rows=2013304 width=12) (actual time=611.500..611.500 rows=1952805 loops=1)
               Buckets: 262144  Batches: 1  Memory Usage: 84599kB
               ->  Seq Scan on table_definition td  (cost=0.00..32174.04 rows=2013304 width=12) (actual time=0.007..198.591 rows=1952805 loops=1)
           ->  Hash  (cost=39.55..39.55 rows=155 width=15) (actual time=0.116..0.116 rows=155 loops=1)
             Buckets: 1024  Batches: 1  Memory Usage: 8kB
             ->  Seq Scan on game_variation_template gvt  (cost=0.00..39.55 rows=155 width=15) (actual time=0.009..0.067 rows=155 loops=1)
analyze verbose audit_command;
INFO:  analyzing "public.audit_command"
INFO:  "audit_command": scanned 30000 of 15429435 pages, containing 861531 live rows and 39590 dead rows; 30000 rows in sample, 586507527 estimated total rows

analyze verbose audit_command; INFO: analyzing "public.audit_command" INFO: "audit_command": scanned 30000 of 15429435 pages, containing 861531 live rows and 39590 dead rows; 30000 rows in sample, 586507527 estimated total rows can can anyone tell me what the problem is and why it is so slow to execute (it is double the time it was previously)?

explain analyze SELECT DISTINCT ac.player_id, gvt.game_type, first_value(platform) over (partition by acs.start_ts, acs.account_id order by start_ts desc rows between unbounded preceding and unbounded following) platform, date_trunc('hour', ac.audit_ts), first_value(audit_ts) over (partition by platform, game_type, acs.account_id order by audit_ts desc rows between unbounded preceding and unbounded following) FROM audit_command ac JOIN table_definition td ON ac.table_id = td.table_id JOIN game_variation_template gvt ON td.game_variation_template_id = gvt.game_variation_template_id LEFT JOIN player_definition p ON ac.player_id = p.player_id LEFT JOIN account_session acs ON p.account_id = acs.account_id WHERE ac.command_type::text <> 'Leave'::text AND ac.command_type::text <> 'GetStatus'::text and start_ts < audit_ts and start_ts >= audit_ts - interval '1 day' AND ac.audit_ts between '2014-06-26T02:10:01.017+01:00' AND '2014-06-27T02:10:01.017+01:00' ;

QUERY PLAN

HashAggregate (cost=4781863.47..4824152.70 rows=3383139 width=47) (actual time=1783393.417..1783412.946 rows=34251 loops=1) -> WindowAgg (cost=4646537.91..4739574.23 rows=3383139 width=47) (actual time=1735317.999..1772580.060 rows=14568155 loops=1) -> Sort (cost=4646537.91..4654995.75 rows=3383139 width=47) (actual time=1735317.969..1756145.084 rows=14568155 loops=1) Sort Key: acs.platform, gvt.game_type, acs.account_id, ac.audit_ts Sort Method: external merge Disk: 1108544kB -> WindowAgg (cost=4211974.87..4279637.65 rows=3383139 width=47) (actual time=1125155.357..1140058.023 rows=14568155 loops=1) -> Sort (cost=4211974.87..4220432.72 rows=3383139 width=47) (actual time=1125141.693..1128195.716 rows=14568155 loops=1) Sort Key: acs.start_ts, acs.account_id Sort Method: external sort Disk: 975392kB -> Hash Join (cost=1274416.28..3845074.61 rows=3383139 width=47) (actual time=1034359.154..1098242.110 rows=14568155 loops=1) Hash Cond: (td.game_variation_template_id = gvt.game_variation_template_id) -> Hash Join (cost=1274374.79..3798514.96 rows=3383139 width=42) (actual time=1034359.024..1091131.468 rows=14568155 loops=1) Hash Cond: (ac.table_id = td.table_id) -> Hash Join (cost=1217034.45..3665053.99 rows=3383139 width=46) (actual time=1033746.587..1082753.263 rows=14568157 loops=1) Hash Cond: (acs.account_id = lobby_user.account_id) Join Filter: ((acs.start_ts < ac.audit_ts) AND (acs.start_ts >= (ac.audit_ts - '1 day'::interval))) Rows Removed by Join Filter: 1953618923 -> Seq Scan on account_session acs (cost=0.00..1507571.65 rows=46583265 width=22) (actual time=0.004..56952.205 rows=43264444 loops=1) -> Hash (cost=1150844.59..1150844.59 rows=5295189 width=31) (actual time=15666.924..15666.924 rows=3835505 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 253959kB -> Hash Join (cost=691441.16..1150844.59 rows=5295189 width=31) (actual time=7817.384..13276.084 rows=3835524 loops=1) Hash Cond: (ac.player_id = lobby_user.player_id) -> Index Scan using audit_command_ts_idx on audit_command ac (cost=0.57..340262.25 rows=5295189 width=24) (actual time=0.025..2697.823 rows=3835524 loops=1) Index Cond: ((audit_ts >= '2014-06-26 02:10:01.017'::timestamp without time zone) AND (audit_ts <= '2014-06-27 02:10:01.017'::timestamp without time zone)) Filter: (((command_type)::text <> 'Leave'::text) AND ((command_type)::text <> 'GetStatus'::text)) Rows Removed by Filter: 16517 -> Hash (cost=590189.15..590189.15 rows=8100115 width=14) (actual time=7813.606..7813.606 rows=8300768 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 377469kB -> Seq Scan on lobby_user (cost=0.00..590189.15 rows=8100115 width=14) (actual time=0.020..3667.951 rows=8300768 loops=1) -> Hash (cost=32174.04..32174.04 rows=2013304 width=12) (actual time=611.500..611.500 rows=1952805 loops=1) Buckets: 262144 Batches: 1 Memory Usage: 84599kB -> Seq Scan on table_definition td (cost=0.00..32174.04 rows=2013304 width=12) (actual time=0.007..198.591 rows=1952805 loops=1) -> Hash (cost=39.55..39.55 rows=155 width=15) (actual time=0.116..0.116 rows=155 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 8kB -> Seq Scan on game_variation_template gvt (cost=0.00..39.55 rows=155 width=15) (actual time=0.009..0.067 rows=155 loops=1)

analyze verbose audit_command; INFO: analyzing "public.audit_command" INFO: "audit_command": scanned 30000 of 15429435 pages, containing 861531 live rows and 39590 dead rows; 30000 rows in sample, 586507527 estimated total rows can anyone tell me what the problem is and why it is so slow to execute (it is double the time it was previously)?

explain analyze SELECT DISTINCT ac.player_id, gvt.game_type,
 first_value(platform) over (partition by acs.start_ts, acs.account_id
 order by start_ts desc rows between unbounded preceding and unbounded following) platform,
 date_trunc('hour', ac.audit_ts),
 first_value(audit_ts) over
   (partition by platform, game_type, acs.account_id
  order by audit_ts desc rows between unbounded preceding and unbounded following)
 FROM audit_command ac
 JOIN table_definition td ON ac.table_id = td.table_id
 JOIN game_variation_template gvt ON td.game_variation_template_id = gvt.game_variation_template_id
 LEFT JOIN player_definition p ON ac.player_id = p.player_id
 LEFT JOIN account_session acs ON p.account_id = acs.account_id
 WHERE ac.command_type::text <> 'Leave'::text AND ac.command_type::text <> 'GetStatus'::text
 and start_ts < audit_ts and start_ts >= audit_ts - interval '1 day'
 AND ac.audit_ts between '2014-06-26T02:10:01.017+01:00' AND '2014-06-27T02:10:01.017+01:00'
;

                                    QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate  (cost=4781863.47..4824152.70 rows=3383139 width=47) (actual time=1783393.417..1783412.946 rows=34251 loops=1)
 ->  WindowAgg  (cost=4646537.91..4739574.23 rows=3383139 width=47) (actual time=1735317.999..1772580.060 rows=14568155 loops=1)
   ->  Sort  (cost=4646537.91..4654995.75 rows=3383139 width=47) (actual time=1735317.969..1756145.084 rows=14568155 loops=1)
     Sort Key: acs.platform, gvt.game_type, acs.account_id, ac.audit_ts
     Sort Method: external merge  Disk: 1108544kB
     ->  WindowAgg  (cost=4211974.87..4279637.65 rows=3383139 width=47) (actual time=1125155.357..1140058.023 rows=14568155 loops=1)
       ->  Sort  (cost=4211974.87..4220432.72 rows=3383139 width=47) (actual time=1125141.693..1128195.716 rows=14568155 loops=1)
         Sort Key: acs.start_ts, acs.account_id
         Sort Method: external sort  Disk: 975392kB
         ->  Hash Join  (cost=1274416.28..3845074.61 rows=3383139 width=47) (actual time=1034359.154..1098242.110 rows=14568155 loops=1)
           Hash Cond: (td.game_variation_template_id = gvt.game_variation_template_id)
           ->  Hash Join  (cost=1274374.79..3798514.96 rows=3383139 width=42) (actual time=1034359.024..1091131.468 rows=14568155 loops=1)
             Hash Cond: (ac.table_id = td.table_id)
             ->  Hash Join  (cost=1217034.45..3665053.99 rows=3383139 width=46) (actual time=1033746.587..1082753.263 rows=14568157 loops=1)
               Hash Cond: (acs.account_id = lobby_user.account_id)
               Join Filter: ((acs.start_ts < ac.audit_ts) AND (acs.start_ts >= (ac.audit_ts - '1 day'::interval)))
               Rows Removed by Join Filter: 1953618923
               ->  Seq Scan on account_session acs  (cost=0.00..1507571.65 rows=46583265 width=22) (actual time=0.004..56952.205 rows=43264444 loops=1)
               ->  Hash  (cost=1150844.59..1150844.59 rows=5295189 width=31) (actual time=15666.924..15666.924 rows=3835505 loops=1)
                 Buckets: 1048576  Batches: 1  Memory Usage: 253959kB
                 ->  Hash Join  (cost=691441.16..1150844.59 rows=5295189 width=31) (actual time=7817.384..13276.084 rows=3835524 loops=1)
                   Hash Cond: (ac.player_id = lobby_user.player_id)
                   ->  Index Scan using audit_command_ts_idx on audit_command ac  (cost=0.57..340262.25 rows=5295189 width=24) (actual time=0.025..2697.823 rows=3835524 loops=1)
                     Index Cond: ((audit_ts >= '2014-06-26 02:10:01.017'::timestamp without time zone) AND (audit_ts <= '2014-06-27 02:10:01.017'::timestamp without time zone))
                     Filter: (((command_type)::text <> 'Leave'::text) AND ((command_type)::text <> 'GetStatus'::text))
                     Rows Removed by Filter: 16517
                   ->  Hash  (cost=590189.15..590189.15 rows=8100115 width=14) (actual time=7813.606..7813.606 rows=8300768 loops=1)
                     Buckets: 1048576  Batches: 1  Memory Usage: 377469kB
                     ->  Seq Scan on lobby_user  (cost=0.00..590189.15 rows=8100115 width=14) (actual time=0.020..3667.951 rows=8300768 loops=1)
             ->  Hash  (cost=32174.04..32174.04 rows=2013304 width=12) (actual time=611.500..611.500 rows=1952805 loops=1)
               Buckets: 262144  Batches: 1  Memory Usage: 84599kB
               ->  Seq Scan on table_definition td  (cost=0.00..32174.04 rows=2013304 width=12) (actual time=0.007..198.591 rows=1952805 loops=1)
           ->  Hash  (cost=39.55..39.55 rows=155 width=15) (actual time=0.116..0.116 rows=155 loops=1)
             Buckets: 1024  Batches: 1  Memory Usage: 8kB
             ->  Seq Scan on game_variation_template gvt  (cost=0.00..39.55 rows=155 width=15) (actual time=0.009..0.067 rows=155 loops=1)
analyze verbose audit_command;
INFO:  analyzing "public.audit_command"
INFO:  "audit_command": scanned 30000 of 15429435 pages, containing 861531 live rows and 39590 dead rows; 30000 rows in sample, 586507527 estimated total rows

can anyone tell me what the problem is and why it is so slow to execute (it is double the time it was previously)?

1
source | link

postgres explain plan with giant gaps between operations

I have a postgresql explain plan that seems to have large gaps between the join, sort & filter processes and can't explain (sorry) it. The query is taking an inordinate amount of time and the planned version is very different from the actual version. I tried upping the work_mem to 1500MB for this session but it is still swapping to disk (is this because there's 2 huge(1GB) sorts)?

explain analyze SELECT DISTINCT ac.player_id, gvt.game_type, first_value(platform) over (partition by acs.start_ts, acs.account_id order by start_ts desc rows between unbounded preceding and unbounded following) platform, date_trunc('hour', ac.audit_ts), first_value(audit_ts) over (partition by platform, game_type, acs.account_id order by audit_ts desc rows between unbounded preceding and unbounded following) FROM audit_command ac JOIN table_definition td ON ac.table_id = td.table_id JOIN game_variation_template gvt ON td.game_variation_template_id = gvt.game_variation_template_id LEFT JOIN player_definition p ON ac.player_id = p.player_id LEFT JOIN account_session acs ON p.account_id = acs.account_id WHERE ac.command_type::text <> 'Leave'::text AND ac.command_type::text <> 'GetStatus'::text and start_ts < audit_ts and start_ts >= audit_ts - interval '1 day' AND ac.audit_ts between '2014-06-26T02:10:01.017+01:00' AND '2014-06-27T02:10:01.017+01:00' ;

QUERY PLAN

HashAggregate (cost=4781863.47..4824152.70 rows=3383139 width=47) (actual time=1783393.417..1783412.946 rows=34251 loops=1) -> WindowAgg (cost=4646537.91..4739574.23 rows=3383139 width=47) (actual time=1735317.999..1772580.060 rows=14568155 loops=1) -> Sort (cost=4646537.91..4654995.75 rows=3383139 width=47) (actual time=1735317.969..1756145.084 rows=14568155 loops=1) Sort Key: acs.platform, gvt.game_type, acs.account_id, ac.audit_ts Sort Method: external merge Disk: 1108544kB -> WindowAgg (cost=4211974.87..4279637.65 rows=3383139 width=47) (actual time=1125155.357..1140058.023 rows=14568155 loops=1) -> Sort (cost=4211974.87..4220432.72 rows=3383139 width=47) (actual time=1125141.693..1128195.716 rows=14568155 loops=1) Sort Key: acs.start_ts, acs.account_id Sort Method: external sort Disk: 975392kB -> Hash Join (cost=1274416.28..3845074.61 rows=3383139 width=47) (actual time=1034359.154..1098242.110 rows=14568155 loops=1) Hash Cond: (td.game_variation_template_id = gvt.game_variation_template_id) -> Hash Join (cost=1274374.79..3798514.96 rows=3383139 width=42) (actual time=1034359.024..1091131.468 rows=14568155 loops=1) Hash Cond: (ac.table_id = td.table_id) -> Hash Join (cost=1217034.45..3665053.99 rows=3383139 width=46) (actual time=1033746.587..1082753.263 rows=14568157 loops=1) Hash Cond: (acs.account_id = lobby_user.account_id) Join Filter: ((acs.start_ts < ac.audit_ts) AND (acs.start_ts >= (ac.audit_ts - '1 day'::interval))) Rows Removed by Join Filter: 1953618923 -> Seq Scan on account_session acs (cost=0.00..1507571.65 rows=46583265 width=22) (actual time=0.004..56952.205 rows=43264444 loops=1) -> Hash (cost=1150844.59..1150844.59 rows=5295189 width=31) (actual time=15666.924..15666.924 rows=3835505 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 253959kB -> Hash Join (cost=691441.16..1150844.59 rows=5295189 width=31) (actual time=7817.384..13276.084 rows=3835524 loops=1) Hash Cond: (ac.player_id = lobby_user.player_id) -> Index Scan using audit_command_ts_idx on audit_command ac (cost=0.57..340262.25 rows=5295189 width=24) (actual time=0.025..2697.823 rows=3835524 loops=1) Index Cond: ((audit_ts >= '2014-06-26 02:10:01.017'::timestamp without time zone) AND (audit_ts <= '2014-06-27 02:10:01.017'::timestamp without time zone)) Filter: (((command_type)::text <> 'Leave'::text) AND ((command_type)::text <> 'GetStatus'::text)) Rows Removed by Filter: 16517 -> Hash (cost=590189.15..590189.15 rows=8100115 width=14) (actual time=7813.606..7813.606 rows=8300768 loops=1) Buckets: 1048576 Batches: 1 Memory Usage: 377469kB -> Seq Scan on lobby_user (cost=0.00..590189.15 rows=8100115 width=14) (actual time=0.020..3667.951 rows=8300768 loops=1) -> Hash (cost=32174.04..32174.04 rows=2013304 width=12) (actual time=611.500..611.500 rows=1952805 loops=1) Buckets: 262144 Batches: 1 Memory Usage: 84599kB -> Seq Scan on table_definition td (cost=0.00..32174.04 rows=2013304 width=12) (actual time=0.007..198.591 rows=1952805 loops=1) -> Hash (cost=39.55..39.55 rows=155 width=15) (actual time=0.116..0.116 rows=155 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 8kB -> Seq Scan on game_variation_template gvt (cost=0.00..39.55 rows=155 width=15) (actual time=0.009..0.067 rows=155 loops=1)

I had a feeling it was an un-vacuumed audit_command table, but the auto-vacuum ran over the weekend and the table is kicking out:

analyze verbose audit_command; INFO: analyzing "public.audit_command" INFO: "audit_command": scanned 30000 of 15429435 pages, containing 861531 live rows and 39590 dead rows; 30000 rows in sample, 586507527 estimated total rows can anyone tell me what the problem is and why it is so slow to execute (it is double the time it was previously)?