Exist: Performance of 5.0.0-RC1 - XPath expressions

[joewiz]

What is the problem

Comparing the current stable release (4.3.0) to 5.0.0-RC1, the performance of an XPath expression like /package:expath is measurably slower in 5.0.0-RC1—by a factor of 4-5x. This performance gap persists as the database size increases.

I believe this issue contributes to the slower performance I'm seeing under 5.0.0-RC1 in real-world apps running on a database with a substantial number of documents and collections. Though there may be other factors too, I wanted to report this one, as I was able to create an easily reproducible test (see below).

I'd welcome others to report their results when running the same test query below against their fully populated databases.

What did you expect

I expected the performance of XPath expressions to be roughly the same in 5.0.0-RC1 as the current stable version (4.3.0).

Describe how to reproduce or add a test

The following test runs an XPath expression 100 times, then returns the timing information.

xquery version "3.1";

declare namespace expath="http://expath.org/ns/pkg";

let $query := "/expath:package"
let $hits := count(/expath:package)
let $iterations := 100
let $tests :=
    for $x in 1 to $iterations
    let $start-time := util:system-time()
    let $eval := util:eval($query)
    return
        map { "duration": seconds-from-duration(util:system-time() - $start-time) * 1000 }
let $total-ms := sum($tests?duration)
let $average-ms := $total-ms div $iterations
return
    map {
        "query": $query,
        "hits": $hits,
        "iterations": $iterations,
        "total-ms": $total-ms, 
        "average-ms": $average-ms,
        "exist-db-version": system:get-version() || "-" || system:get-revision()
    }

The results in 4.3.0 vs. 5.0.0-RC1, after submitting the query 10 times first after startup to allow the database to "warm up", are as follows:

[
    {
        "hits": 8,
        "query": "/expath:package",
        "total-ms": 50,
        "iterations": 100,
        "average-ms": 0.5,
        "exist-db-version": "4.3.0-3d6c60327"
    },
    {
        "hits": 8,
        "query": "/expath:package",
        "total-ms": 235,
        "iterations": 100,
        "average-ms": 2.35,
        "exist-db-version": "5.0.0-RC1-141b5c7"
    }
]

In other words, an XPath expression like /expath:package takes .5ms in 4.3.0 but 2.35ms in 5.0.0-RC1. This is with a stock system containing just the 8 built-in xars.

However, the effect gets worse the larger the number of hits. Let's populate the database with some more data:

xquery version "3.1";

declare namespace expath="http://expath.org/ns/pkg";

let $clear := if (xmldb:collection-available("/db/test")) then xmldb:remove("/db/test") else ()
let $base-col := xmldb:create-collection("/db", "test")
let $number-of-files := 10000
return
    (1 to $number-of-files) ! xmldb:store($base-col, . || ".xml", element expath:package { attribute num { . } } )

After populating the database with 10,000 documents that will be selected by the test query, the results of the original query worsen by about 10x for each, to 6.5ms for 4.3.0, but 22.32ms for 5.0.0-RC1. The performance gap remains just as wide as the number of hits increases, rather than converging—about 4-5x slower in 5.0.0-RC1.

In my testing with an hsg-project system (which contains about 30 xars, ~650MB when compressed), opening a page in a stock TEI Publisher-generated app takes about 25 seconds with 5.0.0-RC1, whereas the same page opens in a reasonable amount of time (1-2 seconds, as I recall) with 4.3.0. Starting from this startling real-world observation, I used monex's profiling tool to track down one source of the poorly performing query to the https://gitlab.existsolutions.com/tei-publisher/tei-publisher-app/blob/master/modules/lib/pages.xql#L41 - which upon further study led me to refine the test to the one reported in this issue.

Context information

• eXist-db version + Git Revision hash: 4.3.0 and 5.0.0-RC1 release (see test output above)
• Java version: 1.8.0_172
• Operating system: macOS 10.13.5
• 32 or 64 bit: 64 bit
• How eXist-db installed: DMG
• Any custom changes in e.g. conf.xml: None

