TestForTooMuchCloning: too many calls to IndexInput.clone during TermRangeQuery: 7

[ChrisHegarty]

Description

TestForTooMuchCloning > test FAILED
    java.lang.AssertionError: too many calls to IndexInput.clone during TermRangeQuery: 7
        at __randomizedtesting.SeedInfo.seed([3B8D209D5C693E94:B3D91F47F295536C]:0)
        at org.junit.Assert.fail(Assert.java:89)
        at org.junit.Assert.assertTrue(Assert.java:42)
        at org.apache.lucene.index.TestForTooMuchCloning.test(TestForTooMuchCloning.java:88)
        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
        at java.base/java.lang.reflect.Method.invoke(Method.java:580)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1763)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
        at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:48)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
        at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
        at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:843)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:490)
        at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
        at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
        at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at org.apache.lucene.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
        at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
        at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
        at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
        at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
        at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:850)
        at java.base/java.lang.Thread.run(Thread.java:1575)

Gradle command to reproduce

./gradlew test --tests TestForTooMuchCloning.test -Dtests.seed=3B8D209D5C693E94 -Dtests.locale=kk-KZ -Dtests.timezone=America/Indiana/Marengo -Dtests.asserts=true -Dtests.file.encoding=UTF-8

[ChrisHegarty]

git bisect tells me that this commit is the culprit #14333 . /cc @gf2121

878e23f77390058b6787e0a0537de9087d1019b3 is the first bad commit
commit 878e23f77390058b6787e0a0537de9087d1019b3
Author: Guo Feng <52390227+gf2121@users.noreply.github.com>
Date:   Mon Apr 14 23:19:04 2025 +0800

    A specialized Trie for Block Tree Index (#14380)

[rmuir]

This test is old, i think. The background IIRC is that for some Directory impls (e.g. NIOFSDirectory or others that use "buffered input"), clone() may cause at minimum a 1KB read/buffer refill. For MMapDirectory the clone() may be cheaper and so excessive cloning may go unnoticed, yet cause a performance issue for some.

[gf2121]

Thanks @ChrisHegarty for git bisect and @rmuir for the context.

(I allowed myself to edit your comment to point to the correct PR.)

I knew the new trie will clone the indexInput twice instead of FST only once so I changed the limitation from 5 to 6 per segment, while i did not expect it will clone 7 times so much. I printed out all the clone traces:

1. at org.apache.lucene.codecs.lucene103.blocktree.FieldReader.newReader(FieldReader.java:92)
2. at org.apache.lucene.codecs.lucene103.blocktree.TrieReader.(TrieReader.java:79)
3. org.apache.lucene.codecs.lucene103.blocktree.IntersectTermsEnum.(IntersectTermsEnum.java:85)
4. org.apache.lucene.codecs.lucene103.blocktree.FieldReader.newReader(FieldReader.java:92)
5. org.apache.lucene.codecs.lucene103.blocktree.TrieReader.(TrieReader.java:79)
6. at org.apache.lucene.codecs.lucene103.blocktree.SegmentTermsEnum.initIndexInput(SegmentTermsEnum.java:83)
7. org.apache.lucene.codecs.lucene103.Lucene103PostingsReader$BlockPostingsEnum.reset(Lucene103PostingsReader.java:517)

So the RangeQuery intersect with IntersectTermsEnum (3 times), then seeExact with SegmentTermsEnum (3 times), and get postings (1 times). The TrieReader is constructed twice so we cloned twice more.

[gf2121]

As the the added clones are cloning index file tip of term dictionary, which is usually opened with mmap. I raised a fix #14547 to simply increase the limit of clones per segment from 6 to 7. Feel free to beat me if we think it is too many.

[mikemccand]

+1 to bump the clone limit to 7 so the test passes again -- clone inflation!!

clone is likely super cheap for MMapDirectory? Hmm it is the JDK version specific MemorySegmentIndexInput (with SingleSegmentImpl subclass to optimize the common case ) that is actually cloned, and it's making a new class instance, setting a few members, making a shallow copy of the actual mapped segments array, and (hmm) calling .toString() on the to-be-cloned IndexInput heh (this just returns the resourceDescription member). So yeah it looks quite cheap.

Also, this clone cost (fixed, one-time cost per segment) is amortized away as the query + segment matches more and more hits. So crazy fast queries matching very few hits are a wee bit slower and still crazy fast, and slow queries matching many hits are not affected in any meaningful way ...

[dweiss]

I hit a failure on this again, after the patch:

./gradlew test -Ptests.seed=49BA5A550192C95E --tests TestForTooMuchCloning

[dweiss]

The number of clones here seems... ahem, high.

  2> Apr 30, 2025 11:04:20 AM org.apache.lucene.internal.vectorization.VectorizationProvider lookup
  2> WARNING: Vector bitsize and/or integer vectors enforcement; using default vectorization provider outside of testMode
   >     java.lang.AssertionError: too many calls to IndexInput.clone during merging: 612

[gf2121]

Thanks for reporting @dweiss , i'll reopen.

Error assert:

lucene/lucene/core/src/test/org/apache/lucene/index/TestForTooMuchCloning.java

Lines 65 to 67 in 2a5597e

	assertTrue(
	"too many calls to IndexInput.clone during merging: " + dir.getInputCloneCount(),
	dir.getInputCloneCount() < 600);

This is an assert for the count of IndexInput.clone during merge, instead of query. I find the limitation 600 comes from #14232, which looks like a "test passed after multiple reruns" magic number.