Non-deterministic 100% CPU hang on postgres 9.3

Hi all,

I'm experiencing an issue where certain queries appear to
non-deterministically "hang", with a CPU pinned at 100%.

I say "hang", where really I've given up after ~12 hours execution. The
exact same query can then be terminated and run in <90 seconds, with none
of the underlying data changing.

I can completely reset the DB (drop tables/recreate) and re-run and
sometimes certain queries will appear to hang forever, sometimes they will
execute in minutes.

I've tried official debian (amd64) packages of postgres 9.3.2 - 9.3.4 (same
issues).

The workload is ostensibly analytics - As a disclaimer I absolutely
understand that these queries may not be non-optimized (I didn't build
them/have not reviewed fully). The part I'm trying to work out is why they
sometimes finish easily in minutes and other times hang.

I've straced the process when it's pinned and there appears to be no system
calls (ie: no IO) just a pure CPU loop.

If anyone could explain this behaviour, or even how I might go about
diagnosing, that would be wonderful.

Query/analyze details follow.

Thanks!

Query:
----
UPDATE ad_events e
set ad_user_id = x.ad_user_id, ad_session_id = x.ad_session_id
FROM
(SELECT t.ad_event_id, COALESCE (s.ad_user_id, u.merged_id,u.ad_user_id)
ad_user_id,
case when (name = 'Clickthrough from Email' or properties->('mp_lib')
= 'web' ) then s.ad_session_id
else null
end as ad_session_id,
t.timestamp, name , properties
from ad_events_mv t
INNER JOIN ad_users u ON (t.user_id = u.orig_distinct_id)
LEFT OUTER JOIN ad_sessions s ON (t.timestamp between s.session_start
and s.session_end and (s.ad_user_id = u.ad_user_id or s.ad_user_id =
u.merged_id))
where t.processed = false
order by s.ad_user_id, s.ad_session_id, timestamp) x
WHERE
x.ad_event_id = e.ad_event_id;
----