[joewiz]

In the original post I mentioned "hsg-project" system:

In my testing with an hsg-project system (which contains about 30 xars, ~650MB when compressed), opening a page in a stock TEI Publisher-generated app takes about 25 seconds with 5.0.0-RC1, whereas the same page opens in a reasonable amount of time (1-2 seconds, as I recall) with 4.3.0.

Here are the actual results of the test in the original post run on the identical database contents, when running with 4.3.0 vs. 5.0.0-RC1:

[
    {
        "hits": 42,
        "query": "/expath:package",
        "total-ms": 1657,
        "iterations": 100,
        "average-ms": 16.57,
        "exist-db-version": "4.3.0-3d6c60327"
    },
    {
        "hits": 42,
        "query": "/expath:package",
        "total-ms": 21365,
        "iterations": 100,
        "average-ms": 213.65,
        "exist-db-version": "5.0.0-RC1-141b5c7"
    }
]

In other words, in this test, the performance of 5.0.0-RC1 is about 12x slower by this benchmark. Something about the test material exacerbates the problem reported in the original issue. It isn't simply about the number of <expath:package> elements in the database. Perhaps it is the total number of nodes in the database, or some other factor.

Should anyone wish to reproduce these results, here are the steps:

1. Install eXist 4.3.0 via DMG installer, renaming eXist-db.app as eXist-db-4.3.0-release.app
2. Install the following via Dashboard > Package Manager:
   
   
   
   • functx-1.0.xar
   
   
   • markdown-0.6.xar
   
   
   • shared-resources-0.7.0.xar
   
   
   • tei-pm-1.1.2.xar
   
   
   • tei-publisher-3.1.0.xar
   
   
   • tei-publisher-lib-2.3.0.xar
   
   
3. Follow instructions at https://github.com/HistoryAtState/hsg-project/wiki/setup#installing-other-dependencies, going as far as the section "Deploying all repositories to eXist".
4. Run the test query above 5 times, recording the results from the final run. Quit eXist 4.3.0.
5. Install eXist 5.0.0-RC1 via DMG installer, renaming eXist-db.app as eXist-db-5.0.0-RC1.app.
6. Run the test query above 5 times, recording the results from the final run.

[dizzzz]

factor 12.... that is is 'open for improvement'.

I think that I saw recently that upon XAR install not necessarily the indexes are actually created/updated ; that is: I had to perform a manual re-index of the database, and I recall I even touched the .xconf files. Maybe it is related.

I assume memory settings, javaversion are all the same?

[joewiz]

Yes, memory settings (accepted defaults on startup) and java version were the same.

[joewiz]

Re: indexes, I did wonder whether indexes were a factor in the performance in my first report, but when I deleted /db/system/config/db/apps and reindexed, the test results were identical. This suggests defined indexes aren’t a factor in the performance reported here.

As for needing to reindex after installing an xar with 5.x when this was unnecessary under 4.x, I haven’t seen that myself, but definitely, if you see that again, please report it!

[dizzzz]

yes I will report.... opening the xconf and saving it again worked for me; I think after restore it was not recognized as an XML file or so.

[wolfgangmm]

From various stress tests I can confirm that current develop is up to 3 times slower on average than 4.x.x (both as of today). For example, jmeter tests on an app which should go live this week show this:

|eXist version | avg | min | max |
|-------------|-----|-----|-----|
|4.x.x | 1001 | 119 | 3181 |
|develop | 2850 | 187 | 18414 |

Tests were performed with the same settings, indexes were used as expected. All tests are read-only, running 20 threads with a ramp up period of 30s and a random pause of 0.2-2s between requests. In particular the max value is worrying. In general, performance deteriorates quickly once more than 10 threads are active. I'm happy to give you access to the app repo for testing (it will become open source anyway, but the concrete date is not my decision).

I'm also trying to create simpler jmeter tests on other core apps.

[adamretter]

@wolfgangmm @joewiz is this now fixed in RC8 by the performance improvement work that I did?

[joewiz]

