Exist: execution time have increased a lot between eXist-db 2.2 and 4.3.1

[algrw]

We use eXist-db from our Hava application with the XMLDB APIs and we have a lot of XQueries using the XSLT transformation and the XSLT fn:doc function

I am trying to migrate from eXist-db 2.2 to 4.3.1 and I have a huge difference of execution time between these 2 versions.

What is the problem

I am running a query using an XSLT resource to transform an XML document. The XSLT document uses the fn:doc function to get information on another XML file with an index:

<xsl:variable name="indexLig"select="doc($indexFileUri)"/>).

• With eXist-db 2.2, the execution took 2 secs (or 20 secs with a larger XML document).
• With eXist-db 4.3.1, the execution took 2 mins (or 40 mins with the same larger XML document)

When running the query with the 4.3.1 version, there are a lot of warning throwing by SanityCheck (AssertFailure: TRACE: Node 0 not found) in the exist log.

I tried with eXist-db 5.0.0.RC2 and I have the same issue.

When I use an in-memory variable in the XSLT document:

<xsl:variable name="indexLig">
    <xsl:copy-of select="doc($indexFileUri)"/>
</xsl:variable>,

the execution took less than 2 secs with the larger document

Attached are the logs I got with eXist-db 2.2 and with eXist-db 4.3.1

What did you expect

When running the query, the execution should take more or less the same amount of time between these versions. I can understand that my index can be wrong or my XSLT document can be optimized but it seems to me there is an issue with the doc function

Describe how to reproduce or add a test

Upload the content of the XQUERY zip file in the collection /db/agd/bilano. The /db/agd/bilano/index collection can then be indexed (with the /db/agd/bilano/index/idxDeclTxt.conf document)

Run the bilano.xqy with eXide.

To use the larger document, you can modify in the query the variable $bilanoFileName to 'bilano.xml', instead of 'bilano_small.xml'

Context information

• eXist-db version + Git Revision hash : eXist-db 4.3.1 / 3b19579
• Java version : Java 1.8.0_121
• Operating system : Windows Server 2008 R2
• 32 or 64 bit : 64 bits
• How is eXist-db installed? with the JAR installer
• Any custom changes : no change in conf.xml

exist-db 2.2_logs.zip
exist-db-4.3.1_logs.zip
xquery.zip

[dizzzz]

maybe related to https://github.com/eXist-db/exist/issues/2096

please could you check (1) the database memory settings (2) if the virus scanner influences the overall speed (3) the performance of your disk

[algrw]

I have 2560Mb in the wrapper conf file (collection cache 384Mo). I wasn't able to deactivate the virus scanner as it is group maintained but I have never had any issues with it, either with eXist-db 2.2 or with other applications.
The server has 8Gb memory (2.5Gb free with eXist-db started)

I installed eXist-db 4.3.1 on my computer, with the same characteristics and I have the same issue

[dizzzz]

Ok thnx for confirming. Since v2.2 a lot of IO things have changed 'under the hood', and we use Saxon these days for XSLT etc etc.

[duncdrum]

@algrw just a long shot, but are you using old range indexes in2.2 what about 4.3.1 have you converted them to new-range, still the old?

[dizzzz]

Checking the zip file.... please could you follow the documentation and rename the collection config file to have it end with .xconf iso .conf , store it in the correct location (!) , reminded and retry?

I’d recommend to follow the naming conventions a it more, eg have query files end with “xq”....

[algrw]

Sorry, the file wasn't named correctly within the zip file. The collection config file end with .xconf and the index can be seen with monex/indexes

[dizzzz]