EXPLAIN ANALYZE follows: QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Update on ad_events e (cost=39730372.92..39765372.92 rows=1000000
width=237) (actual time=130140.450..130140.450 rows=0 loops=1)
-> Hash Join (cost=39730372.92..39765372.92 rows=1000000 width=237)
(actual time=54243.877..66848.448 rows=2000000 loops=1)
Hash Cond: (x.ad_event_id = e.ad_event_id)
-> Subquery Scan on x (cost=39654433.45..39666933.45
rows=1000000 width=144) (actual time=52682.740..57668.998 rows=2000000
loops=1)
-> Sort (cost=39654433.45..39656933.45 rows=1000000
width=108) (actual time=52682.693..55003.467 rows=2000000 loops=1)
Sort Key: s.ad_user_id, s.ad_session_id, t."timestamp"
Sort Method: external merge Disk: 1078104kB
-> Nested Loop Left Join (cost=12054.20..39554775.61
rows=1000000 width=108) (actual time=204.872..43742.396 rows=2000000
loops=1)
Join Filter: ((t."timestamp" >= s.session_start)
AND (t."timestamp" <= s.session_end))
Rows Removed by Join Filter: 18792613
-> Hash Join (cost=12046.09..203878.09
rows=1000000 width=92) (actual time=204.402..4293.175 rows=2000000 loops=1)
Hash Cond: (t.user_id = u.orig_distinct_id)
-> Seq Scan on ad_events_mv t
(cost=0.00..173082.00 rows=1000000 width=112) (actual time=0.022..1813.272
rows=2000000 loops=1)
Filter: (NOT processed)
-> Hash (cost=7932.15..7932.15
rows=329115 width=67) (actual time=204.166..204.166 rows=329115 loops=1)
Buckets: 65536 Batches: 1 Memory
Usage: 30590kB
-> Seq Scan on ad_users u
(cost=0.00..7932.15 rows=329115 width=67) (actual time=0.009..85.231
rows=329115 loops=1)
-> Bitmap Heap Scan on ad_sessions s
(cost=8.11..39.22 rows=8 width=32) (actual time=0.007..0.015 rows=10
loops=2000000)
Recheck Cond: ((ad_user_id = u.ad_user_id)
OR (ad_user_id = u.merged_id))
-> BitmapOr (cost=8.11..8.11 rows=8
width=0) (actual time=0.005..0.005 rows=0 loops=2000000)
-> Bitmap Index Scan on
ad_sessions_ad_user_id_idx (cost=0.00..4.05 rows=4 width=0) (actual
time=0.003..0.003 rows=8 loops=2000000)
Index Cond: (ad_user_id =
u.ad_user_id)
-> Bitmap Index Scan on
ad_sessions_ad_user_id_idx (cost=0.00..4.05 rows=4 width=0) (actual
time=0.001..0.001 rows=3 loops=2000000)
:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Update on ad_events e (cost=39730372.92..39765372.92 rows=1000000
width=237) (actual time=130140.450..130140.450 rows=0 loops=1)
-> Hash Join (cost=39730372.92..39765372.92 rows=1000000 width=237)
(actual time=54243.877..66848.448 rows=2000000 loops=1)
Hash Cond: (x.ad_event_id = e.ad_event_id)
-> Subquery Scan on x (cost=39654433.45..39666933.45
rows=1000000 width=144) (actual time=52682.740..57668.998 rows=2000000
loops=1)
-> Sort (cost=39654433.45..39656933.45 rows=1000000
width=108) (actual time=52682.693..55003.467 rows=2000000 loops=1)
Sort Key: s.ad_user_id, s.ad_session_id, t."timestamp"
Sort Method: external merge Disk: 1078104kB
-> Nested Loop Left Join (cost=12054.20..39554775.61
rows=1000000 width=108) (actual time=204.872..43742.396 rows=2000000
loops=1)
Join Filter: ((t."timestamp" >= s.session_start)
AND (t."timestamp" <= s.session_end))
Rows Removed by Join Filter: 18792613
-> Hash Join (cost=12046.09..203878.09
rows=1000000 width=92) (actual time=204.402..4293.175 rows=2000000 loops=1)
Hash Cond: (t.user_id = u.orig_distinct_id)
-> Seq Scan on ad_events_mv t
(cost=0.00..173082.00 rows=1000000 width=112) (actual time=0.022..1813.272
rows=2000000 loops=1)
Filter: (NOT processed)
-> Hash (cost=7932.15..7932.15
rows=329115 width=67) (actual time=204.166..204.166 rows=329115 loops=1)
Buckets: 65536 Batches: 1 Memory
Usage: 30590kB
-> Seq Scan on ad_users u
(cost=0.00..7932.15 rows=329115 width=67) (actual time=0.009..85.231
rows=329115 loops=1)
-> Bitmap Heap Scan on ad_sessions s
(cost=8.11..39.22 rows=8 width=32) (actual time=0.007..0.015 rows=10
loops=2000000)
Recheck Cond: ((ad_user_id = u.ad_user_id)
OR (ad_user_id = u.merged_id))
-> BitmapOr (cost=8.11..8.11 rows=8
width=0) (actual time=0.005..0.005 rows=0 loops=2000000)
-> Bitmap Index Scan on
ad_sessions_ad_user_id_idx (cost=0.00..4.05 rows=4 width=0) (actual
time=0.003..0.003 rows=8 loops=2000000)
Index Cond: (ad_user_id =
u.ad_user_id)
-> Bitmap Index Scan on
ad_sessions_ad_user_id_idx (cost=0.00..4.05 rows=4 width=0) (actual
time=0.001..0.001 rows=3 loops=2000000)
Index Cond: (ad_user_id =
u.merged_id)
-> Hash (cost=50938.65..50938.65 rows=2000065 width=101) (actual
time=1560.037..1560.037 rows=2000000 loops=1)
Buckets: 262144 Batches: 1 Memory Usage: 253047kB
-> Seq Scan on ad_events e (cost=0.00..50938.65
rows=2000065 width=101) (actual time=0.014..633.555 rows=2000000 loops=1)