@adamretter I repeated the 2 tests in my original post above using the recently released versions of eXist 4.7.1 and 5.0.0-RC8, submitting the test query 10 times to allow the system to warm up before producing the results listed below. (I'm testing on a different computer, so raw numbers are probably not comparable between last year and this year.) Here is the new set of results from today:

Query 1: From a fresh database, run /expath:package 100 times.

[
    {
        "hits": 11,
        "query": "/expath:package",
        "total-ms": 75,
        "iterations": 100,
        "average-ms": 0.75,
        "exist-db-version": "4.7.1-7094a7057"
    },
    {
        "hits": 12,
        "query": "/expath:package",
        "total-ms": 2160,
        "iterations": 100,
        "average-ms": 21.6,
        "exist-db-version": "5.0.0-RC8-244f4735c79b8e979b920d59a6699cf46bee6a61"
    }
]

Performance change from 4.x to 5.x: 28.8x slower.

Query 2: First create 10,000 <expath:package> documents, then run Query 1.

[
    {
        "hits": 10011,
        "query": "/expath:package",
        "total-ms": 772,
        "iterations": 100,
        "average-ms": 7.72,
        "exist-db-version": "4.7.1-7094a7057"
    },
    {
        "hits": 10012,
        "query": "/expath:package",
        "total-ms": 130393,
        "iterations": 100,
        "average-ms": 1303.93,
        "exist-db-version": "5.0.0-RC8-244f4735c79b8e979b920d59a6699cf46bee6a61"
    }
]

Performance change from 4.x to 5.x: 168.9x slower.

I have not yet performed any tests with TEI Publisher based apps, but seeing as the line of TEI Publisher I linked to that contains the /expath:package XPath expression has not yet changed, I would expect the effect to be the same.

This is using macOS 10.14.6, eXist official DMG app distributions downloaded directly via bintray, with Oracle JDK 1.8.0_211.

[adamretter]

@joewiz I did some profiling. When an expression like /expath:package it attempts (via RootNode.java) to READ lock all documents in the entire database, before getting a reference to them.

This is the same in 4.x.x and 5.0.0. The difference is that in 5.0.0, locking is more expensive than in 4.x.x, but should be less buggy and scale better when there are multiple users. There was a small design issue with the locking in 5.0.0 which meant that when a single thread was locking a large number of documents there was a O(n) operation to report that event, I have now reduced that to O(1) in https://github.com/adamretter/exist/commit/507542e. You can test the branch here is you like: https://github.com/adamretter/exist/commits/hotfix/lock-table-performance

I now measure the Query performance on my machine for 5.1.0-SNAPSHOT to be "total-ms": 1506. A big increase, but still not as good as 4.7.1. I need to try further to improve the lock performance.

Also I would question whether all of those documents really need to be locked at all for that operation, as the important Document fields in 5.x.x that are used by NodeProxy are immutable... but I need to talk to @wolfgangmm about this first...

[joewiz]

@adamretter Here are the results running your PR #2962 on the same machine:

Query 1 (collection size of 10): eXist 5 is 3% faster than eXist 4.7.1:

{
    "hits": 12,
    "query": "/expath:package",
    "total-ms": 73,
    "iterations": 100,
    "average-ms": 0.73,
    "exist-db-version": "5.1.0-SNAPSHOT-9e627d720fa8452a3c571df870b85a1c553e39a8"
}

Query 2 (collection size of 10,000): eXist 5 is over 2x faster than eXist 4.7.1:

{
    "hits": 10012,
    "query": "/expath:package",
    "total-ms": 355,
    "iterations": 100,
    "average-ms": 3.55,
    "exist-db-version": "5.1.0-SNAPSHOT-9e627d720fa8452a3c571df870b85a1c553e39a8"
}

Very impressive, and this is just the simple, single threaded case. Based on what Adam told us during the Community Call, multi-user multi-threaded is where we should really see eXist 5 sing over 4.

[adamretter]

Closed by https://github.com/eXist-db/exist/commit/febb068c89f20e98f4eb6711412bc13ccd60231a