StandardQueryParser is over 100 times slower in v5 compared to v3 [LUCENE-7260]

[asfimport]

The following test code times parsing a large query.

import org.apache.lucene.analysis.KeywordAnalyzer;
//import org.apache.lucene.analysis.core.KeywordAnalyzer;
import org.apache.lucene.queryParser.standard.StandardQueryParser;
//import org.apache.lucene.queryparser.flexible.standard.StandardQueryParser;
import org.apache.lucene.search.BooleanQuery;

public class LargeQueryTest {
    public static void main(String[] args) throws Exception {
        BooleanQuery.setMaxClauseCount(50_000);
        StringBuilder builder = new StringBuilder(50_000*10);
        builder.append("id:( ");
        boolean first = true;
        for (int i = 0; i < 50_000; i++) {
            if (first) {
                first = false;
            } else {
                builder.append(" OR ");
            }
            builder.append(String.valueOf(i));
        }
        builder.append(" )");
        String queryString = builder.toString();

        StandardQueryParser parser2 = new StandardQueryParser(new KeywordAnalyzer());

        for (int i = 0; i < 10; i++) {
            long t0 = System.currentTimeMillis();
            parser2.parse(queryString, "nope");
            long t1 = System.currentTimeMillis();
            System.out.println(t1-t0);
        }
    }
}

For Lucene 3.6.2, the timings settle down to 200~300 with the fastest being 207.
For Lucene 5.4.1, the timings settle down to 20000~30000 with the fastest being 22444.

So at some point, some change made the query parser 100 times slower. I would suspect that it has something to do with how the list of children is now handled. Every time someone gets the children, it copies the list. Every time someone sets the children, it walks through to detach parent references and then reattaches them all again.

If it were me, I would probably make these collections immutable so that I didn't have to defensively copy them.

---

Migrated from LUCENE-7260 by Trejkaz, 1 vote, updated Feb 16 2017
Environment:

Java 8u51

[asfimport]

Yonik Seeley (@yonik) (migrated from JIRA)

It may be BooleanQuery construction and not the parser. Stuff like #7366 made constructing one a more heavy-weight operation.

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Do something with the result of the parsing, otherwise the result may be junk due to jvm optimizing out what it thinks is dead code. If this is indeed still the case it should be fairly easy to find by bisecting codebase between the two releases.

[asfimport]

Trejkaz (migrated from JIRA)

Well, this slowdown is also noticeable in our full application, where we are using the query for a search after doing the parsing. If it weren't, I wouldn't have even created this cut-down test. It is certainly a lot slower in the full application as well, but it's harder to produce timings for the full application and 3.6 without also accidentally including other factors.

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

But it's enough to just compute a rolling simple hash using the query object's hashCode returned from parsing and sysout it at the end (after the loop)? I don't negate the overall information, I'm just saying the numbers may be off by a significant factor.

[asfimport]

Dawid Weiss (@dweiss) (migrated from JIRA)

Also, if this is so significantly slower it should be possible to find the hotspot causing the problem with a profiler (yourkit is excellent).

[asfimport]

Robert Muir (@rmuir) (migrated from JIRA)

This also doesn't need to be fast: it returns an exception by default. You disable that safeguard, and then build a 50k term boolean query in the slowest possible way.

[asfimport]

Trejkaz (migrated from JIRA)

Is there a faster way to do it? Keeping in mind that it has to be something starting from a query string, since that's what the user originally entered who reported the issue to us.

[asfimport]

Trejkaz (migrated from JIRA)

Meanwhile I threw some hashCode() calls in on the query object, in this sort of fashion:

        int temp = 0;
        for (int i = 0; i < 10; i++)
        {
            long t0 = System.currentTimeMillis();
            Query query = parser2.parse(queryString, "nope");
            long t1 = System.currentTimeMillis();
            temp ^= query.hashCode();
            System.out.println("ignore: " + temp);
            System.out.println("dt: " + (t1-t0));
        }

I'll take the ignore lines out because it just adds noise. Both tests run faster today but it looks like someone updated the JVM we're running against, so it could be related to that. These timings are for JDK 8u92. Interesting how whatever they did in the JVM has made one of the tests 1/3 faster!

3.6:

dt: 996
dt: 659
dt: 286
dt: 393
dt: 240
dt: 257
dt: 187
dt: 529
dt: 263
dt: 183

5.4:

dt: 20213
dt: 16613
dt: 15311
dt: 14633
dt: 14925
dt: 14571
dt: 14008
dt: 16320
dt: 15211
dt: 14881

[asfimport]

Trejkaz (migrated from JIRA)

Lucene 5.5 is an additional 50% slower.

dt: 28105
dt: 27394
dt: 27947
dt: 25959
dt: 24957
dt: 27461
dt: 25734
dt: 27295
dt: 26739
dt: 28613

[asfimport]

Trejkaz (migrated from JIRA)

Lucene 6.3:

dt: 22307
dt: 21190
dt: 21004
dt: 20972
dt: 21435
dt: 21802
dt: 21487
dt: 21282
dt: 20886
dt: 21386