jackrabbit-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "kazim_ssuet@yahoo.com" <kazim_ss...@yahoo.com>
Subject query.execute() and result.getNodes() taking over 20 min each
Date Wed, 27 Oct 2010 17:27:08 GMT

Hi,
My queries are performing very poorly after loading 10K documents in
repository. This is not related to having 10K child nodes under a parent,
since these documents are distributed as
"ClientCode/EntityType/EntityCreationDate/EntityCode/FileNode".

I am using standalone server and in debug log I see thousands of repetitions
of following lines (actually there are about 69K lines of log, for just one
search, and majority are the following lines):
...
...
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
0d7cb53c-ece7-4c18-80b9-38eb863b1e49
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
0d7cb53c-ece7-4c18-80b9-38eb863b1e49/{http://www.csi.com}oid
27.10.2010 11:40:48 *DEBUG* FilterMultiColumnQuery:
[fdfeff7e-2084-4c6a-b9d1-9fb2bb9f9d76(62)]
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
fdfeff7e-2084-4c6a-b9d1-9fb2bb9f9d76
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
fdfeff7e-2084-4c6a-b9d1-9fb2bb9f9d76/{http://www.csi.com}oid
27.10.2010 11:40:48 *DEBUG* FilterMultiColumnQuery:
[8b482401-7a45-4fe9-bc50-91d2ea42846b(64)]
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
8b482401-7a45-4fe9-bc50-91d2ea42846b
...
...
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
8b482401-7a45-4fe9-bc50-91d2ea42846b/{http://www.csi.com}oid
27.10.2010 11:40:48 *DEBUG* FilterMultiColumnQuery:
[18a51aff-496c-483f-9b1e-82f4a46b387a(68)]
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
18a51aff-496c-483f-9b1e-82f4a46b387a
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
18a51aff-496c-483f-9b1e-82f4a46b387a/{http://www.csi.com}oid
27.10.2010 11:40:48 *DEBUG* FilterMultiColumnQuery:
[0123cda7-d0f6-4c35-87d2-d48402e8566e(70)]
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
0123cda7-d0f6-4c35-87d2-d48402e8566e
27.10.2010 11:40:48 *DEBUG* ItemManager: caching item
0123cda7-d0f6-4c35-87d2-d48402e8566e/{http://www.csi.com}oid
27.10.2010 11:40:48 *DEBUG* FilterMultiColumnQuery:
[9a4d00a1-edce-4910-bac5-8921861597f9(75)]
27.10.2010 11:40:49 *DEBUG* ItemManager: caching item
9a4d00a1-edce-4910-bac5-8921861597f9
27.10.2010 11:40:49 *DEBUG* CacheManager: resizeAll size=8
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@17044c5 now:131072
used:0 access:0 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@17c96a9 now:131072
used:0 access:0 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@17f11fb now:131072
used:1328 access:0 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@1295fe8 now:131072
used:2892 access:0 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@19f9d2 now:15859712
used:4280326 access:127 new:4194304
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@658bbe now:131072
used:105186 access:84 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@b9726e now:131072
used:1328 access:0 new:131072
27.10.2010 11:40:49 *DEBUG* CacheManager:
org.apache.jackrabbit.core.state.MLRUItemStateCache@4f71a3 now:131072
used:2528 access:0 new:131072
...
...


My query is:
SELECT * FROM [csi:file] WHERE [csi:oid] = 'WFC.e1.5032907' AND
ISDESCENDANTNODE('/WFC/e1/01-05-2010/5032907')

"query.execute()" returns in 1,279 sec (over 21 min).
also 
"result.getNodes()" takes about the same amount of time.


Following is the log that I thought was related to QueryImpl and
QueryResultImpl:

27.10.2010 11:40:45 *DEBUG* RepositoryImpl: User adminId logged in to
workspace default
27.10.2010 11:40:45 *DEBUG* QueryResultImpl: getResults(2147483647) limit=-1
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* TermDocsCache: #3
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 11:40:45 *DEBUG* FilterMultiColumnQuery:
[{http://www.centerprise.com}file]
27.10.2010 11:40:45 *DEBUG* QueryResultImpl: query executed in 31 ms (35)
...
...
...
27.10.2010 12:02:04 *DEBUG* QueryResultImpl: retrieved ScoreNodes in 1278963
ms (6391)
27.10.2010 12:02:04 *DEBUG* QueryImpl: executed in 1,278.99 s. (SELECT
[csi:file].* FROM [csi:file] WHERE [csi:file].[csi:oid] = 'WFC.e1.5032907'
AND ISDESCENDANTNODE([csi:file], [/WFC/e1/01-05-2010/5032907]))
27.10.2010 12:02:04 *DEBUG* QueryResultImpl: getResults(2) limit=-1
...
...
...
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* TermDocsCache: #4
TermDocs(_:PROPERTIES,3:primaryType[11:file)
27.10.2010 12:02:04 *DEBUG* FilterMultiColumnQuery:
[{http://www.centerprise.com}file]
27.10.2010 12:02:04 *DEBUG* QueryResultImpl: query executed in 31 ms (0)
27.10.2010 12:26:33 *DEBUG* QueryResultImpl: retrieved ScoreNodes in 438564
ms (6391)

I am using Oracle persistance manager and my search config looks like this:

In repository.xml:

<SearchIndex class="org.apache.jackrabbit.core.query.lucene.SearchIndex">
with params:
param name="path" value="${rep.home}/repository/index"
param name="supportHighlighting" value="true"

In workspace.xml:

<SearchIndex class="org.apache.jackrabbit.core.query.lucene.SearchIndex">
with params:
param name="path" value="${wsp.home}/index"
param name="supportHighlighting" value="true"

PS: search is fine when there are just a few documents loaded in repository. 

Please help.

Thanks.
-- 
View this message in context: http://jackrabbit.510166.n4.nabble.com/query-execute-and-result-getNodes-taking-over-20-min-each-tp3015942p3015942.html
Sent from the Jackrabbit - Dev mailing list archive at Nabble.com.

Mime
View raw message