if data is not carefully provided, we really cannot provide support :-( and it costs too much time :-(
please be aware of that.

[dizzzz]

did you check with the profiler what is happening?

please provide a complete bundle of correct information (=zip file), a description is just not sufficient, the current ZIP file is not usable.

probably the best option is to create with eXide a XAR file project containing all files, and attach it to this ticket.

[algrw]

@dizzzz Thanks for your reply . And I understand very well that the information should be correctly provided. Sorry about that.

Attached is the XAR file. As it is the first one I do (we use xmldb to access the eXist-db database from our java application), please tell me if something is wrong and I will provide you zip files instead.

After installing it, it should create the agdResult application.
I run it either with the url : ..../exist/apps/agdResult/xqueries/bilano.xq or with eXide
The result will be the name of the output file generated by the query (i.e.
<result>/db/apps/agdResult/resources/result.xml</result>)

The file used by the xsl document for the doc function ("/db/apps/agdResult/index/idxDeclTxt.xml") is indexed and I can see the index nodes with monex/indexes. The xconf file is in the collection "/db/apps/agdResult/index" (but it is also in the collection "/db/system/config/db/apps/agdResult/index")

I tried to check the query with the profiler but I didn't see any index usage for my query. I can see the "bilano.xq" query and the time for the "transform:transform" function (or the xmldb:store one) but that's all. I don't know if it is because the index file is wrong or because I don't know how to use the profiler

I also created a query using a search on the document similar to the search done in the xsl - "..../exist/apps/agdResult/xqueries/bilano_noXsl.xq" :

with the query:

let $indexLig := doc($indexFileUri)
let $id := $indexLig//idx[(@LD cast as xs:integer) le $nl and (@LF cast as xs:integer) ge $nl]/@BL

with xsl:

<xsl:variable name="indexLig" select="doc($indexFileUri)"/>
<xsl:variable name="idb" select="$indexLig//idx[(@LD cast as xs:integer) le $noLig and (@LF cast as xs:integer) ge $noLig]"/>

and even if I don't see the index used by the query with the profiler, the execution is much faster (0.15s instead of 24s).

agdResult-0.1.zip

[algrw]

Just a little more information. When I run the query ..../exist/apps/agdResult/xqueries/bilano_noXsl.xq, I don't have the warning (Node 0 not found) in the exist log.

[adamretter]

I compared how Saxon retrieves nodes in eXist-db 2.2 (Saxon-HE 9.4.0-7) and eXist-db 5.0.0-RC2 (Saxon-HE 9.8.0-12).

When looking up a following-sibling node the calls that Saxon makes on the eXist-db DOM implementation looks something like this:

eXist-db 2.2 (Saxon HE 9.4.0-7)

1. Document.hasChildNodes() == true
2. Document.hasChildNodes() == true
3. Document.getChildNodes() == []
4. NodeListImpl.getLength() == 1 e.g. [].getLength == 1
5. NodeListImpl.item(0) == e.g. [].item(0) ==
6. ElementImpl.hasChildNodes() == false e.g. .hasChildNodes() == false

eXist-db 5.0.0-RC2 (Saxon HE 9.8.0-12)

1. DocumentImpl.hasChildNodes() == true
2. DocumentImpl.getFirstChild() ==
3. ElementImpl.hasChildNodes() == false e.g. .hasChildNodes() == false
4. ElementImpl.isSameNode(DocumentImpl) == false e.g. .isSameNode(doc) == false
5. ElementImpl.getNextSibling() == null e.g. .getNextSibling() == null

As you can see in eXist-db 2.2 getChildNodes is used by Saxon, whereas in eXist-db 5.0.0-RC2, getNextSibling is used by Saxon.

There are two issues with getNextSibling in eXist-db that cause problems, which I have fixes for and will send soon:

1. When getNextSibling reaches the end of the document (which it should) it causes a SanityCheck error to be raised. We should not raise a Sanity Check error here.

2. getNextSibling and getPreviousSibling have quite some bugs, which I think I have resolved here and hope to merge shortly.

It was interesting to run eXist-db 2.2 again, the thing that really surprised me was how quickly it started up. We should try and figure out why 4.3.1 and later are so slow at starting compared to 2.2...

I think if you can wait for my upcoming PR (Pull Request) and re-test it might be interesting to see if that helps with your performance issue. If not, we should dig further into this...

[algrw]

@adamretter Thanks a lot. I will wait for your PR and re-test it

[adamretter]

@algrw Okay my PR which might help with this is here - https://github.com/eXist-db/exist/pull/2113 please can you test?

[algrw]

@adamretter Sorry but I don't know how to add this fix to my eXist-db installation. Can you tell me how to do it or prepare a patch for me?

Thanks

[joewiz]

@algrw While there are decent command-line methods of checking out a PR, my preferred way is to use the free GitHub Desktop client, pointing it to the directory where you've cloned eXist, and then navigating to the Branches list > Pull Requests:

Just click on the PR you'd like to check out, and GitHub does the necessary work of checking out the PR's branch for you. Then rebuild eXist and test.

[algrw]

@joewiz Thanks, I was able to pull the PR on the develop branch

@adamretter There is no more warning "node 0 not found" in the exist log. But when I run my application this morning after pulling the PR, I got an error "GC overhead limit exceeded" (see logs attached).
I tried to reproduce the error but when I run the application, the wrapper re-started the database because of the ping timeout.
I modified the timeout (wrapper.ping.timeout = 600) but now, when I run the application, the database hangs with no errors in the logs, the dashboard isn't accessible any more and the UC used is around 100%.

logs_dev.zip

[duncdrum]

@algrw you can try switching to a difference garbage collecting mechanism by passing JAVA_TOOL_OPTIONS to exist at start time: -XX:+UseG1GC -XX:+UseStringDeduplication. We're doing this for the docker images and it made quite a difference in my experience.

[dizzzz]

@duncdrum the GC option is switched on by default for java8uXX no?

[duncdrum]

@dizzzz i m not sure i think it also depends on the patch version, but its easy to see if G1GC is used or not.

[adamretter]

@algrw If the GC1G option suggested doesn't help. Then it seems like we have another issue in 5.0.0 perhaps. I will also send a PR for 4.3.1 shortly, so you could test that, which should rule out any differences in 5.0.0.

[algrw]

@adamretter I added the GC1G option and I had the same issue (java heap space). Attached are the logs files.
logs java heap space.zip

[adamretter]

@algrw okay thanks. For the moment you might like to test against 4.3.1+ then. I have opened a PR for that version now too: https://github.com/eXist-db/exist/pull/2115

[duncdrum]

@algrw lots to dig into here, just to get a better sense of the scale of the problem, what are your memory settings in 2.2 that were able to run this?

[algrw]

@duncdrum For the initial test, there was 2560M as max memory on the wrapper.conf file for the eXist-db 2.2. Both tests were running on the same server. And I run it on my computer with 1024M as mas memory

[algrw]

@adamretter I tested it against 4.x.x with your PR. No more warning "node 0 not found" in the exist log. The application was able to run without memory errors. The execution time is better (around 15s with the small XML) so better than in 4.3.1 but much longer than in 2.2 (around 0.3s).

[adamretter]

@algrw Okay I will take a look and see if I can reproduce the performance regression...