You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@manifoldcf.apache.org by Karl Wright <da...@gmail.com> on 2014/11/01 13:09:13 UTC
Re: (Continuous) crawl performance
Hi Aeham,
To figure out what is going on, it would probably be sufficient to execute
the following queries and send me the results:
EXPLAIN SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
ORDER BY t0.docpriority LIMIT 20;
SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
ORDER BY t0.docpriority LIMIT 20;
These should both read directly from the index in question; we can see
immediately what kinds of documents it is having to skip to get to the
active ones.
Thanks!
Karl
On Fri, Oct 31, 2014 at 2:42 PM, Karl Wright <da...@gmail.com> wrote:
> Hi Aeham,
>
> I've looked at this at some level of detail now, and have some conclusions.
>
> (1) The first query you provided is in fact using the proper index for
> ordering; it's just not obvious from the plan. The way you can tell is if
> there is an explicit sort/limit. The primary jobqueue index scan is
> happening within an anti-join and a semi-join; you can tell this by cutting
> out all the EXISTS clauses and getting a reduced plan that way, and
> comparing. For instance, here's an explain of the simple query:
>
> >>>>>>
> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 ORDER BY t0.docpriority LIMIT 240;
> QUERY PLAN
>
>
> -------------------------------------------------------------------------------------------------
> Limit (cost=0.29..38.20 rows=240 width=161)
> -> Index Scan using i1413214448001 on jobqueue t0 (cost=0.29..2312.39
> rows=14634 width=161)
> (2 rows)
> <<<<<<
>
> Applying filtering criteria:
>
> >>>>>>
> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
> t0.checkaction='R' AND t0.checktime<=2414771559577 ORDER BY t0.docpriority
> LIMIT 240;
> QUERY PLAN
>
>
> ------------------------------------------------------------------------------------------------
> Limit (cost=0.29..68.98 rows=240 width=161)
> -> Index Scan using i1413214448001 on jobqueue t0 (cost=0.29..2389.31
> rows=8347 width=161)
> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
> 2414771559577::bigint))
> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
> (4 rows)
> <<<<<<
>
> Now, this is a bit strange, because there is a filter on the status, so
> the index isn't helping there, and yet the index includes the status:
> "i1413214448001" btree (docpriority, status, checkaction, checktime)
> But maybe this is a statistical optimization? I don't know.
>
> Anyhow, as soon as a NOT EXISTS clause is added, you see an anti-join:
>
> >>>>>>
> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
> t0.checkaction='R' AND t0.checktime<=2414771559577 AND NOT EXISTS(SELECT
> 'x' FROM prereqevents t3,events t4 WHERE t0.id=t3.owner AND t3.eventname=
> t4.name) ORDER BY t0.docpriority LIMIT 240;
> QUERY PLAN
>
>
> ----------------------------------------------------------------------------------------------------------
> Limit (cost=0.57..231.40 rows=240 width=161)
> -> Nested Loop Anti Join (cost=0.57..7957.24 rows=8273 width=161)
> -> Index Scan using i1413214448001 on jobqueue t0
> (cost=0.29..2389.31 rows=8347 width=161)
> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
> 2414771559577::bigint))
> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
> -> Nested Loop (cost=0.29..0.66 rows=1 width=8)
> -> Index Scan using i1413214448007 on prereqevents t3
> (cost=0.14..0.17 rows=1 width=524)
> Index Cond: (t0.id = owner)
> -> Index Only Scan using events_pkey on events t4
> (cost=0.14..0.48 rows=1 width=516)
> Index Cond: (name = (t3.eventname)::text)
> (10 rows)
> <<<<<<
>
> The index scan is still there and is apparently providing the sorting,
> which is good still. It's just inside an anti-join.
>
> So you can take this further and add the two remaining EXISTS/NOT EXISTS
> clauses, and then your first plan makes sense. But your proposed *second*
> plan is clearly *not* using the docpriority index for sorting, since it
> sorts by itself later on:
>
> >>>>>>
> Limit (cost=122440.72..122441.42 rows=280 width=177) (actual
> time=1010.722..1010.722 rows=0 loops=1)
> -> Sort (cost=122440.72..122451.13 rows=4164 width=177) (actual
> time=1010.719..1010.719 rows=0 loops=1)
> Sort Key: t0.docpriority
> Sort Method: quicksort Memory: 25kB
> <<<<<<
>
> So what we need to understand now is why the first query is slow. It's
> reading from the correct index, but is nevertheless taking a long time,
> possibly because there are a lot of records with status 'P' or 'G' that
> belong to jobs that are not in state 'a' or 'A' that it has to go through
> before it assembles 240 results. Can you confirm this picture?
>
> Thanks,
> Karl
>
>
> On Fri, Oct 31, 2014 at 1:09 PM, Aeham Abushwashi <
> aeham.abushwashi@exonar.com> wrote:
>
>> That's great news, thanks Karl! On my part, I've been digging deeper into
>> the execution plans of the two queries and I've made a similar observation
>> of the ORDER BY skewing the original query's plan significantly. However,
>> I
>> have yet to figure out why the same ORDER BY clause doesn't have a similar
>> impact on the modified query that uses JOIN. I'll look into this a bit
>> more
>> over the weekend.
>>
>> Best regards,
>> Aeham
>>
>
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Thanks Karl.
I've just started other nodes and, you're right, they don't go down the
prioritization route, which is a relief!
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Hi Aeham,
The query plans look reasonable. The fact that all the document priorities
need to be written accounts for the high postgresql I/O. About the only
thing I can think to do is put the writes in a transaction, which may help
performance somewhat. I'll experiment with that over the weekend.
bq. I was also wondering, and this is just me speculating at this point,
whether the exact same set of docs would be re-processed every time another
crawler agent node is started.
That should not happen. There are two different kinds of restarts -- one
where NO agents nodes are registered, and a second where there are already
agents nodes registered. Reprioritization should not take place when the
secondary nodes start up.
However, reprioritization *does* take place whenever you start, stop,
pause, or resume a job. I don't have a good solution for that issue yet.
Karl
On Fri, Nov 7, 2014 at 11:50 AM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> With all crawler agents stopped, the current state of the system is as
> follows (using a variant of the reprioritization query):
>
> SELECT jobid, status, COUNT(*) FROM jobqueue t0 WHERE (status='H' OR
> status='P' OR status='G') AND priorityset<1415374856000 AND checkaction='R'
> AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR t1.status='b'
> OR t1.status='A' OR t1.status='a' OR t1.status='R' OR t1.status='r' OR
> t1.status='O' OR t1.status='o' OR t1.status='U' OR t1.status='u') AND
> t1.id=t0.jobid)
> GROUP BY jobid, status ORDER BY jobid;
> jobid | status | count
> ---------------+--------+---------
> 1413897188357 | P | 47281
> 1413897188357 | G | 2420206
> 1414075755977 | G | 43399
> 1415018782273 | G | 9
> 1415020466369 | G | 24
>
> Note that all 4 crawls are in continuous mode and status Active.
>
> When the first agent node is started, it iterates through the above docs
> and updates their priority. Starting with the following query:
>
> SELECT id,dochash,docid,jobid FROM jobqueue t0 WHERE (status='H' OR
> status='P' OR status='G') AND priorityset< [some timestamp] AND
> checkaction='R' AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR
> t1.status='b' OR t1.status='A' OR t1.status='a' OR t1.status='R' OR
> t1.status='r' OR t1.status='O' OR t1.status='o' OR t1.status='U' OR
> t1.status='u') AND t1.id=t0.jobid) LIMIT 10000
>
> which takes ~4 seconds for each batch. The AgentsThread then proceeds to
> update their priority one by one. This, the VisualVM profiler suggests,
> adds another ~9 seconds to each iteration and hits postgresql (IO) really
> hard. With ~2.5M docs to go through, the numbers gradually add up.
>
> I was also wondering, and this is just me speculating at this point,
> whether the exact same set of docs would be re-processed every time another
> crawler agent node is started. I say that because, the AgentsThread sets
> priorityset to current time which presumably would lead any subsequent
> starting node to hit the (moe or less) same set of documents as the
> previous one did.
>
>
> For reference, the execution plan of the SELECT QUERY is as follows:
>
> EXPLAIN ANALYZE SELECT id,dochash,docid,jobid FROM jobqueue t0 WHERE
> (status='H' OR status='P' OR status='G') AND priorityset<1415374856000 AND
> checkaction='R' AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR
> t1.status='b' OR t1.status='A' OR t1.status='a' OR t1.status='R' OR
> t1.status='r' OR t1.status='O' OR t1.status='o' OR t1.status='U' OR
> t1.status='u') AND t1.id=t0.jobid) LIMIT 10000;
>
> QUERY PLAN
>
>
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Limit (cost=19486.41..57634.31 rows=10000 width=143) (actual
> time=1646.862..4869.705 rows=10000 loops=1)
> -> Hash Join (cost=19486.41..1456197.07 rows=376616 width=143) (actual
> time=1646.859..4864.841 rows=10000 loops=1)
> Hash Cond: (t0.jobid = t1.id)
> -> Bitmap Heap Scan on jobqueue t0 (cost=19401.16..1451681.36
> rows=690462 width=143) (actual time=1646.308..4096.874 rows=2768867
> loops=1)
> Recheck Cond: (((status = 'H'::bpchar) AND (priorityset <
> 1415374856000::bigint)) OR ((status = 'P'::bpchar) AND (checkaction =
> 'R'::bpchar)) OR ((status = 'G'::bpchar) AND (checkaction = 'R'::bpchar)))
> Filter: ((priorityset < 1415374856000::bigint) AND
> (checkaction = 'R'::bpchar))
> -> BitmapOr (cost=19401.16..19401.16 rows=710369 width=0)
> (actual time=1456.979..1456.979 rows=0 loops=1)
> -> Bitmap Index Scan on i1392985450173
> (cost=0.00..10.31 rows=1 width=0) (actual time=0.029..0.029 rows=0 loops=1)
> Index Cond: ((status = 'H'::bpchar) AND
> (priorityset < 1415374856000::bigint))
> -> Bitmap Index Scan on i1392985450174
> (cost=0.00..5524.25 rows=207759 width=0) (actual time=349.283..349.283
> rows=1552934 loops=1)
> Index Cond: ((status = 'P'::bpchar) AND
> (checkaction = 'R'::bpchar))
> -> Bitmap Index Scan on i1392985450174
> (cost=0.00..13348.76 rows=502610 width=0) (actual time=1107.663..1107.663
> rows=4266856 loops=1)
> Index Cond: ((status = 'G'::bpchar) AND
> (checkaction = 'R'::bpchar))
> -> Hash (cost=85.10..85.10 rows=12 width=8) (actual
> time=0.074..0.074 rows=4 loops=1)
> Buckets: 1024 Batches: 1 Memory Usage: 2kB
> -> Bitmap Heap Scan on jobs t1 (cost=46.64..85.10 rows=12
> width=8) (actual time=0.058..0.068 rows=4 loops=1)
> Recheck Cond: ((status = 'B'::bpchar) OR (status =
> 'b'::bpchar) OR (status = 'A'::bpchar) OR (status = 'a'::bpchar) OR (status
> = 'R'::bpchar) OR (status = 'r'::bpchar) OR (status = 'O'::bpchar) OR
> (status = 'o'::bpch
> ar) OR (status = 'U'::bpchar) OR (status = 'u'::bpchar))
> -> BitmapOr (cost=46.64..46.64 rows=13 width=0)
> (actual time=0.049..0.049 rows=0 loops=1)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.019..0.019 rows=0 loops=1)
> Index Cond: (status = 'B'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.003..0.003 rows=0 loops=1)
> Index Cond: (status = 'b'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..8.28 rows=4 width=0) (actual time=0.008..0.008 rows=4 loops=1)
> Index Cond: (status = 'A'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
> Index Cond: (status = 'a'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.004..0.004 rows=0 loops=1)
> Index Cond: (status = 'R'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
> Index Cond: (status = 'r'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
> Index Cond: (status = 'O'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
> Index Cond: (status = 'o'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
> Index Cond: (status = 'U'::bpchar)
> -> Bitmap Index Scan on i1392985450183
> (cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
> Index Cond: (status = 'u'::bpchar)
> Total runtime: 4872.335 ms
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
With all crawler agents stopped, the current state of the system is as
follows (using a variant of the reprioritization query):
SELECT jobid, status, COUNT(*) FROM jobqueue t0 WHERE (status='H' OR
status='P' OR status='G') AND priorityset<1415374856000 AND checkaction='R'
AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR t1.status='b'
OR t1.status='A' OR t1.status='a' OR t1.status='R' OR t1.status='r' OR
t1.status='O' OR t1.status='o' OR t1.status='U' OR t1.status='u') AND
t1.id=t0.jobid)
GROUP BY jobid, status ORDER BY jobid;
jobid | status | count
---------------+--------+---------
1413897188357 | P | 47281
1413897188357 | G | 2420206
1414075755977 | G | 43399
1415018782273 | G | 9
1415020466369 | G | 24
Note that all 4 crawls are in continuous mode and status Active.
When the first agent node is started, it iterates through the above docs
and updates their priority. Starting with the following query:
SELECT id,dochash,docid,jobid FROM jobqueue t0 WHERE (status='H' OR
status='P' OR status='G') AND priorityset< [some timestamp] AND
checkaction='R' AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR
t1.status='b' OR t1.status='A' OR t1.status='a' OR t1.status='R' OR
t1.status='r' OR t1.status='O' OR t1.status='o' OR t1.status='U' OR
t1.status='u') AND t1.id=t0.jobid) LIMIT 10000
which takes ~4 seconds for each batch. The AgentsThread then proceeds to
update their priority one by one. This, the VisualVM profiler suggests,
adds another ~9 seconds to each iteration and hits postgresql (IO) really
hard. With ~2.5M docs to go through, the numbers gradually add up.
I was also wondering, and this is just me speculating at this point,
whether the exact same set of docs would be re-processed every time another
crawler agent node is started. I say that because, the AgentsThread sets
priorityset to current time which presumably would lead any subsequent
starting node to hit the (moe or less) same set of documents as the
previous one did.
For reference, the execution plan of the SELECT QUERY is as follows:
EXPLAIN ANALYZE SELECT id,dochash,docid,jobid FROM jobqueue t0 WHERE
(status='H' OR status='P' OR status='G') AND priorityset<1415374856000 AND
checkaction='R' AND EXISTS(SELECT 'x' FROM jobs t1 WHERE (t1.status='B' OR
t1.status='b' OR t1.status='A' OR t1.status='a' OR t1.status='R' OR
t1.status='r' OR t1.status='O' OR t1.status='o' OR t1.status='U' OR
t1.status='u') AND t1.id=t0.jobid) LIMIT 10000;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=19486.41..57634.31 rows=10000 width=143) (actual
time=1646.862..4869.705 rows=10000 loops=1)
-> Hash Join (cost=19486.41..1456197.07 rows=376616 width=143) (actual
time=1646.859..4864.841 rows=10000 loops=1)
Hash Cond: (t0.jobid = t1.id)
-> Bitmap Heap Scan on jobqueue t0 (cost=19401.16..1451681.36
rows=690462 width=143) (actual time=1646.308..4096.874 rows=2768867 loops=1)
Recheck Cond: (((status = 'H'::bpchar) AND (priorityset <
1415374856000::bigint)) OR ((status = 'P'::bpchar) AND (checkaction =
'R'::bpchar)) OR ((status = 'G'::bpchar) AND (checkaction = 'R'::bpchar)))
Filter: ((priorityset < 1415374856000::bigint) AND
(checkaction = 'R'::bpchar))
-> BitmapOr (cost=19401.16..19401.16 rows=710369 width=0)
(actual time=1456.979..1456.979 rows=0 loops=1)
-> Bitmap Index Scan on i1392985450173
(cost=0.00..10.31 rows=1 width=0) (actual time=0.029..0.029 rows=0 loops=1)
Index Cond: ((status = 'H'::bpchar) AND
(priorityset < 1415374856000::bigint))
-> Bitmap Index Scan on i1392985450174
(cost=0.00..5524.25 rows=207759 width=0) (actual time=349.283..349.283
rows=1552934 loops=1)
Index Cond: ((status = 'P'::bpchar) AND
(checkaction = 'R'::bpchar))
-> Bitmap Index Scan on i1392985450174
(cost=0.00..13348.76 rows=502610 width=0) (actual time=1107.663..1107.663
rows=4266856 loops=1)
Index Cond: ((status = 'G'::bpchar) AND
(checkaction = 'R'::bpchar))
-> Hash (cost=85.10..85.10 rows=12 width=8) (actual
time=0.074..0.074 rows=4 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
-> Bitmap Heap Scan on jobs t1 (cost=46.64..85.10 rows=12
width=8) (actual time=0.058..0.068 rows=4 loops=1)
Recheck Cond: ((status = 'B'::bpchar) OR (status =
'b'::bpchar) OR (status = 'A'::bpchar) OR (status = 'a'::bpchar) OR (status
= 'R'::bpchar) OR (status = 'r'::bpchar) OR (status = 'O'::bpchar) OR
(status = 'o'::bpch
ar) OR (status = 'U'::bpchar) OR (status = 'u'::bpchar))
-> BitmapOr (cost=46.64..46.64 rows=13 width=0)
(actual time=0.049..0.049 rows=0 loops=1)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.019..0.019 rows=0 loops=1)
Index Cond: (status = 'B'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.003..0.003 rows=0 loops=1)
Index Cond: (status = 'b'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..8.28 rows=4 width=0) (actual time=0.008..0.008 rows=4 loops=1)
Index Cond: (status = 'A'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (status = 'a'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.004..0.004 rows=0 loops=1)
Index Cond: (status = 'R'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (status = 'r'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
Index Cond: (status = 'O'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
Index Cond: (status = 'o'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (status = 'U'::bpchar)
-> Bitmap Index Scan on i1392985450183
(cost=0.00..4.26 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Index Cond: (status = 'u'::bpchar)
Total runtime: 4872.335 ms
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Please continue in this thread.
Karl
On Fri, Nov 7, 2014 at 11:01 AM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> Hi Karl,
>
> Thank you very much for getting the patch out so quickly and apologies for
> not getting back to you sooner - I was only able to test the patch today.
>
> The good news is that the ZK interaction has almost completely disappeared
> from the profiler radar.
>
> I've now progressed further through the test and uncovered the next
> performance issue - still in the area of reprioritization. Let me know if
> you want me to provide details on this thread, open up a new one or raise a
> JIRA ticket directly.
>
> Many thanks,
> Aeham
>
>
>
>
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Hi Karl,
Thank you very much for getting the patch out so quickly and apologies for
not getting back to you sooner - I was only able to test the patch today.
The good news is that the ZK interaction has almost completely disappeared
from the profiler radar.
I've now progressed further through the test and uncovered the next
performance issue - still in the area of reprioritization. Let me know if
you want me to provide details on this thread, open up a new one or raise a
JIRA ticket directly.
Many thanks,
Aeham
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
I've created a ticket (CONNECTORS-1094) and attached a patch, which should
deal with this problem. Please let me know if it helps.
Karl
On Wed, Nov 5, 2014 at 12:01 PM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> That's fine - thank you very much for all your help so far!
>
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
That's fine - thank you very much for all your help so far!
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
I will look into this when I have a chance.
Karl
On Wed, Nov 5, 2014 at 11:48 AM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> Hi Karl,
>
> With the latest revisions, documents for all jobs (legacy and new) do get
> picked up and processed, which is great! This was verified on a small
> 1-node test system.
> I have since applied the fix to a much larger environment (29M docs across
> 4 MCF agents using a 3-node Zookeeper cluster) which has a bunch of
> mid-sized (100,000s docs) jobs in a Running state. The update of the
> priorityset field for ~36M jobqueue records took just over an hour. More
> problematically for me is the rate of reprioritization on startup which was
> very slow - nearly 2 hours to update ~600,000 records.
>
> A couple of SQL queries
> (JobManager#getNextNotYetProcessedRepriotizationDocuments and
> ManifoldCF#writeDocumentPriorities) come up frequently, but a VisualVM
> profile of the MCF agent shows the majority of the Agents thread's time is
> spent talking to ZK, for locking + reading some config data very frequently
> - see the snapshots below.
>
> Is it possible to avoid the per-document locking pattern seen in this case?
>
> Cheers,
> Aeham
>
> ++++++++++++++++++++++
>
> 2014-11-05 15:39:42
>
> "Agents thread" - Thread t@21
> java.lang.Thread.State: WAITING
> at java.lang.Object.wait(Native Method)
> - waiting on <487ef1bb> (a org.apache.zookeeper.ClientCnxn$Packet)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1149)
> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1180)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.readData(ZooKeeperConnection.java:819)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.getSharedConfiguration(ZooKeeperLockManager.java:670)
> at
>
> org.apache.manifoldcf.core.interfaces.LockManagerFactory.getBooleanProperty(LockManagerFactory.java:110)
> at
>
> org.apache.manifoldcf.crawler.connectors.sharedrive.SharedDriveConnector.setThreadContext(SharedDriveConnector.java:157)
> at
>
> org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool.getConnector(ConnectorPool.java:489)
> - locked <3f2843d4> (a
> org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool)
> at
>
> org.apache.manifoldcf.core.connectorpool.ConnectorPool.grab(ConnectorPool.java:255)
> at
>
> org.apache.manifoldcf.crawler.repositoryconnectorpool.RepositoryConnectorPool.grab(RepositoryConnectorPool.java:86)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1007)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
> at
>
> org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
> - locked <6c7d33b0> (a java.util.HashMap)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
>
> Locked ownable synchronizers:
> - None
>
> ++++++++++++++++++++++
>
> 2014-11-05 15:39:52
>
> "Agents thread" - Thread t@21
> java.lang.Thread.State: WAITING
> at java.lang.Object.wait(Native Method)
> - waiting on <52698c72> (a org.apache.zookeeper.ClientCnxn$Packet)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
> at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:781)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.createSequentialChild(ZooKeeperConnection.java:1116)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.obtainReadLock(ZooKeeperConnection.java:691)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.obtainGlobalReadLock(ZooKeeperLockObject.java:193)
> at
>
> org.apache.manifoldcf.core.lockmanager.LockObject.enterReadLock(LockObject.java:310)
> - locked <151db932> (a
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
> at
>
> org.apache.manifoldcf.core.lockmanager.LockGate.enterReadLock(LockGate.java:261)
> at
>
> org.apache.manifoldcf.core.lockmanager.BaseLockManager.enterRead(BaseLockManager.java:1283)
> at
>
> org.apache.manifoldcf.core.lockmanager.BaseLockManager.enterReadLock(BaseLockManager.java:790)
> at
>
> org.apache.manifoldcf.crawler.reprioritizationtracker.ReprioritizationTracker.getMinimumDepth(ReprioritizationTracker.java:251)
> at
>
> org.apache.manifoldcf.crawler.system.PriorityCalculator.<init>(PriorityCalculator.java:89)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1021)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
> at
>
> org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
> - locked <6c7d33b0> (a java.util.HashMap)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
>
> Locked ownable synchronizers:
> - None
>
> ++++++++++++++++++++++
>
> 2014-11-05 15:39:59
>
> "Agents thread" - Thread t@21
> java.lang.Thread.State: WAITING
> at java.lang.Object.wait(Native Method)
> - waiting on <79c64d6d> (a org.apache.zookeeper.ClientCnxn$Packet)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:871)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.releaseLock(ZooKeeperConnection.java:796)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.clearLock(ZooKeeperLockObject.java:218)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.clearGlobalReadLockNoWait(ZooKeeperLockObject.java:212)
> at
>
> org.apache.manifoldcf.core.lockmanager.LockObject.clearGlobalReadLock(LockObject.java:395)
> at
>
> org.apache.manifoldcf.core.lockmanager.LockObject.leaveReadLock(LockObject.java:376)
> - locked <126e1776> (a
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
> at
>
> org.apache.manifoldcf.core.lockmanager.LockGate.leaveReadLock(LockGate.java:289)
> - locked <126e1776> (a
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
> at
>
> org.apache.manifoldcf.core.lockmanager.BaseLockManager.leaveRead(BaseLockManager.java:1369)
> at
>
> org.apache.manifoldcf.core.lockmanager.BaseLockManager.leaveReadLock(BaseLockManager.java:804)
> at
>
> org.apache.manifoldcf.crawler.reprioritizationtracker.ReprioritizationTracker.getMinimumDepth(ReprioritizationTracker.java:258)
> at
>
> org.apache.manifoldcf.crawler.system.PriorityCalculator.<init>(PriorityCalculator.java:89)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1021)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
> at
>
> org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
> - locked <6c7d33b0> (a java.util.HashMap)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
>
> Locked ownable synchronizers:
> - None
>
> ++++++++++++++++++++++
>
> 2014-11-05 15:40:11
>
> "Agents thread" - Thread t@21
> java.lang.Thread.State: WAITING
> at java.lang.Object.wait(Native Method)
> - waiting on <354dbdf> (a org.apache.zookeeper.ClientCnxn$Packet)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1149)
> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1180)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.readData(ZooKeeperConnection.java:819)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.getSharedConfiguration(ZooKeeperLockManager.java:670)
> at
>
> org.apache.manifoldcf.core.interfaces.LockManagerFactory.getBooleanProperty(LockManagerFactory.java:110)
> at
>
> org.apache.manifoldcf.crawler.connectors.sharedrive.SharedDriveConnector.setThreadContext(SharedDriveConnector.java:157)
> at
>
> org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool.getConnector(ConnectorPool.java:489)
> - locked <6f2f3168> (a
> org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool)
> at
>
> org.apache.manifoldcf.core.connectorpool.ConnectorPool.grab(ConnectorPool.java:255)
> at
>
> org.apache.manifoldcf.crawler.repositoryconnectorpool.RepositoryConnectorPool.grab(RepositoryConnectorPool.java:86)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1007)
> at
>
> org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
> at
>
> org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
> at
>
> org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
> - locked <6c7d33b0> (a java.util.HashMap)
> at
>
> org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
>
> Locked ownable synchronizers:
> - None
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Hi Karl,
With the latest revisions, documents for all jobs (legacy and new) do get
picked up and processed, which is great! This was verified on a small
1-node test system.
I have since applied the fix to a much larger environment (29M docs across
4 MCF agents using a 3-node Zookeeper cluster) which has a bunch of
mid-sized (100,000s docs) jobs in a Running state. The update of the
priorityset field for ~36M jobqueue records took just over an hour. More
problematically for me is the rate of reprioritization on startup which was
very slow - nearly 2 hours to update ~600,000 records.
A couple of SQL queries
(JobManager#getNextNotYetProcessedRepriotizationDocuments and
ManifoldCF#writeDocumentPriorities) come up frequently, but a VisualVM
profile of the MCF agent shows the majority of the Agents thread's time is
spent talking to ZK, for locking + reading some config data very frequently
- see the snapshots below.
Is it possible to avoid the per-document locking pattern seen in this case?
Cheers,
Aeham
++++++++++++++++++++++
2014-11-05 15:39:42
"Agents thread" - Thread t@21
java.lang.Thread.State: WAITING
at java.lang.Object.wait(Native Method)
- waiting on <487ef1bb> (a org.apache.zookeeper.ClientCnxn$Packet)
at java.lang.Object.wait(Object.java:503)
at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1149)
at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1180)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.readData(ZooKeeperConnection.java:819)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.getSharedConfiguration(ZooKeeperLockManager.java:670)
at
org.apache.manifoldcf.core.interfaces.LockManagerFactory.getBooleanProperty(LockManagerFactory.java:110)
at
org.apache.manifoldcf.crawler.connectors.sharedrive.SharedDriveConnector.setThreadContext(SharedDriveConnector.java:157)
at
org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool.getConnector(ConnectorPool.java:489)
- locked <3f2843d4> (a
org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool)
at
org.apache.manifoldcf.core.connectorpool.ConnectorPool.grab(ConnectorPool.java:255)
at
org.apache.manifoldcf.crawler.repositoryconnectorpool.RepositoryConnectorPool.grab(RepositoryConnectorPool.java:86)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1007)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
at
org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
at
org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
- locked <6c7d33b0> (a java.util.HashMap)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
Locked ownable synchronizers:
- None
++++++++++++++++++++++
2014-11-05 15:39:52
"Agents thread" - Thread t@21
java.lang.Thread.State: WAITING
at java.lang.Object.wait(Native Method)
- waiting on <52698c72> (a org.apache.zookeeper.ClientCnxn$Packet)
at java.lang.Object.wait(Object.java:503)
at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:781)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.createSequentialChild(ZooKeeperConnection.java:1116)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.obtainReadLock(ZooKeeperConnection.java:691)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.obtainGlobalReadLock(ZooKeeperLockObject.java:193)
at
org.apache.manifoldcf.core.lockmanager.LockObject.enterReadLock(LockObject.java:310)
- locked <151db932> (a
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
at
org.apache.manifoldcf.core.lockmanager.LockGate.enterReadLock(LockGate.java:261)
at
org.apache.manifoldcf.core.lockmanager.BaseLockManager.enterRead(BaseLockManager.java:1283)
at
org.apache.manifoldcf.core.lockmanager.BaseLockManager.enterReadLock(BaseLockManager.java:790)
at
org.apache.manifoldcf.crawler.reprioritizationtracker.ReprioritizationTracker.getMinimumDepth(ReprioritizationTracker.java:251)
at
org.apache.manifoldcf.crawler.system.PriorityCalculator.<init>(PriorityCalculator.java:89)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1021)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
at
org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
at
org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
- locked <6c7d33b0> (a java.util.HashMap)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
Locked ownable synchronizers:
- None
++++++++++++++++++++++
2014-11-05 15:39:59
"Agents thread" - Thread t@21
java.lang.Thread.State: WAITING
at java.lang.Object.wait(Native Method)
- waiting on <79c64d6d> (a org.apache.zookeeper.ClientCnxn$Packet)
at java.lang.Object.wait(Object.java:503)
at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:871)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.releaseLock(ZooKeeperConnection.java:796)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.clearLock(ZooKeeperLockObject.java:218)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject.clearGlobalReadLockNoWait(ZooKeeperLockObject.java:212)
at
org.apache.manifoldcf.core.lockmanager.LockObject.clearGlobalReadLock(LockObject.java:395)
at
org.apache.manifoldcf.core.lockmanager.LockObject.leaveReadLock(LockObject.java:376)
- locked <126e1776> (a
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
at
org.apache.manifoldcf.core.lockmanager.LockGate.leaveReadLock(LockGate.java:289)
- locked <126e1776> (a
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockObject)
at
org.apache.manifoldcf.core.lockmanager.BaseLockManager.leaveRead(BaseLockManager.java:1369)
at
org.apache.manifoldcf.core.lockmanager.BaseLockManager.leaveReadLock(BaseLockManager.java:804)
at
org.apache.manifoldcf.crawler.reprioritizationtracker.ReprioritizationTracker.getMinimumDepth(ReprioritizationTracker.java:258)
at
org.apache.manifoldcf.crawler.system.PriorityCalculator.<init>(PriorityCalculator.java:89)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1021)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
at
org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
at
org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
- locked <6c7d33b0> (a java.util.HashMap)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
Locked ownable synchronizers:
- None
++++++++++++++++++++++
2014-11-05 15:40:11
"Agents thread" - Thread t@21
java.lang.Thread.State: WAITING
at java.lang.Object.wait(Native Method)
- waiting on <354dbdf> (a org.apache.zookeeper.ClientCnxn$Packet)
at java.lang.Object.wait(Object.java:503)
at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1149)
at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1180)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperConnection.readData(ZooKeeperConnection.java:819)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.getSharedConfiguration(ZooKeeperLockManager.java:670)
at
org.apache.manifoldcf.core.interfaces.LockManagerFactory.getBooleanProperty(LockManagerFactory.java:110)
at
org.apache.manifoldcf.crawler.connectors.sharedrive.SharedDriveConnector.setThreadContext(SharedDriveConnector.java:157)
at
org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool.getConnector(ConnectorPool.java:489)
- locked <6f2f3168> (a
org.apache.manifoldcf.core.connectorpool.ConnectorPool$Pool)
at
org.apache.manifoldcf.core.connectorpool.ConnectorPool.grab(ConnectorPool.java:255)
at
org.apache.manifoldcf.crawler.repositoryconnectorpool.RepositoryConnectorPool.grab(RepositoryConnectorPool.java:86)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.writeDocumentPriorities(ManifoldCF.java:1007)
at
org.apache.manifoldcf.crawler.system.ManifoldCF.resetAllDocumentPriorities(ManifoldCF.java:960)
at
org.apache.manifoldcf.crawler.system.CrawlerAgent.cleanUpAllAgentData(CrawlerAgent.java:155)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$CleanupAgent.cleanUpAllServices(AgentsDaemon.java:356)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:203)
at
org.apache.manifoldcf.core.lockmanager.ZooKeeperLockManager.registerServiceBeginServiceActivity(ZooKeeperLockManager.java:129)
at
org.apache.manifoldcf.agents.system.AgentsDaemon.checkAgents(AgentsDaemon.java:270)
- locked <6c7d33b0> (a java.util.HashMap)
at
org.apache.manifoldcf.agents.system.AgentsDaemon$AgentsThread.run(AgentsDaemon.java:208)
Locked ownable synchronizers:
- None
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Hi Aehem,
I decided that it is safer to always set the prioritySet field to 0 when
the docPriority is nullDocumentPriority. I've committed another revision
for this, and described it in the CONNECTORS-1091 ticket. I've also
included upgrade code that updates the prioritySet field automatically upon
initialization.
Karl
On Tue, Nov 4, 2014 at 1:23 PM, Karl Wright <da...@gmail.com> wrote:
> Hi Aeham,
>
> I would be careful to set the "priorityset" field value to 0 only for
> documents that have state "G" and whose job is active.
>
> bq. I believe the priority should be set by
> ManifoldCF#
> resetAllDocumentPriorities but it's not, because
> JobManager#getNextNotYetProcessedReprioritizationDocuments returns no rows
> to update
>
> Where is resetAllDocumentPriorities being called from that you are seeing
> this? When a job is started, documents that are put into the "G" state all
> have prioritySet times set to 0, so that the subsequent
> resetAllDocumentPriorities() call will assign priorities to them. If there
> are other conditions where resetAllDocumentPriorities() is getting called
> after documents are put into the "G" state, where this ISN'T happening, I'd
> like to know about them.
>
> Thanks,
> Karl
>
>
> On Tue, Nov 4, 2014 at 1:15 PM, Aeham Abushwashi <
> aeham.abushwashi@exonar.com> wrote:
>
>> Hi Karl,
>>
>> After applying the 1.7.2 revisions for CONNECTORS-1090, -1091, -1092 and
>> -1093 to my 1.6.1 branch, if I create a new crawl, then its documents get
>> picked up by the next scan; however, that doesn't happen for an existing
>> crawl. The docpriority for documents in the existing craw is still at
>> 1000000001.
>>
>> I believe the priority should be set by
>> ManifoldCF#resetAllDocumentPriorities but it's not, because
>> JobManager#getNextNotYetProcessedReprioritizationDocuments returns no rows
>> to update, which I think is due to the legacy job's docs having a
>> priorityset of NULL. Replacing the current priorityset condition in
>> JobManager#getNextNotYetProcessedReprioritizationDocuments with
>> (priorityset IS NULL OR priorityset<?) addresses this specific issue.
>> Is this a valid fix or do you see it introducing undesirable behaviour or
>> masking an issue elsewhere?
>>
>> Cheers,
>> Aeham
>>
>>
>
>
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Hi Aeham,
I would be careful to set the "priorityset" field value to 0 only for
documents that have state "G" and whose job is active.
bq. I believe the priority should be set by
ManifoldCF#
resetAllDocumentPriorities but it's not, because
JobManager#getNextNotYetProcessedReprioritizationDocuments returns no rows
to update
Where is resetAllDocumentPriorities being called from that you are seeing
this? When a job is started, documents that are put into the "G" state all
have prioritySet times set to 0, so that the subsequent
resetAllDocumentPriorities() call will assign priorities to them. If there
are other conditions where resetAllDocumentPriorities() is getting called
after documents are put into the "G" state, where this ISN'T happening, I'd
like to know about them.
Thanks,
Karl
On Tue, Nov 4, 2014 at 1:15 PM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> Hi Karl,
>
> After applying the 1.7.2 revisions for CONNECTORS-1090, -1091, -1092 and
> -1093 to my 1.6.1 branch, if I create a new crawl, then its documents get
> picked up by the next scan; however, that doesn't happen for an existing
> crawl. The docpriority for documents in the existing craw is still at
> 1000000001.
>
> I believe the priority should be set by
> ManifoldCF#resetAllDocumentPriorities but it's not, because
> JobManager#getNextNotYetProcessedReprioritizationDocuments returns no rows
> to update, which I think is due to the legacy job's docs having a
> priorityset of NULL. Replacing the current priorityset condition in
> JobManager#getNextNotYetProcessedReprioritizationDocuments with
> (priorityset IS NULL OR priorityset<?) addresses this specific issue.
> Is this a valid fix or do you see it introducing undesirable behaviour or
> masking an issue elsewhere?
>
> Cheers,
> Aeham
>
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Hi Karl,
After applying the 1.7.2 revisions for CONNECTORS-1090, -1091, -1092 and
-1093 to my 1.6.1 branch, if I create a new crawl, then its documents get
picked up by the next scan; however, that doesn't happen for an existing
crawl. The docpriority for documents in the existing craw is still at
1000000001.
I believe the priority should be set by
ManifoldCF#resetAllDocumentPriorities but it's not, because
JobManager#getNextNotYetProcessedReprioritizationDocuments returns no rows
to update, which I think is due to the legacy job's docs having a
priorityset of NULL. Replacing the current priorityset condition in
JobManager#getNextNotYetProcessedReprioritizationDocuments with
(priorityset IS NULL OR priorityset<?) addresses this specific issue.
Is this a valid fix or do you see it introducing undesirable behaviour or
masking an issue elsewhere?
Cheers,
Aeham
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Thanks Karl.
I've just tested the addition of the docpriority clause and it makes a HUGE
difference! The query that used to take 12 seconds to find no hits, now
runs in 12ms!! If I tweak some of the values in the WHERE clause to make it
hit some rows, I get back the expected number of rows in ~200ms. This is an
excellent improvement!
I'll integrate the change into our build and let you know how it goes, but
the early signs are very very promising!
Many thanks,
Aeham
On 3 November 2014 11:17, Karl Wright <da...@gmail.com> wrote:
> Hi Aeham,
>
> This confirms my diagnosis. The patches I worked out over the weekend
> (attached to tickets CONNECTORS-1090 and CONNECTORS-1091) will likely fix
> the problem, which is that there is no cutoff for the docpriority value in
> the query, so rows with "null" docpriority are being scanned.
>
> Please apply the patches (they should work for 1.7.1 also), and let me
> know.
>
> If you want to assess the query in advance with an EXPLAIN, just add the
> docpriority clause to the WHERE condition, making it FIRST. The clause
> should read:
>
> t0.docpriority < 1e9+1
>
> or:
>
> t0.docpriority < 1000000001
>
> Thanks!
> Karl
>
>
> Thanks,
> Karl
>
>
> On Mon, Nov 3, 2014 at 5:18 AM, Aeham Abushwashi <
> aeham.abushwashi@exonar.com> wrote:
>
> > Hi Karl,
> >
> > >> It's reading from the correct index, but is nevertheless taking a long
> > time, possibly because there are a lot of records with status 'P' or 'G'
> > that belong to jobs that are not in state 'a' or 'A' that it has to go
> > through before it assembles 240 results. Can you confirm this picture?
> >
> > Yes, as you can see from the previous query plans, some time is spent
> > scanning index i1392985450172 (docpriority, status, checkaction,
> > checktime), which identifies >3M rows only for them to be (slowly)
> filtered
> > out in the subsequent Nested Loop Semi Join step
> >
> > +++++++++
> > -> Nested Loop Semi Join (cost=0.00..2634519.48
> rows=7784
> > width=177) (actual time=12395.696..12395.696 rows=0 loops=1)
> > -> Index Scan using i1392985450172 on jobqueue t0
> > (cost=0.00..2609016.45 rows=89520 width=177) (actual
> time=668.127..3970.495
> > rows=3346768 loops=1)
> > Index Cond: ((checkaction = 'R'::bpchar) AND
> > (checktime <= 1414683318802::bigint))
> > Filter: ((status = 'P'::bpchar) OR (status =
> > 'G'::bpchar))
> > -> Index Scan using jobs_pkey on jobs t1
> > (cost=0.00..0.28 rows=1 width=8) (actual time=0.002..0.002 rows=0
> > loops=3346768)
> > Index Cond: (id = t0.jobid)
> > Filter: ((priority = 5) AND ((status =
> > 'A'::bpchar) OR (status = 'a'::bpchar)))
> > Rows Removed by Filter: 1
> > +++++++++
> >
> >
> >
> >
> > Here's the result of the two queries (the docid values have been edited
> > slightly):
> >
> > # EXPLAIN SELECT
> > t0.id
> >
> ,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> > FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> > ORDER BY t0.docpriority LIMIT 20;
> > QUERY PLAN
> >
> >
> ------------------------------------------------------------------------------------------------------
> > Limit (cost=0.00..44.91 rows=20 width=177)
> > -> Index Scan using i1392985450172 on jobqueue t0
> > (cost=0.00..2332467.51 rows=1038668 width=177)
> > Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
> > 2414771559577::bigint))
> > (3 rows)
> >
> >
> > # SELECT t0.id
> >
> ,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> > FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> > ORDER BY t0.docpriority LIMIT 20;
> > id | jobid | dochash
> > | docid
> |
> > status | failtime | failcount | priorityset
> >
> >
> ---------------+---------------+------------------------------------------+--------------------------------------------------------+--------+----------+-----------+---------------
> > 1414075904032 | 1414075755977 |
> 874175EB926535C5FA51041B6749ED5D07E733FB |
> > smb://server12/share6/dataset/ | G | |
> > | 1414075898255
> > 1414075908486 | 1414075755977 |
> 0926EDF31E39E33B5F2ADAC7444D978BE8C44B74 |
> > smb://server12/share6/dataset/sj/ | G | | |
> > 1414075786902
> > 1414075908485 | 1414075755977 |
> 10E374B9BDF2079B50FFFCB0FE79657E443345BD |
> > smb://server12/share6/dataset/mk/ | G | |
> |
> > 1414075786902
> > 1414075908484 | 1414075755977 |
> 16612703F3352A933D7F1FBE92B732021DF89253 |
> > smb://server12/share6/dataset/bs/ | G | |
> > | 1414075786902
> > 1414075908483 | 1414075755977 |
> 37B69C012298D6E02D8F52DCC0584BF2E5F5ACC2 |
> > smb://server12/share6/dataset/le/ | G | |
> > | 1414075786902
> > 1414075908482 | 1414075755977 |
> 5A30C8F9B135C44A0AED75606950F97359C7DD6F |
> > smb://server12/share6/dataset/se/ | G | |
> |
> > 1414075786902
> > 1414075908481 | 1414075755977 |
> 5BC721E8788D524E4F47F54568FDBEB7A3E916E8 |
> > smb://server12/share6/dataset/mmk/ | G | | |
> > 1414075786902
> > 1414075908479 | 1414075755977 |
> 657D59AFB34889CD00C70C06D5079F4F11C2C6B8 |
> > smb://server12/share6/dataset/mm/ | G | | |
> > 1414075786902
> > 1414075908475 | 1414075755977 |
> 6BD906C002CC1CF76B455EDB5ADDFC56038F24A5 |
> > smb://server12/share6/dataset/sg/ | G | | |
> > 1414075786902
> > 1414075908470 | 1414075755977 |
> 70597810DD4A5E5F915491B0F1C2FA617257D728 |
> > smb://server12/share6/dataset/pd/ | G | | |
> > 1414075786902
> > 1414075908467 | 1414075755977 |
> 7212CA810B46E82A2CAD2385B8D679635EEDE9C9 |
> > smb://server12/share6/dataset/kp/ | G | |
> |
> > 1414075786902
> > 1414075908466 | 1414075755977 |
> 8298498EE916875B7C6FB8C86AC81137E0623444 |
> > smb://server12/share6/dataset/hk/ | G | |
> > | 1414075786902
> > 1414075908464 | 1414075755977 |
> 9D5D7536E1090B0B3A6745ADEE7E8498DFDCE15F |
> > smb://server12/share6/dataset/kk/ | G | |
> > | 1414075786902
> > 1414075908462 | 1414075755977 |
> A656510E82BA82E97091C47CAF2773908D636BD0 |
> > smb://server12/share6/dataset/wk/ | G | |
> > | 1414075786902
> > 1414075908461 | 1414075755977 |
> B2C98456C11BF5D3429FDD769C56E6CF6A8FD5F0 |
> > smb://server12/share6/dataset/gr/ | G | |
> > | 1414075786902
> > 1414075908458 | 1414075755977 |
> BB394B981A1928A9695FE31010D804241A72DF64 |
> > smb://server12/share6/dataset/dc/ | G | |
> > | 1414075786902
> > 1414075908457 | 1414075755977 |
> C914D0196854BF457F9631F5D3446ACCA2D5676E |
> > smb://server12/share6/dataset/dl/ | G | |
> > | 1414075786902
> > 1414075908456 | 1414075755977 |
> CE8C71D2B9768DE078734AD01B149CDFCE976B53 |
> > smb://server12/share6/dataset/cm/ | G | |
> |
> > 1414075786902
> > 1414075908455 | 1414075755977 |
> DA56598671A6A272D15D6D7216C0E7C86C706DC6 |
> > smb://server12/share6/dataset/lp/ | G | | |
> > 1414075786902
> > 1414075908453 | 1414075755977 |
> EF58A961D56F18BA0EFACE9933457A6CF4FB683B |
> > smb://server12/share6/dataset/fj/ | G | |
> > | 1414075786902
> > (20 rows)
> >
>
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Hi Aeham,
This confirms my diagnosis. The patches I worked out over the weekend
(attached to tickets CONNECTORS-1090 and CONNECTORS-1091) will likely fix
the problem, which is that there is no cutoff for the docpriority value in
the query, so rows with "null" docpriority are being scanned.
Please apply the patches (they should work for 1.7.1 also), and let me know.
If you want to assess the query in advance with an EXPLAIN, just add the
docpriority clause to the WHERE condition, making it FIRST. The clause
should read:
t0.docpriority < 1e9+1
or:
t0.docpriority < 1000000001
Thanks!
Karl
Thanks,
Karl
On Mon, Nov 3, 2014 at 5:18 AM, Aeham Abushwashi <
aeham.abushwashi@exonar.com> wrote:
> Hi Karl,
>
> >> It's reading from the correct index, but is nevertheless taking a long
> time, possibly because there are a lot of records with status 'P' or 'G'
> that belong to jobs that are not in state 'a' or 'A' that it has to go
> through before it assembles 240 results. Can you confirm this picture?
>
> Yes, as you can see from the previous query plans, some time is spent
> scanning index i1392985450172 (docpriority, status, checkaction,
> checktime), which identifies >3M rows only for them to be (slowly) filtered
> out in the subsequent Nested Loop Semi Join step
>
> +++++++++
> -> Nested Loop Semi Join (cost=0.00..2634519.48 rows=7784
> width=177) (actual time=12395.696..12395.696 rows=0 loops=1)
> -> Index Scan using i1392985450172 on jobqueue t0
> (cost=0.00..2609016.45 rows=89520 width=177) (actual time=668.127..3970.495
> rows=3346768 loops=1)
> Index Cond: ((checkaction = 'R'::bpchar) AND
> (checktime <= 1414683318802::bigint))
> Filter: ((status = 'P'::bpchar) OR (status =
> 'G'::bpchar))
> -> Index Scan using jobs_pkey on jobs t1
> (cost=0.00..0.28 rows=1 width=8) (actual time=0.002..0.002 rows=0
> loops=3346768)
> Index Cond: (id = t0.jobid)
> Filter: ((priority = 5) AND ((status =
> 'A'::bpchar) OR (status = 'a'::bpchar)))
> Rows Removed by Filter: 1
> +++++++++
>
>
>
>
> Here's the result of the two queries (the docid values have been edited
> slightly):
>
> # EXPLAIN SELECT
> t0.id
> ,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> ORDER BY t0.docpriority LIMIT 20;
> QUERY PLAN
>
> ------------------------------------------------------------------------------------------------------
> Limit (cost=0.00..44.91 rows=20 width=177)
> -> Index Scan using i1392985450172 on jobqueue t0
> (cost=0.00..2332467.51 rows=1038668 width=177)
> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
> 2414771559577::bigint))
> (3 rows)
>
>
> # SELECT t0.id
> ,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> ORDER BY t0.docpriority LIMIT 20;
> id | jobid | dochash
> | docid |
> status | failtime | failcount | priorityset
>
> ---------------+---------------+------------------------------------------+--------------------------------------------------------+--------+----------+-----------+---------------
> 1414075904032 | 1414075755977 | 874175EB926535C5FA51041B6749ED5D07E733FB |
> smb://server12/share6/dataset/ | G | |
> | 1414075898255
> 1414075908486 | 1414075755977 | 0926EDF31E39E33B5F2ADAC7444D978BE8C44B74 |
> smb://server12/share6/dataset/sj/ | G | | |
> 1414075786902
> 1414075908485 | 1414075755977 | 10E374B9BDF2079B50FFFCB0FE79657E443345BD |
> smb://server12/share6/dataset/mk/ | G | | |
> 1414075786902
> 1414075908484 | 1414075755977 | 16612703F3352A933D7F1FBE92B732021DF89253 |
> smb://server12/share6/dataset/bs/ | G | |
> | 1414075786902
> 1414075908483 | 1414075755977 | 37B69C012298D6E02D8F52DCC0584BF2E5F5ACC2 |
> smb://server12/share6/dataset/le/ | G | |
> | 1414075786902
> 1414075908482 | 1414075755977 | 5A30C8F9B135C44A0AED75606950F97359C7DD6F |
> smb://server12/share6/dataset/se/ | G | | |
> 1414075786902
> 1414075908481 | 1414075755977 | 5BC721E8788D524E4F47F54568FDBEB7A3E916E8 |
> smb://server12/share6/dataset/mmk/ | G | | |
> 1414075786902
> 1414075908479 | 1414075755977 | 657D59AFB34889CD00C70C06D5079F4F11C2C6B8 |
> smb://server12/share6/dataset/mm/ | G | | |
> 1414075786902
> 1414075908475 | 1414075755977 | 6BD906C002CC1CF76B455EDB5ADDFC56038F24A5 |
> smb://server12/share6/dataset/sg/ | G | | |
> 1414075786902
> 1414075908470 | 1414075755977 | 70597810DD4A5E5F915491B0F1C2FA617257D728 |
> smb://server12/share6/dataset/pd/ | G | | |
> 1414075786902
> 1414075908467 | 1414075755977 | 7212CA810B46E82A2CAD2385B8D679635EEDE9C9 |
> smb://server12/share6/dataset/kp/ | G | | |
> 1414075786902
> 1414075908466 | 1414075755977 | 8298498EE916875B7C6FB8C86AC81137E0623444 |
> smb://server12/share6/dataset/hk/ | G | |
> | 1414075786902
> 1414075908464 | 1414075755977 | 9D5D7536E1090B0B3A6745ADEE7E8498DFDCE15F |
> smb://server12/share6/dataset/kk/ | G | |
> | 1414075786902
> 1414075908462 | 1414075755977 | A656510E82BA82E97091C47CAF2773908D636BD0 |
> smb://server12/share6/dataset/wk/ | G | |
> | 1414075786902
> 1414075908461 | 1414075755977 | B2C98456C11BF5D3429FDD769C56E6CF6A8FD5F0 |
> smb://server12/share6/dataset/gr/ | G | |
> | 1414075786902
> 1414075908458 | 1414075755977 | BB394B981A1928A9695FE31010D804241A72DF64 |
> smb://server12/share6/dataset/dc/ | G | |
> | 1414075786902
> 1414075908457 | 1414075755977 | C914D0196854BF457F9631F5D3446ACCA2D5676E |
> smb://server12/share6/dataset/dl/ | G | |
> | 1414075786902
> 1414075908456 | 1414075755977 | CE8C71D2B9768DE078734AD01B149CDFCE976B53 |
> smb://server12/share6/dataset/cm/ | G | | |
> 1414075786902
> 1414075908455 | 1414075755977 | DA56598671A6A272D15D6D7216C0E7C86C706DC6 |
> smb://server12/share6/dataset/lp/ | G | | |
> 1414075786902
> 1414075908453 | 1414075755977 | EF58A961D56F18BA0EFACE9933457A6CF4FB683B |
> smb://server12/share6/dataset/fj/ | G | |
> | 1414075786902
> (20 rows)
>
Re: (Continuous) crawl performance
Posted by Aeham Abushwashi <ae...@exonar.com>.
Hi Karl,
>> It's reading from the correct index, but is nevertheless taking a long
time, possibly because there are a lot of records with status 'P' or 'G'
that belong to jobs that are not in state 'a' or 'A' that it has to go
through before it assembles 240 results. Can you confirm this picture?
Yes, as you can see from the previous query plans, some time is spent
scanning index i1392985450172 (docpriority, status, checkaction,
checktime), which identifies >3M rows only for them to be (slowly) filtered
out in the subsequent Nested Loop Semi Join step
+++++++++
-> Nested Loop Semi Join (cost=0.00..2634519.48 rows=7784
width=177) (actual time=12395.696..12395.696 rows=0 loops=1)
-> Index Scan using i1392985450172 on jobqueue t0
(cost=0.00..2609016.45 rows=89520 width=177) (actual time=668.127..3970.495
rows=3346768 loops=1)
Index Cond: ((checkaction = 'R'::bpchar) AND
(checktime <= 1414683318802::bigint))
Filter: ((status = 'P'::bpchar) OR (status =
'G'::bpchar))
-> Index Scan using jobs_pkey on jobs t1
(cost=0.00..0.28 rows=1 width=8) (actual time=0.002..0.002 rows=0
loops=3346768)
Index Cond: (id = t0.jobid)
Filter: ((priority = 5) AND ((status =
'A'::bpchar) OR (status = 'a'::bpchar)))
Rows Removed by Filter: 1
+++++++++
Here's the result of the two queries (the docid values have been edited
slightly):
# EXPLAIN SELECT
t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
ORDER BY t0.docpriority LIMIT 20;
QUERY PLAN
------------------------------------------------------------------------------------------------------
Limit (cost=0.00..44.91 rows=20 width=177)
-> Index Scan using i1392985450172 on jobqueue t0
(cost=0.00..2332467.51 rows=1038668 width=177)
Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
2414771559577::bigint))
(3 rows)
# SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
ORDER BY t0.docpriority LIMIT 20;
id | jobid | dochash
| docid |
status | failtime | failcount | priorityset
---------------+---------------+------------------------------------------+--------------------------------------------------------+--------+----------+-----------+---------------
1414075904032 | 1414075755977 | 874175EB926535C5FA51041B6749ED5D07E733FB |
smb://server12/share6/dataset/ | G | |
| 1414075898255
1414075908486 | 1414075755977 | 0926EDF31E39E33B5F2ADAC7444D978BE8C44B74 |
smb://server12/share6/dataset/sj/ | G | | |
1414075786902
1414075908485 | 1414075755977 | 10E374B9BDF2079B50FFFCB0FE79657E443345BD |
smb://server12/share6/dataset/mk/ | G | | |
1414075786902
1414075908484 | 1414075755977 | 16612703F3352A933D7F1FBE92B732021DF89253 |
smb://server12/share6/dataset/bs/ | G | |
| 1414075786902
1414075908483 | 1414075755977 | 37B69C012298D6E02D8F52DCC0584BF2E5F5ACC2 |
smb://server12/share6/dataset/le/ | G | |
| 1414075786902
1414075908482 | 1414075755977 | 5A30C8F9B135C44A0AED75606950F97359C7DD6F |
smb://server12/share6/dataset/se/ | G | | |
1414075786902
1414075908481 | 1414075755977 | 5BC721E8788D524E4F47F54568FDBEB7A3E916E8 |
smb://server12/share6/dataset/mmk/ | G | | |
1414075786902
1414075908479 | 1414075755977 | 657D59AFB34889CD00C70C06D5079F4F11C2C6B8 |
smb://server12/share6/dataset/mm/ | G | | |
1414075786902
1414075908475 | 1414075755977 | 6BD906C002CC1CF76B455EDB5ADDFC56038F24A5 |
smb://server12/share6/dataset/sg/ | G | | |
1414075786902
1414075908470 | 1414075755977 | 70597810DD4A5E5F915491B0F1C2FA617257D728 |
smb://server12/share6/dataset/pd/ | G | | |
1414075786902
1414075908467 | 1414075755977 | 7212CA810B46E82A2CAD2385B8D679635EEDE9C9 |
smb://server12/share6/dataset/kp/ | G | | |
1414075786902
1414075908466 | 1414075755977 | 8298498EE916875B7C6FB8C86AC81137E0623444 |
smb://server12/share6/dataset/hk/ | G | |
| 1414075786902
1414075908464 | 1414075755977 | 9D5D7536E1090B0B3A6745ADEE7E8498DFDCE15F |
smb://server12/share6/dataset/kk/ | G | |
| 1414075786902
1414075908462 | 1414075755977 | A656510E82BA82E97091C47CAF2773908D636BD0 |
smb://server12/share6/dataset/wk/ | G | |
| 1414075786902
1414075908461 | 1414075755977 | B2C98456C11BF5D3429FDD769C56E6CF6A8FD5F0 |
smb://server12/share6/dataset/gr/ | G | |
| 1414075786902
1414075908458 | 1414075755977 | BB394B981A1928A9695FE31010D804241A72DF64 |
smb://server12/share6/dataset/dc/ | G | |
| 1414075786902
1414075908457 | 1414075755977 | C914D0196854BF457F9631F5D3446ACCA2D5676E |
smb://server12/share6/dataset/dl/ | G | |
| 1414075786902
1414075908456 | 1414075755977 | CE8C71D2B9768DE078734AD01B149CDFCE976B53 |
smb://server12/share6/dataset/cm/ | G | | |
1414075786902
1414075908455 | 1414075755977 | DA56598671A6A272D15D6D7216C0E7C86C706DC6 |
smb://server12/share6/dataset/lp/ | G | | |
1414075786902
1414075908453 | 1414075755977 | EF58A961D56F18BA0EFACE9933457A6CF4FB683B |
smb://server12/share6/dataset/fj/ | G | |
| 1414075786902
(20 rows)
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Ok, in order for everything to work as planned, you will also need the
patch for CONNECTORS-1091 applied. In fact this latter problem is serious
enough that it may warrant a 1.7.2 release, along with CONNECTORS-1090
fixes.
Karl
On Sun, Nov 2, 2014 at 8:51 PM, Karl Wright <da...@gmail.com> wrote:
> Unfortunately, I've found that this change triggers another bug. Please
> hold off until I have a fix for that one as well.
>
> Karl
>
>
> On Sun, Nov 2, 2014 at 9:34 AM, Karl Wright <da...@gmail.com> wrote:
>
>> Hi Aeham,
>>
>> The more I look at this, the more I'm convinced that there must be a bug
>> elsewhere that permits jobqueue records with non-null document priorities
>> to hang around.
>>
>> If you look at this JobManager method:
>>
>> public void finishJobStops(long timestamp, ArrayList modifiedJobs)
>> throws ManifoldCFException
>>
>> ... which is used whenever a job is stopped for any reason, you will note
>> that the logic in question is *supposed* to clear the document priority
>> field for all documents belonging to that job. If that works as it is
>> supposed to, then there should be *no* documents in the docpriority index
>> with a document priority which belong to inactive or paused jobs.
>>
>> So the only way that this index can be slow is if, perchance, PostgreSQL
>> puts "null" values for a field FIRST in the index. But:
>>
>> >>>>>>
>> /** Clear all document priorities for a job */
>> public void clearDocPriorities(Long jobID)
>> throws ManifoldCFException
>> {
>> HashMap map = new HashMap();
>> map.put(prioritySetField,null);
>> map.put(docPriorityField,nullDocPriority);
>> ArrayList list = new ArrayList();
>> String query = buildConjunctionClause(list,new ClauseDescription[]{
>> new UnitaryClause(jobIDField,jobID)});
>> performUpdate(map,"WHERE "+query,list,null);
>> noteModifications(0,1,0);
>> }
>> <<<<<<
>>
>> ... where "nullDocPriority" is declared as:
>>
>> >>>>>>
>> public static final double noDocPriorityValue = 1e9;
>> public static final Double nullDocPriority = new
>> Double(noDocPriorityValue + 1.0);
>> <<<<<<
>>
>> ... which is a value picked to be last, always. (It was necessary to
>> pick a specific value because MySQL did not put nulls at the end, but
>> rather at the beginning.)
>>
>> So now I am very curious as to what is *really* at the front of this
>> index -- so please execute the query I sent and let me know.
>>
>> It occurs to me that there is another way for the query to be slow,
>> however -- which is if there are insufficient matching rows to meet the
>> LIMIT size. In this case, the entire index would be scanned. But this can
>> be readily addressed by simply putting in an appropriate WHERE condition:
>>
>> >>>>>>
>> new UnitaryClause("t0."+jobQueue.docPriorityField,"<",nullDocPriority),
>> <<<<<<
>>
>> If the results of the query I asked you to run look fine, then we may
>> want to try this next. I've attached a second patch to CONNECTORS-1090.
>> Please apply both patches to see if that fixes your query execution time.
>>
>>
>> Thanks,
>> Karl
>>
>>
>>
>> On Sat, Nov 1, 2014 at 8:09 AM, Karl Wright <da...@gmail.com> wrote:
>>
>>> Hi Aeham,
>>>
>>> To figure out what is going on, it would probably be sufficient to
>>> execute the following queries and send me the results:
>>>
>>> EXPLAIN SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
>>> ORDER BY t0.docpriority LIMIT 20;
>>> SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
>>> ORDER BY t0.docpriority LIMIT 20;
>>>
>>> These should both read directly from the index in question; we can see
>>> immediately what kinds of documents it is having to skip to get to the
>>> active ones.
>>>
>>> Thanks!
>>> Karl
>>>
>>>
>>> On Fri, Oct 31, 2014 at 2:42 PM, Karl Wright <da...@gmail.com> wrote:
>>>
>>>> Hi Aeham,
>>>>
>>>> I've looked at this at some level of detail now, and have some
>>>> conclusions.
>>>>
>>>> (1) The first query you provided is in fact using the proper index for
>>>> ordering; it's just not obvious from the plan. The way you can tell is if
>>>> there is an explicit sort/limit. The primary jobqueue index scan is
>>>> happening within an anti-join and a semi-join; you can tell this by cutting
>>>> out all the EXISTS clauses and getting a reduced plan that way, and
>>>> comparing. For instance, here's an explain of the simple query:
>>>>
>>>> >>>>>>
>>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>>> FROM jobqueue t0 ORDER BY t0.docpriority LIMIT 240;
>>>> QUERY PLAN
>>>>
>>>>
>>>> -------------------------------------------------------------------------------------------------
>>>> Limit (cost=0.29..38.20 rows=240 width=161)
>>>> -> Index Scan using i1413214448001 on jobqueue t0
>>>> (cost=0.29..2312.39 rows=14634 width=161)
>>>> (2 rows)
>>>> <<<<<<
>>>>
>>>> Applying filtering criteria:
>>>>
>>>> >>>>>>
>>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>>>> t0.checkaction='R' AND t0.checktime<=2414771559577 ORDER BY t0.docpriority
>>>> LIMIT 240;
>>>> QUERY PLAN
>>>>
>>>>
>>>> ------------------------------------------------------------------------------------------------
>>>> Limit (cost=0.29..68.98 rows=240 width=161)
>>>> -> Index Scan using i1413214448001 on jobqueue t0
>>>> (cost=0.29..2389.31 rows=8347 width=161)
>>>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
>>>> 2414771559577::bigint))
>>>> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
>>>> (4 rows)
>>>> <<<<<<
>>>>
>>>> Now, this is a bit strange, because there is a filter on the status, so
>>>> the index isn't helping there, and yet the index includes the status:
>>>> "i1413214448001" btree (docpriority, status, checkaction, checktime)
>>>> But maybe this is a statistical optimization? I don't know.
>>>>
>>>> Anyhow, as soon as a NOT EXISTS clause is added, you see an anti-join:
>>>>
>>>> >>>>>>
>>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>>>> t0.checkaction='R' AND t0.checktime<=2414771559577 AND NOT EXISTS(SELECT
>>>> 'x' FROM prereqevents t3,events t4 WHERE t0.id=t3.owner AND
>>>> t3.eventname=t4.name) ORDER BY t0.docpriority LIMIT 240;
>>>> QUERY PLAN
>>>>
>>>>
>>>> ----------------------------------------------------------------------------------------------------------
>>>> Limit (cost=0.57..231.40 rows=240 width=161)
>>>> -> Nested Loop Anti Join (cost=0.57..7957.24 rows=8273 width=161)
>>>> -> Index Scan using i1413214448001 on jobqueue t0
>>>> (cost=0.29..2389.31 rows=8347 width=161)
>>>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime
>>>> <= 2414771559577::bigint))
>>>> Filter: ((status = 'P'::bpchar) OR (status =
>>>> 'G'::bpchar))
>>>> -> Nested Loop (cost=0.29..0.66 rows=1 width=8)
>>>> -> Index Scan using i1413214448007 on prereqevents t3
>>>> (cost=0.14..0.17 rows=1 width=524)
>>>> Index Cond: (t0.id = owner)
>>>> -> Index Only Scan using events_pkey on events t4
>>>> (cost=0.14..0.48 rows=1 width=516)
>>>> Index Cond: (name = (t3.eventname)::text)
>>>> (10 rows)
>>>> <<<<<<
>>>>
>>>> The index scan is still there and is apparently providing the sorting,
>>>> which is good still. It's just inside an anti-join.
>>>>
>>>> So you can take this further and add the two remaining EXISTS/NOT
>>>> EXISTS clauses, and then your first plan makes sense. But your proposed
>>>> *second* plan is clearly *not* using the docpriority index for sorting,
>>>> since it sorts by itself later on:
>>>>
>>>> >>>>>>
>>>> Limit (cost=122440.72..122441.42 rows=280 width=177) (actual
>>>> time=1010.722..1010.722 rows=0 loops=1)
>>>> -> Sort (cost=122440.72..122451.13 rows=4164 width=177) (actual
>>>> time=1010.719..1010.719 rows=0 loops=1)
>>>> Sort Key: t0.docpriority
>>>> Sort Method: quicksort Memory: 25kB
>>>> <<<<<<
>>>>
>>>> So what we need to understand now is why the first query is slow. It's
>>>> reading from the correct index, but is nevertheless taking a long time,
>>>> possibly because there are a lot of records with status 'P' or 'G' that
>>>> belong to jobs that are not in state 'a' or 'A' that it has to go through
>>>> before it assembles 240 results. Can you confirm this picture?
>>>>
>>>> Thanks,
>>>> Karl
>>>>
>>>>
>>>> On Fri, Oct 31, 2014 at 1:09 PM, Aeham Abushwashi <
>>>> aeham.abushwashi@exonar.com> wrote:
>>>>
>>>>> That's great news, thanks Karl! On my part, I've been digging deeper
>>>>> into
>>>>> the execution plans of the two queries and I've made a similar
>>>>> observation
>>>>> of the ORDER BY skewing the original query's plan significantly.
>>>>> However, I
>>>>> have yet to figure out why the same ORDER BY clause doesn't have a
>>>>> similar
>>>>> impact on the modified query that uses JOIN. I'll look into this a bit
>>>>> more
>>>>> over the weekend.
>>>>>
>>>>> Best regards,
>>>>> Aeham
>>>>>
>>>>
>>>>
>>>
>>
>
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Unfortunately, I've found that this change triggers another bug. Please
hold off until I have a fix for that one as well.
Karl
On Sun, Nov 2, 2014 at 9:34 AM, Karl Wright <da...@gmail.com> wrote:
> Hi Aeham,
>
> The more I look at this, the more I'm convinced that there must be a bug
> elsewhere that permits jobqueue records with non-null document priorities
> to hang around.
>
> If you look at this JobManager method:
>
> public void finishJobStops(long timestamp, ArrayList modifiedJobs)
> throws ManifoldCFException
>
> ... which is used whenever a job is stopped for any reason, you will note
> that the logic in question is *supposed* to clear the document priority
> field for all documents belonging to that job. If that works as it is
> supposed to, then there should be *no* documents in the docpriority index
> with a document priority which belong to inactive or paused jobs.
>
> So the only way that this index can be slow is if, perchance, PostgreSQL
> puts "null" values for a field FIRST in the index. But:
>
> >>>>>>
> /** Clear all document priorities for a job */
> public void clearDocPriorities(Long jobID)
> throws ManifoldCFException
> {
> HashMap map = new HashMap();
> map.put(prioritySetField,null);
> map.put(docPriorityField,nullDocPriority);
> ArrayList list = new ArrayList();
> String query = buildConjunctionClause(list,new ClauseDescription[]{
> new UnitaryClause(jobIDField,jobID)});
> performUpdate(map,"WHERE "+query,list,null);
> noteModifications(0,1,0);
> }
> <<<<<<
>
> ... where "nullDocPriority" is declared as:
>
> >>>>>>
> public static final double noDocPriorityValue = 1e9;
> public static final Double nullDocPriority = new
> Double(noDocPriorityValue + 1.0);
> <<<<<<
>
> ... which is a value picked to be last, always. (It was necessary to pick
> a specific value because MySQL did not put nulls at the end, but rather at
> the beginning.)
>
> So now I am very curious as to what is *really* at the front of this index
> -- so please execute the query I sent and let me know.
>
> It occurs to me that there is another way for the query to be slow,
> however -- which is if there are insufficient matching rows to meet the
> LIMIT size. In this case, the entire index would be scanned. But this can
> be readily addressed by simply putting in an appropriate WHERE condition:
>
> >>>>>>
> new UnitaryClause("t0."+jobQueue.docPriorityField,"<",nullDocPriority),
> <<<<<<
>
> If the results of the query I asked you to run look fine, then we may want
> to try this next. I've attached a second patch to CONNECTORS-1090. Please
> apply both patches to see if that fixes your query execution time.
>
>
> Thanks,
> Karl
>
>
>
> On Sat, Nov 1, 2014 at 8:09 AM, Karl Wright <da...@gmail.com> wrote:
>
>> Hi Aeham,
>>
>> To figure out what is going on, it would probably be sufficient to
>> execute the following queries and send me the results:
>>
>> EXPLAIN SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
>> ORDER BY t0.docpriority LIMIT 20;
>> SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
>> ORDER BY t0.docpriority LIMIT 20;
>>
>> These should both read directly from the index in question; we can see
>> immediately what kinds of documents it is having to skip to get to the
>> active ones.
>>
>> Thanks!
>> Karl
>>
>>
>> On Fri, Oct 31, 2014 at 2:42 PM, Karl Wright <da...@gmail.com> wrote:
>>
>>> Hi Aeham,
>>>
>>> I've looked at this at some level of detail now, and have some
>>> conclusions.
>>>
>>> (1) The first query you provided is in fact using the proper index for
>>> ordering; it's just not obvious from the plan. The way you can tell is if
>>> there is an explicit sort/limit. The primary jobqueue index scan is
>>> happening within an anti-join and a semi-join; you can tell this by cutting
>>> out all the EXISTS clauses and getting a reduced plan that way, and
>>> comparing. For instance, here's an explain of the simple query:
>>>
>>> >>>>>>
>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>> FROM jobqueue t0 ORDER BY t0.docpriority LIMIT 240;
>>> QUERY PLAN
>>>
>>>
>>> -------------------------------------------------------------------------------------------------
>>> Limit (cost=0.29..38.20 rows=240 width=161)
>>> -> Index Scan using i1413214448001 on jobqueue t0
>>> (cost=0.29..2312.39 rows=14634 width=161)
>>> (2 rows)
>>> <<<<<<
>>>
>>> Applying filtering criteria:
>>>
>>> >>>>>>
>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>>> t0.checkaction='R' AND t0.checktime<=2414771559577 ORDER BY t0.docpriority
>>> LIMIT 240;
>>> QUERY PLAN
>>>
>>>
>>> ------------------------------------------------------------------------------------------------
>>> Limit (cost=0.29..68.98 rows=240 width=161)
>>> -> Index Scan using i1413214448001 on jobqueue t0
>>> (cost=0.29..2389.31 rows=8347 width=161)
>>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
>>> 2414771559577::bigint))
>>> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
>>> (4 rows)
>>> <<<<<<
>>>
>>> Now, this is a bit strange, because there is a filter on the status, so
>>> the index isn't helping there, and yet the index includes the status:
>>> "i1413214448001" btree (docpriority, status, checkaction, checktime)
>>> But maybe this is a statistical optimization? I don't know.
>>>
>>> Anyhow, as soon as a NOT EXISTS clause is added, you see an anti-join:
>>>
>>> >>>>>>
>>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>>> t0.checkaction='R' AND t0.checktime<=2414771559577 AND NOT EXISTS(SELECT
>>> 'x' FROM prereqevents t3,events t4 WHERE t0.id=t3.owner AND
>>> t3.eventname=t4.name) ORDER BY t0.docpriority LIMIT 240;
>>> QUERY PLAN
>>>
>>>
>>> ----------------------------------------------------------------------------------------------------------
>>> Limit (cost=0.57..231.40 rows=240 width=161)
>>> -> Nested Loop Anti Join (cost=0.57..7957.24 rows=8273 width=161)
>>> -> Index Scan using i1413214448001 on jobqueue t0
>>> (cost=0.29..2389.31 rows=8347 width=161)
>>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime
>>> <= 2414771559577::bigint))
>>> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
>>> -> Nested Loop (cost=0.29..0.66 rows=1 width=8)
>>> -> Index Scan using i1413214448007 on prereqevents t3
>>> (cost=0.14..0.17 rows=1 width=524)
>>> Index Cond: (t0.id = owner)
>>> -> Index Only Scan using events_pkey on events t4
>>> (cost=0.14..0.48 rows=1 width=516)
>>> Index Cond: (name = (t3.eventname)::text)
>>> (10 rows)
>>> <<<<<<
>>>
>>> The index scan is still there and is apparently providing the sorting,
>>> which is good still. It's just inside an anti-join.
>>>
>>> So you can take this further and add the two remaining EXISTS/NOT EXISTS
>>> clauses, and then your first plan makes sense. But your proposed *second*
>>> plan is clearly *not* using the docpriority index for sorting, since it
>>> sorts by itself later on:
>>>
>>> >>>>>>
>>> Limit (cost=122440.72..122441.42 rows=280 width=177) (actual
>>> time=1010.722..1010.722 rows=0 loops=1)
>>> -> Sort (cost=122440.72..122451.13 rows=4164 width=177) (actual
>>> time=1010.719..1010.719 rows=0 loops=1)
>>> Sort Key: t0.docpriority
>>> Sort Method: quicksort Memory: 25kB
>>> <<<<<<
>>>
>>> So what we need to understand now is why the first query is slow. It's
>>> reading from the correct index, but is nevertheless taking a long time,
>>> possibly because there are a lot of records with status 'P' or 'G' that
>>> belong to jobs that are not in state 'a' or 'A' that it has to go through
>>> before it assembles 240 results. Can you confirm this picture?
>>>
>>> Thanks,
>>> Karl
>>>
>>>
>>> On Fri, Oct 31, 2014 at 1:09 PM, Aeham Abushwashi <
>>> aeham.abushwashi@exonar.com> wrote:
>>>
>>>> That's great news, thanks Karl! On my part, I've been digging deeper
>>>> into
>>>> the execution plans of the two queries and I've made a similar
>>>> observation
>>>> of the ORDER BY skewing the original query's plan significantly.
>>>> However, I
>>>> have yet to figure out why the same ORDER BY clause doesn't have a
>>>> similar
>>>> impact on the modified query that uses JOIN. I'll look into this a bit
>>>> more
>>>> over the weekend.
>>>>
>>>> Best regards,
>>>> Aeham
>>>>
>>>
>>>
>>
>
Re: (Continuous) crawl performance
Posted by Karl Wright <da...@gmail.com>.
Hi Aeham,
The more I look at this, the more I'm convinced that there must be a bug
elsewhere that permits jobqueue records with non-null document priorities
to hang around.
If you look at this JobManager method:
public void finishJobStops(long timestamp, ArrayList modifiedJobs)
throws ManifoldCFException
... which is used whenever a job is stopped for any reason, you will note
that the logic in question is *supposed* to clear the document priority
field for all documents belonging to that job. If that works as it is
supposed to, then there should be *no* documents in the docpriority index
with a document priority which belong to inactive or paused jobs.
So the only way that this index can be slow is if, perchance, PostgreSQL
puts "null" values for a field FIRST in the index. But:
>>>>>>
/** Clear all document priorities for a job */
public void clearDocPriorities(Long jobID)
throws ManifoldCFException
{
HashMap map = new HashMap();
map.put(prioritySetField,null);
map.put(docPriorityField,nullDocPriority);
ArrayList list = new ArrayList();
String query = buildConjunctionClause(list,new ClauseDescription[]{
new UnitaryClause(jobIDField,jobID)});
performUpdate(map,"WHERE "+query,list,null);
noteModifications(0,1,0);
}
<<<<<<
... where "nullDocPriority" is declared as:
>>>>>>
public static final double noDocPriorityValue = 1e9;
public static final Double nullDocPriority = new
Double(noDocPriorityValue + 1.0);
<<<<<<
... which is a value picked to be last, always. (It was necessary to pick
a specific value because MySQL did not put nulls at the end, but rather at
the beginning.)
So now I am very curious as to what is *really* at the front of this index
-- so please execute the query I sent and let me know.
It occurs to me that there is another way for the query to be slow, however
-- which is if there are insufficient matching rows to meet the LIMIT
size. In this case, the entire index would be scanned. But this can be
readily addressed by simply putting in an appropriate WHERE condition:
>>>>>>
new UnitaryClause("t0."+jobQueue.docPriorityField,"<",nullDocPriority),
<<<<<<
If the results of the query I asked you to run look fine, then we may want
to try this next. I've attached a second patch to CONNECTORS-1090. Please
apply both patches to see if that fixes your query execution time.
Thanks,
Karl
On Sat, Nov 1, 2014 at 8:09 AM, Karl Wright <da...@gmail.com> wrote:
> Hi Aeham,
>
> To figure out what is going on, it would probably be sufficient to execute
> the following queries and send me the results:
>
> EXPLAIN SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> ORDER BY t0.docpriority LIMIT 20;
> SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
> FROM jobqueue t0 WHERE t0.checkaction='R' AND t0.checktime<=2414771559577
> ORDER BY t0.docpriority LIMIT 20;
>
> These should both read directly from the index in question; we can see
> immediately what kinds of documents it is having to skip to get to the
> active ones.
>
> Thanks!
> Karl
>
>
> On Fri, Oct 31, 2014 at 2:42 PM, Karl Wright <da...@gmail.com> wrote:
>
>> Hi Aeham,
>>
>> I've looked at this at some level of detail now, and have some
>> conclusions.
>>
>> (1) The first query you provided is in fact using the proper index for
>> ordering; it's just not obvious from the plan. The way you can tell is if
>> there is an explicit sort/limit. The primary jobqueue index scan is
>> happening within an anti-join and a semi-join; you can tell this by cutting
>> out all the EXISTS clauses and getting a reduced plan that way, and
>> comparing. For instance, here's an explain of the simple query:
>>
>> >>>>>>
>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>> FROM jobqueue t0 ORDER BY t0.docpriority LIMIT 240;
>> QUERY PLAN
>>
>>
>> -------------------------------------------------------------------------------------------------
>> Limit (cost=0.29..38.20 rows=240 width=161)
>> -> Index Scan using i1413214448001 on jobqueue t0
>> (cost=0.29..2312.39 rows=14634 width=161)
>> (2 rows)
>> <<<<<<
>>
>> Applying filtering criteria:
>>
>> >>>>>>
>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>> t0.checkaction='R' AND t0.checktime<=2414771559577 ORDER BY t0.docpriority
>> LIMIT 240;
>> QUERY PLAN
>>
>>
>> ------------------------------------------------------------------------------------------------
>> Limit (cost=0.29..68.98 rows=240 width=161)
>> -> Index Scan using i1413214448001 on jobqueue t0
>> (cost=0.29..2389.31 rows=8347 width=161)
>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
>> 2414771559577::bigint))
>> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
>> (4 rows)
>> <<<<<<
>>
>> Now, this is a bit strange, because there is a filter on the status, so
>> the index isn't helping there, and yet the index includes the status:
>> "i1413214448001" btree (docpriority, status, checkaction, checktime)
>> But maybe this is a statistical optimization? I don't know.
>>
>> Anyhow, as soon as a NOT EXISTS clause is added, you see an anti-join:
>>
>> >>>>>>
>> dbname=# explain SELECT t0.id,t0.jobid,t0.dochash,t0.docid,t0.status,t0.failtime,t0.failcount,t0.priorityset
>> FROM jobqueue t0 WHERE (t0.status='P' OR t0.status='G') AND
>> t0.checkaction='R' AND t0.checktime<=2414771559577 AND NOT EXISTS(SELECT
>> 'x' FROM prereqevents t3,events t4 WHERE t0.id=t3.owner AND t3.eventname=
>> t4.name) ORDER BY t0.docpriority LIMIT 240;
>> QUERY PLAN
>>
>>
>> ----------------------------------------------------------------------------------------------------------
>> Limit (cost=0.57..231.40 rows=240 width=161)
>> -> Nested Loop Anti Join (cost=0.57..7957.24 rows=8273 width=161)
>> -> Index Scan using i1413214448001 on jobqueue t0
>> (cost=0.29..2389.31 rows=8347 width=161)
>> Index Cond: ((checkaction = 'R'::bpchar) AND (checktime <=
>> 2414771559577::bigint))
>> Filter: ((status = 'P'::bpchar) OR (status = 'G'::bpchar))
>> -> Nested Loop (cost=0.29..0.66 rows=1 width=8)
>> -> Index Scan using i1413214448007 on prereqevents t3
>> (cost=0.14..0.17 rows=1 width=524)
>> Index Cond: (t0.id = owner)
>> -> Index Only Scan using events_pkey on events t4
>> (cost=0.14..0.48 rows=1 width=516)
>> Index Cond: (name = (t3.eventname)::text)
>> (10 rows)
>> <<<<<<
>>
>> The index scan is still there and is apparently providing the sorting,
>> which is good still. It's just inside an anti-join.
>>
>> So you can take this further and add the two remaining EXISTS/NOT EXISTS
>> clauses, and then your first plan makes sense. But your proposed *second*
>> plan is clearly *not* using the docpriority index for sorting, since it
>> sorts by itself later on:
>>
>> >>>>>>
>> Limit (cost=122440.72..122441.42 rows=280 width=177) (actual
>> time=1010.722..1010.722 rows=0 loops=1)
>> -> Sort (cost=122440.72..122451.13 rows=4164 width=177) (actual
>> time=1010.719..1010.719 rows=0 loops=1)
>> Sort Key: t0.docpriority
>> Sort Method: quicksort Memory: 25kB
>> <<<<<<
>>
>> So what we need to understand now is why the first query is slow. It's
>> reading from the correct index, but is nevertheless taking a long time,
>> possibly because there are a lot of records with status 'P' or 'G' that
>> belong to jobs that are not in state 'a' or 'A' that it has to go through
>> before it assembles 240 results. Can you confirm this picture?
>>
>> Thanks,
>> Karl
>>
>>
>> On Fri, Oct 31, 2014 at 1:09 PM, Aeham Abushwashi <
>> aeham.abushwashi@exonar.com> wrote:
>>
>>> That's great news, thanks Karl! On my part, I've been digging deeper into
>>> the execution plans of the two queries and I've made a similar
>>> observation
>>> of the ORDER BY skewing the original query's plan significantly.
>>> However, I
>>> have yet to figure out why the same ORDER BY clause doesn't have a
>>> similar
>>> impact on the modified query that uses JOIN. I'll look into this a bit
>>> more
>>> over the weekend.
>>>
>>> Best regards,
>>> Aeham
>>>
>>
>>
>