Re: [Exist-open] Profiling

[Elliotte R. H. <el...@ib...>]

On Fri, Feb 5, 2010 at 7:06 AM, Wolfgang Meier <wol...@ex...> wrote:
>> I think I must have something configured wrong because I always get
>> "No Index" on all queries. Is there any way to ask eXist which indexes
>> it has calculated for which collections?
>
> I would first check the data directory to see if the range index data
> file (values.dbx) is empty or not. If it has just 8k or so, chances
> are good that your index definition is not applied at all.

values.dbx is about 250K.

Looks like exist is not finding any relevant indexes. E.g.

05 Feb 2010 07:37:29,193 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-24
05 Feb 2010 07:37:29,195 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare

The indexes are on atom:updated but it looks like it wants an index on
substring-before(atom:updated, "T") because that's the key.

I'm not sure but I suspect the query it's trying to index is this one:

let $entries :=
collection("/db/ccl/news")/atom:entry[starts-with(atom:updated,
$date)]

That's the only query that hits the date range shown in the fuiler log
below. The other queries go over a much larger range and the DB
doesn't seem to try an index at all for that:

let $dates := distinct-values(
    for $updated in collection("/db/ccl/news")/atom:entry/atom:updated
    order by $updated descending
    return substring-before($updated, 'T')
)

How are indexes used for the starts-with function? Maybe it's only
looking for full words? E.g. perhaps an index lookup for 2009-12-24
would find "2009-12-24 12:35 PM" but not find "2009-12-24T12:35:00"

This is one full hit's log:

05 Feb 2010 07:37:23,104 [P1-9] DEBUG (ConfigurationHelper.java
[getExistHome]:55) - Got eXist home from broker: /Applications/eXist
05 Feb 2010 07:37:23,105 [P1-9] INFO  (Descriptor.java [<init>]:102) -
Reading Descriptor from file /Applications/eXist/descriptor.xml
05 Feb 2010 07:37:23,359 [P1-9] INFO  (XQueryServlet.java [init]:142)
- form-encoding = UTF-8
05 Feb 2010 07:37:23,359 [P1-9] INFO  (XQueryServlet.java [init]:146)
- container-encoding = UTF-8
05 Feb 2010 07:37:23,360 [P1-9] INFO  (XQueryServlet.java [init]:150)
- encoding = UTF-8
05 Feb 2010 07:37:24,525 [P1-9] TRACE (Optimizer.java
[visitLocationStep]:98) - Rewriting expression:
child::atom:entry[child::atom:updated = $dates[1]]
05 Feb 2010 07:37:24,530 [P1-9] TRACE (Optimizer.java
[visitLocationStep]:98) - Rewriting expression:
child::atom:entry[child::atom:updated = $date]
05 Feb 2010 07:37:24,542 [P1-9] DEBUG (XQuery.java [compile]:157) -
Query diagnostics:
[skipped: more than 150 expressions]
05 Feb 2010 07:37:24,542 [P1-9] DEBUG (XQuery.java [compile]:161) -
Compilation took 768 ms
05 Feb 2010 07:37:24,640 [P1-9] DEBUG (DefaultCacheManager.java
[requestMem]:189) - Growing cache collections.dbx (a
org.exist.storage.cache.LRUCache) from 64 to 80
05 Feb 2010 07:37:26,435 [P1-9] DEBUG (DefaultCacheManager.java
[requestMem]:189) - Growing cache collections.dbx (a
org.exist.storage.cache.LRUCache) from 80 to 100
05 Feb 2010 07:37:28,868 [P1-9] TRACE (Optimize.java
[visitGeneralComparison]:219) - exist:optimize: found optimizable:
org.exist.xquery.GeneralComparison
05 Feb 2010 07:37:28,870 [P1-9] TRACE (Optimize.java [before]:240) -
exist:optimize: context step: child::atom:entry[child::atom:updated =
$dates[1]]
05 Feb 2010 07:37:28,870 [P1-9] TRACE (Optimize.java [before]:241) -
exist:optimize: context var: null
05 Feb 2010 07:37:28,871 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:29,004 [P1-9] TRACE (Optimize.java
[visitGeneralComparison]:219) - exist:optimize: found optimizable:
org.exist.xquery.GeneralComparison
05 Feb 2010 07:37:29,005 [P1-9] TRACE (Optimize.java [before]:240) -
exist:optimize: context step: child::atom:entry[child::atom:updated =
$date]
05 Feb 2010 07:37:29,023 [P1-9] TRACE (Optimize.java [before]:241) -
exist:optimize: context var: null
05 Feb 2010 07:37:29,038 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:29,193 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-24
05 Feb 2010 07:37:29,195 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:29,625 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:29,750 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-23
05 Feb 2010 07:37:29,752 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:30,098 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:30,118 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-22
05 Feb 2010 07:37:30,120 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:30,542 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:30,560 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-21
05 Feb 2010 07:37:30,561 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:30,787 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:30,816 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-18
05 Feb 2010 07:37:30,818 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:31,081 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:31,114 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-17
05 Feb 2010 07:37:31,144 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:31,486 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:31,493 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-16
05 Feb 2010 07:37:31,494 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:31,667 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:31,673 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-15
05 Feb 2010 07:37:31,673 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:31,797 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:31,802 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-14
05 Feb 2010 07:37:31,803 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:31,931 [P1-9] TRACE (Optimize.java [eval]:166) -
exist:optimize: Cannot optimize expression.
05 Feb 2010 07:37:31,937 [P1-9] TRACE (GeneralComparison.java
[quickNodeSetCompare]:726) - No suitable index found for key:
2009-12-10
05 Feb 2010 07:37:31,937 [P1-9] TRACE (GeneralComparison.java
[nodeSetCompare]:488) - No index: fall back to nodeSetCompare
05 Feb 2010 07:37:32,074 [P1-9] DEBUG (XQuery.java [execute]:231) -
Execution took 7,531 ms
05 Feb 2010 07:37:32,075 [P1-9] DEBUG (XQueryContext.java
[checkOptions]:2752) - Setting serialization property from pragma:
method = xhtml
05 Feb 2010 07:37:32,075 [P1-9] DEBUG (XQueryContext.java
[checkOptions]:2752) - Setting serialization property from pragma:
media-type = text/html
05 Feb 2010 07:37:32,079 [P1-9] DEBUG (HTTPUtils.java
[addLastModifiedHeader]:61) - mostRecentDocumentTime: 0
05 Feb 2010 07:37:32,264 [P1-4] DEBUG (TextSearchEngine.java
[<init>]:111) - using tokenizer:
org.exist.storage.analysis.SimpleTokenizer
05 Feb 2010 07:37:32,265 [P1-4] DEBUG (NativeBroker.java [<init>]:201)
- Initializing broker 256639605
05 Feb 2010 07:37:32,278 [P1-4] DEBUG
(TransformerFactoryAllocator.java [getTransformerFactory]:101) - Set
transformer factory: org.apache.xalan.processor.TransformerFactoryImpl
05 Feb 2010 07:37:32,279 [P1-4] DEBUG (BrokerPool.java
[createBroker]:1203) - created broker
'org.exist.storage.NativeBroker_exist_2 for database instance 'exist'


-- 
Elliotte Rusty Harold
el...@ib...