You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@jackrabbit.apache.org by "kazim_ssuet@yahoo.com" <ka...@yahoo.com> on 2010/10/27 19:27:08 UTC
query.execute() and result.getNodes() taking over 20 min each
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.
Re: query.execute() and result.getNodes() taking over 20 min each
Posted by "kazim_ssuet@yahoo.com" <ka...@yahoo.com>.
Got it.
I modified query creation from
queryManager.createQuery(queryString, Query.JCR_SQL2)
to
queryManager.createQuery(queryString, Query.SQL)
and modified query from
SELECT * FROM [csi:file] WHERE [csi:oid] = 'WFC.e1.5032907' AND
ISDESCENDANTNODE('/WFC/e1/01-05-2010/5032907')
to
SELECT * FROM csi:file WHERE csi:oid = 'WFC.e1.5032907'
and now search only takes 30-40 mili sec on avg.
Thanks,
KS.
--
View this message in context: http://jackrabbit.510166.n4.nabble.com/query-execute-and-result-getNodes-taking-over-20-min-each-tp3015942p3016422.html
Sent from the Jackrabbit - Dev mailing list archive at Nabble.com.
Re: query.execute() and result.getNodes() taking over 20 min each
Posted by "kazim_ssuet@yahoo.com" <ka...@yahoo.com>.
Any suggestions, what might I be doing wrong?
If you need more information, let me know.
--
View this message in context: http://jackrabbit.510166.n4.nabble.com/query-execute-and-result-getNodes-taking-over-20-min-each-tp3015942p3016171.html
Sent from the Jackrabbit - Dev mailing list archive at Nabble.com.