manifoldcf-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "roel goovaerts (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CONNECTORS-1592) Found long running query in manifold scheduled job
Date Tue, 09 Apr 2019 13:15:00 GMT

    [ https://issues.apache.org/jira/browse/CONNECTORS-1592?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16813384#comment-16813384
] 

roel goovaerts commented on CONNECTORS-1592:
--------------------------------------------

Hi Karl, 

We've had some time to analyze and debug in detail. First of all we ran the databasemaintenance
script when manifold was shut down; after a restart and 2 hours of crawling it started to
log long-running queries again.

While monitoring, we noticed that there are frequent locks following queries; normally these
logs are resolved quickly (as yo uwould expect). But every once in a while the locks start
stacking up until postgres is using 100% of cpu and is shown as being idle and manifold is
idle as well. After a while things pick up again and manifold starts logging long-running
queries.

SELECT_blocked_queries.txt contains a incomplete list of queries that are blocked by another
process. This list was captured at a time we were monitoring such an inactive moment.

When looking into the tables created in postgres we saw that jobID is a primary key of the
jobs table, and this is a foreign key for the intrinsiclink-table and jobqueue-table. There
are 21 entries in the job-table and 1400+ entries in the jobQueue-table.

>From our analysis we have some hypothesis:
- one 'root' query doesn't get committed, this keeps a lock on the job-, intrinsiclink- or
jobQueue-table and cascades into the bulk of locked queries. Main question here is how one
query could get stuck; can a query be waiting for something from manifold until it is committed?
- there is a locking conflict that arises from the jobID being a foreing key constraint for
both the jobQueue and intrinsiclinks. From debugging we have the impression that postgres
locks the whole intrinsiclink-table in a query which is specified to have one specific jobId.

Your input in this issue would be appreciated. 
Based on the "performance tuning" and "building ManifoldCF" resources we have verified our
properties to be in the correct database limits; The only thing we were wondering, concerning
the formula 'manifoldcf_db_pool_size * number_of_manifoldcf_processes <= maximum_postgresql_database_handles
- 2', is if manifold_db_pool_size is postgres.max_connections?

 

some additional questions:
- could using the multi process-functionality of org.apache.manifoldcf.usejettyparentclassloader
be used to improve this issue?
- I have read that disabling swap can be good for intensive db-interactions; do you have experience
with disabling swap improving manifold?
- is there a possibility that we could set-up a conference call with someone from the manifold
team?

Many thanks for your time.

