Re: Help with EXPLAIN ANALYZE runtimes

LOL ... Excuse my ignorance but what's Karnak headear?

It's a SELECT statement. There are no foreign-keys, just primary keys and
indexes (some clustered). All joins are through integers / big integers
(since anything beginning with id_ is either an integer or big integer).

The intention of showing an excerpt was to keep the focus of my question on
the two different runtimes - what these two runtimes mean (in contrast to
each other), and what causes them to be so different, so that I could tackle
the optimisation of the query. This obviously backfired :-(

Below are the EXPLAIN ANALYZE and queries in full. What has got me
bamboozled is how the query plan seems to report 51ms but it then reports a
final figure of over 11 seconds - why the huge jump?

Thanks and regards
Martin
________________________________

Start of EXPLAIN ANALYZE ...

SQL: Query Results
QUERY PLAN
Unique (cost=7.16..7.32 rows=3 width=188) (actual time=51.000..51.000
rows=16 loops=1)
-> Sort (cost=7.16..7.16 rows=3 width=188) (actual time=51.000..51.000
rows=16 loops=1)
Sort Key: am.id_assessment, c.id_claim, c.nm_claim, p.id_provider,
p.nm_title, p.nm_first, p.nm_last, ad.id_address, ad.nm_address_1,
ad.nm_address_2, ad.nm_address_3, ad.nm_suburb, ad.nm_city,
s.nm_state_short, ad.nm_postcode, am.dt_assessment, am.dt_booking,
ast.nm_assessmentstatus, ast.b_offer_report, asn.id_assessmentstatus,
asn.nm_assessmentstatus
-> Merge Join (cost=4.60..7.13 rows=3 width=188) (actual
time=41.000..51.000 rows=16 loops=1)
Merge Cond: ("outer".id_datastatus = "inner".id_datastatus)
Join Filter: (("inner".id_claim = "outer".id_claim) AND
("inner".id_assessment = "outer".id_assessment))
-> Nested Loop (cost=0.00..19.31 rows=8 width=97) (actual
time=0.000..0.000 rows=48 loops=1)
Join Filter: ("inner".id_datastatus =
"outer".id_datastatus)
-> Nested Loop (cost=0.00..16.09 rows=3 width=74)
(actual time=0.000..0.000 rows=16 loops=1)
Join Filter: (("inner".id_previous =
"outer".id_assessmentstatus) AND ("inner".id_datastatus =
"outer".id_datastatus))
-> Nested Loop (cost=0.00..8.23 rows=1 width=53)
(actual time=0.000..0.000 rows=2 loops=1)
Join Filter: (("outer".id_assessmentstatus =
"inner".id_assessmentstatus) AND ("inner".id_datastatus =
"outer".id_datastatus))
-> Nested Loop (cost=0.00..6.98 rows=1
width=20) (actual time=0.000..0.000 rows=2 loops=1)
Join Filter: ("inner".id_datastatus =
"outer".id_datastatus)
-> Index Scan using datastatus_pkey
on datastatus ds (cost=0.00..5.93 rows=1 width=8) (actual time=0.000..0.000
rows=1 loops=1)
Filter: (b_active <> 0)
-> Seq Scan on assessmentworkflow aw
(cost=0.00..1.02 rows=2 width=12) (actual time=0.000..0.000 rows=2 loops=1)
-> Seq Scan on assessmentstatus ast
(cost=0.00..1.10 rows=10 width=33) (actual time=0.000..0.000 rows=10
loops=2)
-> Merge Join (cost=0.00..7.23 rows=42 width=37)
(actual time=0.000..0.000 rows=42 loops=2)
Merge Cond: ("outer".id_assessmentstatus =
"inner".id_assessmentstatus)
Join Filter: ("outer".id_datastatus =
"inner".id_datastatus)
-> Index Scan using assessmentstatus_pkey
on assessmentstatus asn (cost=0.00..3.11 rows=10 width=29) (actual
time=0.000..0.000 rows=10 loops=2)
-> Index Scan using
idx_assessmenttransition_1 on assessmenttransition "at" (cost=0.00..3.46
rows=42 width=12) (actual time=0.000..0.000 rows=42 loops=2)
-> Seq Scan on claim c (cost=0.00..1.04 rows=3
width=23) (actual time=0.000..0.000 rows=3 loops=16)
Filter: (id_user = 1)
-> Sort (cost=4.60..4.60 rows=3 width=143) (actual
time=41.000..41.000 rows=97 loops=1)
Sort Key: p.id_datastatus
-> Merge Join (cost=3.94..4.57 rows=3 width=143)
(actual time=10.000..41.000 rows=3 loops=1)
Merge Cond: ("outer".id_provider =
"inner".id_provider)
Join Filter: (("inner".id_state =
"outer".id_state) AND ("outer".id_datastatus = "inner".id_datastatus))
-> Nested Loop (cost=0.00..508.65 rows=3336
width=51) (actual time=0.000..20.000 rows=2153 loops=1)
Join Filter: ("outer".id_datastatus =
"inner".id_datastatus)
-> Index Scan using provider_pkey on
provider p (cost=0.00..16.59 rows=417 width=33) (actual time=0.000..0.000
rows=270 loops=1)
-> Seq Scan on state s (cost=0.00..1.08
rows=8 width=18) (actual time=0.000..0.000 rows=8 loops=270)
-> Sort (cost=3.94..3.94 rows=3 width=108)
(actual time=10.000..10.000 rows=17 loops=1)
Sort Key: am.id_provider
-> Merge Join (cost=1.05..3.91 rows=3
width=108) (actual time=10.000..10.000 rows=3 loops=1)
Merge Cond: ("outer".id_address =
"inner".id_address)
Join Filter: ("outer".id_datastatus =
"inner".id_datastatus)
-> Index Scan using address_pkey on
address ad (cost=0.00..14.14 rows=376 width=76) (actual time=10.000..10.000
rows=82 loops=1)
-> Sort (cost=1.05..1.06 rows=3
width=36) (actual time=0.000..0.000 rows=3 loops=1)
Sort Key: am.id_address
-> Seq Scan on assessment am
(cost=0.00..1.03 rows=3 width=36) (actual time=0.000..0.000 rows=3 loops=1)
Total runtime: 51.000 ms

44 row(s)

Total runtime: 11,452.979 ms

... End of EXPLAIN ANALYZE

Start of query ...

SELECT DISTINCT am.id_assessment,
c.id_claim,
c.nm_claim,
p.id_provider,
p.nm_title,
p.nm_first,
p.nm_last,
ad.id_address,
ad.nm_address_1,
ad.nm_address_2,
ad.nm_address_3,
ad.nm_suburb,
ad.nm_city,
s.nm_state_short,
ad.nm_postcode,
am.dt_assessment,
am.dt_booking,
ast.nm_assessmentstatus,
ast.b_offer_report,
asn.id_assessmentstatus,
asn.nm_assessmentstatus
FROM assessment am,
address ad,
assessmentworkflow aw,
assessmenttransition at,
assessmentstatus ast,
assessmentstatus asn,
claim c,
state s,
provider p,
datastatus ds
WHERE am.id_claim = c.id_claim
AND am.id_assessment = aw.id_assessment
AND aw.id_assessmentstatus = ast.id_assessmentstatus
AND am.id_provider = p.id_provider
AND c.id_user = 1
AND at.id_previous = aw.id_assessmentstatus
AND asn.id_assessmentstatus = at.id_assessmentstatus
AND am.id_address = ad.id_address
AND ad.id_state = s.id_state
AND am.id_datastatus = ds.id_datastatus
AND ad.id_datastatus = ds.id_datastatus
AND aw.id_datastatus = ds.id_datastatus
AND at.id_datastatus = ds.id_datastatus
AND ast.id_datastatus = ds.id_datastatus
AND asn.id_datastatus = ds.id_datastatus
AND c.id_datastatus = ds.id_datastatus
AND s.id_datastatus = ds.id_datastatus
AND p.id_datastatus = ds.id_datastatus
AND ds.b_active <> 0

... End of query.