Return-Path: X-Original-To: apmail-manifoldcf-dev-archive@www.apache.org Delivered-To: apmail-manifoldcf-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id C300810C11 for ; Wed, 15 Oct 2014 16:26:34 +0000 (UTC) Received: (qmail 98581 invoked by uid 500); 15 Oct 2014 16:26:34 -0000 Delivered-To: apmail-manifoldcf-dev-archive@manifoldcf.apache.org Received: (qmail 98524 invoked by uid 500); 15 Oct 2014 16:26:34 -0000 Mailing-List: contact dev-help@manifoldcf.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@manifoldcf.apache.org Delivered-To: mailing list dev@manifoldcf.apache.org Received: (qmail 98512 invoked by uid 99); 15 Oct 2014 16:26:34 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 15 Oct 2014 16:26:34 +0000 Date: Wed, 15 Oct 2014 16:26:34 +0000 (UTC) From: "Karl Wright (JIRA)" To: dev@manifoldcf.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Resolved] (CONNECTORS-678) Postgresql generating unusual and slow (76 second) plans for stuffer queries MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CONNECTORS-678?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Karl Wright resolved CONNECTORS-678. ------------------------------------ Resolution: Won't Fix Fix Version/s: (was: ManifoldCF 2.0) Adjusting the number of queries between analysis requests seems to have done the job for Erlend, at least. So I am closing this ticket; will reopen if I see other cases of this behavior. > Postgresql generating unusual and slow (76 second) 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 > > 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 query was noted in the log as taking 76 seconds to execute. -- This message was sent by Atlassian JIRA (v6.3.4#6332)