> Found long running query in manifold scheduled job
> --------------------------------------------------
>
>                 Key: CONNECTORS-1592
>                 URL: https://issues.apache.org/jira/browse/CONNECTORS-1592
>             Project: ManifoldCF
>          Issue Type: Bug
>    Affects Versions: ManifoldCF 2.12
>            Reporter: Subasini Rath
>            Priority: Major
>         Attachments: LongRunningWithPlan_thread39.txt, SELECT_blocked_queries.txt, postgresql.conf,
properties.xml
>
>
> Hi Karl,
>    I am also facing the above mentioned issue. (Similar to Connector-880)
> I am using manifold2.12 binary version. I am using Solr output connector and Web repository
connection. Manifold is using all default configuration.
> When I am running the jobs manually, it runs fine. Same jobs have been scheduled to run
everyday.
> I am getting below exceptions and the job gets hanged/ going to waiting stage.
> Could you please help me in resolving the same.
> I am getting the below error -
> Scenario-1
> WARN 2019-03-08T23:58:20,338 (qtp550147359-413) - Found a long-running query (2706114
ms): [SELECT t0.id,t0.description,t0.status,t0.starttime,t0.endtime,t0.errortext FROM jobs
t0 ORDER BY description ASC]
>  WARN 2019-03-08T23:58:20,337 (Document delete stuffer thread) - Found a long-running
query (2737370 ms): [SELECT id FROM jobs WHERE status=? LIMIT 1]
>  WARN 2019-03-08T23:58:20,339 (Job reset thread) - Found a long-running query (2770133
ms): [SELECT id FROM jobs WHERE status IN (?,?)]
>  WARN 2019-03-08T23:58:20,386 (Document delete stuffer thread) - Parameter 0: 'e'
>  WARN 2019-03-08T23:58:20,337 (Set priority thread) - Found a long-running query (2732379
ms): [SELECT id,dochash,docid,jobid FROM jobqueue WHERE needpriority=? LIMIT 1000]
>  WARN 2019-03-08T23:58:20,386 (Set priority thread) - Parameter 0: 'T'
>  WARN 2019-03-08T23:58:20,386 (Job reset thread) - Parameter 0: 'I'
>  WARN 2019-03-08T23:58:20,386 (Job reset thread) - Parameter 1: 'i'
>  WARN 2019-03-08T23:58:20,372 (Seeding thread) - Parameter 2: '1552047176062'
>  WARN 2019-03-08T23:58:20,474 (Document cleanup stuffer thread) - Found a long-running
query (2737524 ms): [SELECT id FROM jobs WHERE status=? LIMIT 1]
>  WARN 2019-03-08T23:58:20,474 (Document cleanup stuffer thread) - Parameter 0: 'S'
>  WARN 2019-03-08T23:58:20,474 (Finisher thread) - Found a long-running query (2752034
ms): [SELECT id FROM jobs WHERE status IN (?,?,?) FOR UPDATE]
>  WARN 2019-03-08T23:58:20,474 (Finisher thread) - Parameter 0: 'A'
>  WARN 2019-03-08T23:58:20,475 (Finisher thread) - Parameter 1: 'W'
>  WARN 2019-03-08T23:58:20,475 (Finisher thread) - Parameter 2: 'R'
>  WARN 2019-03-08T23:58:20,475 (Delete startup thread) - Found a long-running query (2752036
ms): [SELECT id FROM jobs WHERE status=? FOR UPDATE]
>  WARN 2019-03-08T23:58:20,475 (Delete startup thread) - Parameter 0: 'E'
>  WARN 2019-03-08T23:58:20,483 (qtp550147359-4339) - Found a long-running query (2496641
ms): [SELECT t0.id,t0.description,t0.status,t0.starttime,t0.endtime,t0.errortext FROM jobs
t0 ORDER BY description ASC]
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: isDistinctSelect=[false]
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: isGrouped=[false]
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: isAggregated=[false]
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: columns=[ COLUMN: PUBLIC.JOBS.ID
not nullable
>  WARN 2019-03-08T23:58:20,492 (qtp550147359-4346) - Found a long-running query (2435908
ms): [SELECT t0.id,t0.description,t0.status,t0.starttime,t0.endtime,t0.errortext FROM jobs
t0 ORDER BY description ASC]
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: 
>  WARN 2019-03-08T23:58:20,492 (Finisher thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,499 (Finisher thread) - Plan: [range variable 1
>  WARN 2019-03-08T23:58:20,499 (Finisher thread) - Plan: join type=INNER
>  WARN 2019-03-08T23:58:20,499 (Finisher thread) - Plan: table=SYSTEM_SUBQUERY
>  WARN 2019-03-08T23:58:20,499 (Finisher thread) - Plan: cardinality=0
>  WARN 2019-03-08T23:58:20,499 (Finisher thread) - Plan: access=FULL SCAN
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: join condition = [index=SYS_IDX_13329
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: ][range variable 2
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: join type=INNER
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: table=JOBS
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: cardinality=3
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: access=INDEX PRED
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: join condition = [index=I1549955498033
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: start conditions=[
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: EQUAL arg_left=[ COLUMN: PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: ] arg_right=[ COLUMN: C1
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: end condition=[
>  WARN 2019-03-08T23:58:20,500 (Finisher thread) - Plan: EQUAL arg_left=[ COLUMN: PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ] arg_right=[ COLUMN: C1
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: other condition=[
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: EQUAL arg_left=[ COLUMN: PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ] arg_right=[ COLUMN: C1
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: PARAMETERS=[
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: @0[DYNAMIC PARAM: , TYPE = VARCHAR
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: @1[DYNAMIC PARAM: , TYPE = VARCHAR
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: @2[DYNAMIC PARAM: , TYPE = VARCHAR
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: SUBQUERIES[
>  WARN 2019-03-08T23:58:20,501 (Finisher thread) - Plan: [level=1
>  WARN 2019-03-08T23:58:20,502 (Finisher thread) - Plan: value expression]]
>  WARN 2019-03-08T23:58:20,502 (Finisher thread) - 
>  WARN 2019-03-08T23:58:20,504 (Delete startup thread) - Plan: isDistinctSelect=[false]
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: isGrouped=[false]
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: isAggregated=[false]
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: columns=[ COLUMN: PUBLIC.JOBS.ID
not nullable
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: 
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: [range variable 1
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: join type=INNER
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: table=JOBS
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: cardinality=3
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: access=INDEX PRED
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: join condition = [index=I1549955498033
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: start conditions=[
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: EQUAL arg_left=[ COLUMN:
PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,505 (Delete startup thread) - Plan: ] arg_right=[ DYNAMIC PARAM:
, TYPE = CHARACTER
>  WARN 2019-03-08T23:58:20,507 (Delete startup thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: isDistinctSelect=[false]
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: isGrouped=[false]
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: isAggregated=[false]
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: columns=[ COLUMN:
PUBLIC.JOBS.ID not nullable
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: 
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: ]
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: [range variable
1
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: join type=INNER
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: table=JOBS
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: cardinality=3
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: access=INDEX
PRED
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: join condition
= [index=I1549955498033
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: start conditions=[
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: EQUAL arg_left=[
COLUMN: PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,507 (Delete startup thread) - Plan: end condition=[
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: ] arg_right=[
DYNAMIC PARAM: , TYPE = CHARACTER
>  WARN 2019-03-08T23:58:20,507 (Document cleanup stuffer thread) - Plan: ]]
>  WARN 2019-03-08T23:58:20,507 (Delete startup thread) - Plan: EQUAL arg_left=[ COLUMN:
PUBLIC.JOBS.STATUS
>  WARN 2019-03-08T23:58:20,508 (Document cleanup stuffer thread) - Plan: end condition=[
>  WARN 2019-03-08T23:58:20,508 (Delete startup thread) - Plan: ] arg_right=[ DYNAMIC PARAM:
, TYPE = CHARACTER
>  WARN 2019-03-08T23:58:20,508 (Document cleanup stuffer thread) - Plan: EQUAL arg_left=[
COLUMN: PUBLIC.JOBS.STATUS
>  
> Scenario-2
> WEB: Illegal seed URL 'http://intranet.abcde.com/wps/wcm/connect/xxx/xxxwebsite/home



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

Mime
View raw message