[ https://issues.apache.org/jira/browse/CONNECTORS-678?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13640242#comment-13640242 ]
Erlend GarĂ¥sen commented on CONNECTORS-678: ------------------------------------------- Here is the EXPLAIN ANALYZE with the same checktime as from my logs. I have added one more below where the checktime value is the same as the start time of the job: checktime = 1366628406182 {code} QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=10560.92..10560.93 rows=1 width=155) (actual time=43.011..43.205 rows=100 loops=1) -> Sort (cost=10560.92..10560.93 rows=1 width=155) (actual time=43.008..43.072 rows=100 loops=1) Sort Key: t0.docpriority Sort Method: top-N heapsort Memory: 51kB -> Nested Loop Anti Join (cost=10536.77..10560.91 rows=1 width=155) (actual time=1.418..39.794 rows=1737 loops=1) Join Filter: (t2.jobid <> t0.jobid) -> Nested Loop Semi Join (cost=10536.77..10552.30 rows=1 width=155) (actual time=1.389..18.418 rows=1737 loops=1) -> Hash Anti Join (cost=10536.77..10550.88 rows=1 width=155) (actual time=1.373..8.495 rows=1737 loops=1) Hash Cond: (t0.id = t3.owner) -> Bitmap Heap Scan on jobqueue t0 (cost=4.61..18.39 rows=7 width=155) (actual time=1.139..4.540 rows=1737 loops=1) Recheck Cond: ((status = ANY ('{P,G}'::bpchar[])) AND (checkaction = 'R'::bpchar) AND (checktime <= 1566628406182::bigint)) -> Bitmap Index Scan on i1362584563123 (cost=0.00..4.61 rows=7 width=0) (actual time=1.058..1.058 rows=1737 loops=1) Index Cond: ((status = ANY ('{P,G}'::bpchar[])) AND (checkaction = 'R'::bpchar) AND (checktime <= 1566628406182::bigint)) -> Hash (cost=7636.98..7636.98 rows=231614 width=8) (actual time=0.090..0.090 rows=0 loops=1) Buckets: 32768 Batches: 1 Memory Usage: 0kB -> Hash Join (cost=13.15..7636.98 rows=231614 width=8) (actual time=0.089..0.089 rows=0 loops=1) Hash Cond: ((t3.eventname)::text = (t4.name)::text) -> Seq Scan on prereqevents t3 (cost=0.00..4439.14 rows=231614 width=37) (actual time=0.014..0.014 rows=1 loops=1) -> Hash (cost=11.40..11.40 rows=140 width=516) (actual time=0.002..0.002 rows=0 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 0kB -> Seq Scan on events t4 (cost=0.00..11.40 rows=140 width=516) (actual time=0.001..0.001 rows=0 loops=1) -> Index Scan using jobs_pkey on jobs t1 (cost=0.00..1.42 rows=1 width=8) (actual time=0.003..0.003 rows=1 loops=1737) Index Cond: (id = t0.jobid) Filter: ((status = ANY ('{A,a}'::bpchar[])) AND (priority = 5)) -> Index Scan using i1362584563120 on jobqueue t2 (cost=0.00..4.30 rows=1 width=49) (actual time=0.009..0.009 rows=0 loops=1737) Index Cond: ((dochash)::text = (t0.dochash)::text) Filter: (status = ANY ('{A,F,a,f,D,d}'::bpchar[])) Total runtime: 43.489 ms (28 rows) {code} checktime = 1366627062 {code} QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------ Limit (cost=10560.92..10560.93 rows=1 width=155) (actual time=32.293..32.482 rows=100 loops=1) -> Sort (cost=10560.92..10560.93 rows=1 width=155) (actual time=32.291..32.357 rows=100 loops=1) Sort Key: t0.docpriority Sort Method: top-N heapsort Memory: 51kB -> Nested Loop Anti Join (cost=10536.77..10560.91 rows=1 width=155) (actual time=0.719..29.757 rows=1737 loops=1) Join Filter: (t2.jobid <> t0.jobid) -> Nested Loop Semi Join (cost=10536.77..10552.30 rows=1 width=155) (actual time=0.703..14.690 rows=1737 loops=1) -> Hash Anti Join (cost=10536.77..10550.88 rows=1 width=155) (actual time=0.689..6.155 rows=1737 loops=1) Hash Cond: (t0.id = t3.owner) -> Bitmap Heap Scan on jobqueue t0 (cost=4.61..18.39 rows=7 width=155) (actual time=0.567..2.642 rows=1737 loops=1) Recheck Cond: ((status = ANY ('{P,G}'::bpchar[])) AND (checkaction = 'R'::bpchar) AND (checktime <= 1366627062)) -> Bitmap Index Scan on i1362584563123 (cost=0.00..4.61 rows=7 width=0) (actual time=0.509..0.509 rows=1737 loops=1) Index Cond: ((status = ANY ('{P,G}'::bpchar[])) AND (checkaction = 'R'::bpchar) AND (checktime <= 1366627062)) -> Hash (cost=7636.98..7636.98 rows=231614 width=8) (actual time=0.020..0.020 rows=0 loops=1) Buckets: 32768 Batches: 1 Memory Usage: 0kB -> Hash Join (cost=13.15..7636.98 rows=231614 width=8) (actual time=0.018..0.018 rows=0 loops=1) Hash Cond: ((t3.eventname)::text = (t4.name)::text) -> Seq Scan on prereqevents t3 (cost=0.00..4439.14 rows=231614 width=37) (actual time=0.004..0.004 rows=1 loops=1) -> Hash (cost=11.40..11.40 rows=140 width=516) (actual time=0.002..0.002 rows=0 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 0kB -> Seq Scan on events t4 (cost=0.00..11.40 rows=140 width=516) (actual time=0.001..0.001 rows=0 loops=1) -> Index Scan using jobs_pkey on jobs t1 (cost=0.00..1.42 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=1737) Index Cond: (id = t0.jobid) Filter: ((status = ANY ('{A,a}'::bpchar[])) AND (priority = 5)) -> Index Scan using i1362584563120 on jobqueue t2 (cost=0.00..4.30 rows=1 width=49) (actual time=0.006..0.006 rows=0 loops=1737) Index Cond: ((dochash)::text = (t0.dochash)::text) Filter: (status = ANY ('{A,F,a,f,D,d}'::bpchar[])) Total runtime: 32.694 ms (28 rows) {code} Regarding your second question, I will get back to this in a separate post. > Postgresql generating terrible plans for stuffer queries > -------------------------------------------------------- > > Key: CONNECTORS-678 > URL: https://issues.apache.org/jira/browse/CONNECTORS-678 > Project: ManifoldCF > Issue Type: Bug > Components: Framework core > Affects Versions: ManifoldCF 1.1.1 > Reporter: Karl Wright > Assignee: Karl Wright > Priority: Critical > Fix For: ManifoldCF 1.2 > > > Query plans like this seem to be taking place: > {code} > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: Limit > (cost=9597.49..9597.49 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: -> Sort > (cost=9597.49..9597.49 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: Sort Key: > t0.docpriority > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: -> Nested > Loop Anti Join (cost=17.68..9597.48 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: Join > Filter: (t2.jobid <> t0.jobid) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: -> > Nested Loop Semi Join (cost=17.68..9588.87 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Join Filter: (t0.jobid = t1.id) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Nested Loop Anti Join (cost=17.68..9586.81 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Join Filter: (t0.id = t3.owner) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Bitmap Heap Scan on jobqueue t0 (cost=4.53..6.54 rows=1 width=155) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Recheck Cond: (status = ANY ('{P,G}'::bpchar[])) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Filter: ((checktime <= 1366628406182::bigint) AND (checkaction = > 'R'::bpchar)) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Bitmap Index Scan on i1362584563122 (cost=0.00..4.53 rows=1 > width=0) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Index Cond: (status = ANY ('{P,G}'::bpchar[])) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Hash Join (cost=13.15..7635.56 rows=231554 width=8) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Hash Cond: ((t3.eventname)::text = (t4.name)::text) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Seq Scan on prereqevents t3 (cost=0.00..4438.54 rows=231554 > width=37) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Hash (cost=11.40..11.40 rows=140 width=516) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Seq Scan on events t4 (cost=0.00..11.40 rows=140 > width=516) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > -> Seq Scan on jobs t1 (cost=0.00..2.03 rows=2 width=8) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Filter: ((status = ANY ('{A,a}'::bpchar[])) AND (priority = 5::bigint)) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: -> > Index Scan using i1362584563120 on jobqueue t2 (cost=0.00..4.30 rows=1 > width=49) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Index Cond: ((dochash)::text = (t0.dochash)::text) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - Plan: > Filter: (status = ANY ('{A,F,a,f,D,d}'::bpchar[])) > WARN 2013-04-22 13:01:20,414 (Stuffer thread) - > {code} > Here's the query: > {code} > EXPLAIN SELECT > t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset > FROM jobqueue t0 WHERE t0.status IN ('P','G') AND t0.checkaction='R' AND > t0.checktime<=1366628406182 AND > EXISTS(SELECT 'x' FROM jobs t1 WHERE t1.status IN ('A','a') AND > t1.id=t0.jobid AND t1.priority=5) AND > NOT EXISTS(SELECT 'x' FROM jobqueue t2 WHERE t2.dochash=t0.dochash AND > t2.status IN ('A','F','a','f','D','d') AND t2.jobid!=t0.jobid) AND > NOT EXISTS(SELECT 'x' FROM prereqevents t3,events t4 WHERE t0.id=t3.owner > AND t3.eventname=t4.name) ORDER BY t0.docpriority ASC LIMIT 100; > {code} -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira