blob: 9c0f84740418efb9c03cc5d959be8a157190b386 [file] [log] [blame]
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to You under the Apache License, Version 2.0
* (the "License"); you may not use this file except in compliance with
* the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package org.apache.solr.update;
import static java.util.concurrent.TimeUnit.MILLISECONDS;
import static java.util.concurrent.TimeUnit.NANOSECONDS;
import static org.junit.Assert.assertEquals;
import java.lang.invoke.MethodHandles;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.TimeUnit;
import org.apache.lucene.util.Constants;
import org.apache.lucene.util.LuceneTestCase.Slow;
import org.apache.solr.common.util.NamedList;
import org.apache.solr.core.SolrCore;
import org.apache.solr.core.SolrEventListener;
import org.apache.solr.search.SolrIndexSearcher;
import org.apache.solr.SolrTestCaseJ4;
import org.apache.solr.util.TestHarness;
import org.junit.Before;
import org.junit.BeforeClass;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
/**
* Test auto commit functionality in a way that doesn't suck.
* <p>
* AutoCommitTest is an abomination that is way to brittle in how it
* tries to check that commits happened, and when they happened.
* The goal of this test class is to (ultimately) completely replace all
* of the functionality of that test class using:
* </p>
* <ul>
* <li>A more robust monitor of commit/newSearcher events that records
* the times of those events in a queue that can be polled.
* Multiple events in rapid succession are not lost.
* </li>
* <li>Timing checks that are forgiving of slow machines and use
* knowledge of how slow A-&gt;B was to affect the expectation of
* how slow B-&gt;C will be
* </li>
* </ul>
*/
@Slow
public class SoftAutoCommitTest extends SolrTestCaseJ4 {
private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
@BeforeClass
public static void beforeClass() throws Exception {
initCore("solrconfig.xml", "schema.xml");
}
private MockEventListener monitor;
private DirectUpdateHandler2 updater;
@Before
public void createMonitor() throws Exception {
assumeFalse("This test is not working on Windows (or maybe machines with only 2 CPUs)",
Constants.WINDOWS);
SolrCore core = h.getCore();
updater = (DirectUpdateHandler2) core.getUpdateHandler();
updater.setCommitWithinSoftCommit(true); // foce to default, let tests change as needed
monitor = new MockEventListener();
core.registerNewSearcherListener(monitor);
updater.registerSoftCommitCallback(monitor);
updater.registerCommitCallback(monitor);
// isolate searcher getting ready from this test
monitor.searcher.poll(5000, MILLISECONDS);
}
@Override
public void setUp() throws Exception {
super.setUp();
}
public void testSoftAndHardCommitMaxDocs() throws Exception {
// NOTE WHEN READING THIS TEST...
// The maxDocs settings on the CommitTrackers are the "upper bound"
// of how many docs can be added with out doing a commit.
// That means they are one less then the actual number of docs that will trigger a commit.
final int softCommitMaxDocs = 5;
final int hardCommitMaxDocs = 7;
assert softCommitMaxDocs < hardCommitMaxDocs; // remainder of test designed with these assumptions
CommitTracker hardTracker = updater.commitTracker;
CommitTracker softTracker = updater.softCommitTracker;
// wait out any leaked commits
monitor.hard.poll(3000, MILLISECONDS);
monitor.soft.poll(0, MILLISECONDS);
monitor.clear();
softTracker.setDocsUpperBound(softCommitMaxDocs);
softTracker.setTimeUpperBound(-1);
hardTracker.setDocsUpperBound(hardCommitMaxDocs);
hardTracker.setTimeUpperBound(-1);
// simplify whats going on by only having soft auto commits trigger new searchers
hardTracker.setOpenSearcher(false);
// Note: doc id counting starts at 0, see comment at start of test regarding "upper bound"
// add num docs up to the soft commit upper bound
for (int i = 0; i < softCommitMaxDocs; i++) {
assertU(adoc("id", ""+(8000 + i), "subject", "testMaxDocs"));
}
// the first soft commit we see must be after this.
final long minSoftCommitNanos = System.nanoTime();
// now add the doc that will trigger the soft commit,
// as well as additional docs up to the hard commit upper bound
for (int i = softCommitMaxDocs; i < hardCommitMaxDocs; i++) {
assertU(adoc("id", ""+(8000 + i), "subject", "testMaxDocs"));
}
// the first hard commit we see must be after this.
final long minHardCommitNanos = System.nanoTime();
// a final doc to trigger the hard commit
assertU(adoc("id", ""+(8000 + hardCommitMaxDocs), "subject", "testMaxDocs"));
// now poll our monitors for the timestamps on the first commits
final Long firstSoftNanos = monitor.soft.poll(5000, MILLISECONDS);
final Long firstHardNanos = monitor.hard.poll(5000, MILLISECONDS);
assertNotNull("didn't get a single softCommit after adding the max docs", firstSoftNanos);
assertNotNull("didn't get a single hardCommit after adding the max docs", firstHardNanos);
assertTrue("softCommit @ " + firstSoftNanos + "ns is before the maxDocs should have triggered it @ " +
minSoftCommitNanos + "ns",
minSoftCommitNanos < firstSoftNanos);
assertTrue("hardCommit @ " + firstHardNanos + "ns is before the maxDocs should have triggered it @ " +
minHardCommitNanos + "ns",
minHardCommitNanos < firstHardNanos);
// wait a bit, w/o other action we shouldn't see any new hard/soft commits
assertNull("Got a hard commit we weren't expecting",
monitor.hard.poll(1000, MILLISECONDS));
assertNull("Got a soft commit we weren't expecting",
monitor.soft.poll(0, MILLISECONDS));
monitor.assertSaneOffers();
monitor.clear();
}
public void testSoftAndHardCommitMaxTimeMixedAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeMixedAdds(CommitWithinType.NONE);
}
public void testSoftCommitWithinAndHardCommitMaxTimeMixedAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeMixedAdds(CommitWithinType.SOFT);
}
public void testHardCommitWithinAndSoftCommitMaxTimeMixedAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeMixedAdds(CommitWithinType.HARD);
}
private void doTestSoftAndHardCommitMaxTimeMixedAdds(final CommitWithinType commitWithinType)
throws Exception {
final int softCommitWaitMillis = 500;
final int hardCommitWaitMillis = 1200;
final int commitWithin = commitWithinType.useValue(softCommitWaitMillis, hardCommitWaitMillis);
CommitTracker hardTracker = updater.commitTracker;
CommitTracker softTracker = updater.softCommitTracker;
updater.setCommitWithinSoftCommit(commitWithinType.equals(CommitWithinType.SOFT));
// wait out any leaked commits
monitor.soft.poll(softCommitWaitMillis * 2, MILLISECONDS);
monitor.hard.poll(hardCommitWaitMillis * 2, MILLISECONDS);
int startingHardCommits = hardTracker.getCommitCount();
int startingSoftCommits = softTracker.getCommitCount();
softTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.SOFT) ? -1 : softCommitWaitMillis);
softTracker.setDocsUpperBound(-1);
hardTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.HARD) ? -1 : hardCommitWaitMillis);
hardTracker.setDocsUpperBound(-1);
// simplify whats going on by only having soft auto commits trigger new searchers
hardTracker.setOpenSearcher(false);
// Add a single document
long add529 = System.nanoTime();
assertU(adoc(commitWithin, "id", "529", "subject", "the doc we care about in this test"));
monitor.assertSaneOffers();
// Wait for the soft commit with some fudge
Long soft529 = monitor.soft.poll(softCommitWaitMillis * 5, MILLISECONDS);
assertNotNull("soft529 wasn't fast enough", soft529);
monitor.assertSaneOffers();
// wait for the hard commit
Long hard529 = monitor.hard.poll(hardCommitWaitMillis * 5, MILLISECONDS);
assertNotNull("hard529 wasn't fast enough", hard529);
// check for the searcher, should have happened right after soft commit
Long searcher529 = monitor.searcher.poll(5000, MILLISECONDS);
assertNotNull("searcher529 wasn't fast enough", searcher529);
monitor.assertSaneOffers();
// toss in another doc, shouldn't affect first hard commit time we poll
assertU(adoc(commitWithin, "id", "530", "subject", "just for noise/activity"));
monitor.assertSaneOffers();
final long soft529Ms = TimeUnit.MILLISECONDS.convert(soft529 - add529, TimeUnit.NANOSECONDS);
assertTrue("soft529 occurred too fast, in " +
soft529Ms + "ms, less than soft commit interval " + softCommitWaitMillis,
soft529Ms >= softCommitWaitMillis);
final long hard529Ms = TimeUnit.MILLISECONDS.convert(hard529 - add529, TimeUnit.NANOSECONDS);
assertTrue("hard529 occurred too fast, in " +
hard529Ms + "ms, less than hard commit interval " + hardCommitWaitMillis,
hard529Ms >= hardCommitWaitMillis);
// however slow the machine was to do the soft commit compared to expected,
// assume newSearcher had some magnitude of that much overhead as well
long slowTestFudge = Math.max(300, 12 * (soft529Ms - softCommitWaitMillis));
final long softCommitToSearcherOpenMs = TimeUnit.MILLISECONDS.convert(searcher529 - soft529, TimeUnit.NANOSECONDS);
assertTrue("searcher529 wasn't soon enough after soft529: Took " +
softCommitToSearcherOpenMs + "ms, >= acceptable " + slowTestFudge + "ms (fudge)",
softCommitToSearcherOpenMs < slowTestFudge);
assertTrue("hard529 was before searcher529: " +
searcher529 + " !<= " + hard529,
searcher529 <= hard529);
monitor.assertSaneOffers();
// there may have been (or will be) a second hard commit for 530
Long hard530 = monitor.hard.poll(hardCommitWaitMillis * 5, MILLISECONDS);
assertEquals("Tracker reports too many hard commits",
(null == hard530 ? 1 : 2),
hardTracker.getCommitCount() - startingHardCommits);
// there may have been a second soft commit for 530,
// but if so it must have already happend
Long soft530 = monitor.soft.poll(0, MILLISECONDS);
if (null != soft530) {
assertEquals("Tracker reports too many soft commits",
2, softTracker.getCommitCount() - startingSoftCommits);
if (null != hard530) {
assertTrue("soft530 after hard530: " +
soft530 + " !<= " + hard530,
soft530 <= hard530);
} else {
assertTrue("soft530 after hard529 but no hard530: " +
soft530 + " !<= " + hard529,
soft530 <= hard529);
}
} else {
assertEquals("Tracker reports too many soft commits",
1, softTracker.getCommitCount() - startingSoftCommits);
}
if (null != soft530 || null != hard530) {
assertNotNull("at least one extra commit for 530, but no searcher",
monitor.searcher.poll(0, MILLISECONDS));
}
// clear commits
monitor.hard.clear();
monitor.soft.clear();
// wait a bit, w/o other action we shouldn't see any
// new hard/soft commits
assertNull("Got a hard commit we weren't expecting",
monitor.hard.poll(1000, MILLISECONDS));
assertNull("Got a soft commit we weren't expecting",
monitor.soft.poll(0, MILLISECONDS));
monitor.assertSaneOffers();
monitor.searcher.clear();
}
public void testSoftAndHardCommitMaxTimeDelete() throws Exception {
doTestSoftAndHardCommitMaxTimeDelete(CommitWithinType.NONE);
}
public void testSoftCommitWithinAndHardCommitMaxTimeDelete() throws Exception {
doTestSoftAndHardCommitMaxTimeDelete(CommitWithinType.SOFT);
}
public void testHardCommitWithinAndSoftCommitMaxTimeDelete() throws Exception {
doTestSoftAndHardCommitMaxTimeDelete(CommitWithinType.HARD);
}
private void doTestSoftAndHardCommitMaxTimeDelete(final CommitWithinType commitWithinType)
throws Exception {
final int softCommitWaitMillis = 500;
final int hardCommitWaitMillis = 1200;
final int commitWithin = commitWithinType.useValue(softCommitWaitMillis, hardCommitWaitMillis);
CommitTracker hardTracker = updater.commitTracker;
CommitTracker softTracker = updater.softCommitTracker;
updater.setCommitWithinSoftCommit(commitWithinType.equals(CommitWithinType.SOFT));
int startingHardCommits = hardTracker.getCommitCount();
int startingSoftCommits = softTracker.getCommitCount();
softTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.SOFT) ? -1 : softCommitWaitMillis);
softTracker.setDocsUpperBound(-1);
hardTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.HARD) ? -1 : hardCommitWaitMillis);
hardTracker.setDocsUpperBound(-1);
// we don't want to overlap soft and hard opening searchers - this now blocks commits and we
// are looking for prompt timings
hardTracker.setOpenSearcher(false);
// add a doc and force a commit
assertU(adoc(commitWithin, "id", "529", "subject", "the doc we care about in this test"));
assertU(commit());
Long soft529;
Long hard529;
monitor.clear();
// Delete the document
long del529 = System.nanoTime();
assertU( delI("529", "commitWithin", ""+commitWithin));
monitor.assertSaneOffers();
// Wait for the soft commit with some fudge
soft529 = monitor.soft.poll(softCommitWaitMillis * 5, MILLISECONDS);
assertNotNull("soft529 wasn't fast enough", soft529);
monitor.assertSaneOffers();
// check for the searcher, should have happened right after soft commit
Long searcher529 = monitor.searcher.poll(softCommitWaitMillis, MILLISECONDS);
assertNotNull("searcher529 wasn't fast enough", searcher529);
monitor.assertSaneOffers();
// toss in another doc, shouldn't affect first hard commit time we poll
assertU(adoc(commitWithin, "id", "550", "subject", "just for noise/activity"));
// wait for the hard commit
hard529 = monitor.hard.poll(hardCommitWaitMillis * 5, MILLISECONDS);
assertNotNull("hard529 wasn't fast enough", hard529);
monitor.assertSaneOffers();
final long soft529Ms = TimeUnit.MILLISECONDS.convert(soft529 - del529, TimeUnit.NANOSECONDS);
assertTrue("soft529 occurred too fast, in " + soft529Ms +
"ms, less than soft commit interval " + softCommitWaitMillis,
soft529Ms >= softCommitWaitMillis);
final long hard529Ms = TimeUnit.MILLISECONDS.convert(hard529 - del529, TimeUnit.NANOSECONDS);
assertTrue("hard529 occurred too fast, in " +
hard529Ms + "ms, less than hard commit interval " + hardCommitWaitMillis,
hard529Ms >= hardCommitWaitMillis);
// however slow the machine was to do the soft commit compared to expected,
// assume newSearcher had some magnitude of that much overhead as well
long slowTestFudge = Math.max(300, 12 * (soft529Ms - softCommitWaitMillis));
final long softCommitToSearcherOpenMs = TimeUnit.MILLISECONDS.convert(searcher529 - soft529, TimeUnit.NANOSECONDS);
assertTrue("searcher529 wasn't soon enough after soft529: Took " +
softCommitToSearcherOpenMs + "ms, >= acceptable " + slowTestFudge + "ms (fudge)",
softCommitToSearcherOpenMs < slowTestFudge);
assertTrue("hard529 was before searcher529: " +
searcher529 + " !<= " + hard529,
searcher529 <= hard529);
// ensure we wait for the last searcher we triggered with 550
monitor.searcher.poll(5000, MILLISECONDS);
// ensure we wait for the commits on 550
monitor.hard.poll(5000, MILLISECONDS);
monitor.soft.poll(5000, MILLISECONDS);
// clear commits
monitor.hard.clear();
monitor.soft.clear();
// wait a bit, w/o other action we shouldn't see any
// new hard/soft commits
assertNull("Got a hard commit we weren't expecting",
monitor.hard.poll(1000, MILLISECONDS));
assertNull("Got a soft commit we weren't expecting",
monitor.soft.poll(0, MILLISECONDS));
monitor.assertSaneOffers();
monitor.searcher.clear();
}
public void testSoftAndHardCommitMaxTimeRapidAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeRapidAdds(CommitWithinType.NONE);
}
public void testSoftCommitWithinAndHardCommitMaxTimeRapidAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeRapidAdds(CommitWithinType.SOFT);
}
public void testHardCommitWithinAndSoftCommitMaxTimeRapidAdds() throws Exception {
doTestSoftAndHardCommitMaxTimeRapidAdds(CommitWithinType.HARD);
}
public void doTestSoftAndHardCommitMaxTimeRapidAdds(final CommitWithinType commitWithinType)
throws Exception {
final int softCommitWaitMillis = 500;
final int hardCommitWaitMillis = 1200;
final int commitWithin = commitWithinType.useValue(softCommitWaitMillis, hardCommitWaitMillis);
CommitTracker hardTracker = updater.commitTracker;
CommitTracker softTracker = updater.softCommitTracker;
updater.setCommitWithinSoftCommit(commitWithinType.equals(CommitWithinType.SOFT));
softTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.SOFT) ? -1 : softCommitWaitMillis);
softTracker.setDocsUpperBound(-1);
hardTracker.setTimeUpperBound(commitWithinType.equals(CommitWithinType.HARD) ? -1 : hardCommitWaitMillis);
hardTracker.setDocsUpperBound(-1);
// we don't want to overlap soft and hard opening searchers - this now blocks commits and we
// are looking for prompt timings
hardTracker.setOpenSearcher(false);
// try to add 5 docs really fast
final long preFirstNanos = System.nanoTime();
for( int i=0;i<5; i++ ) {
assertU(adoc(commitWithin, "id", ""+500 + i, "subject", "five fast docs"));
}
final long postLastNanos = System.nanoTime();
monitor.assertSaneOffers();
final long maxTimeMillis = MILLISECONDS.convert(postLastNanos - preFirstNanos, NANOSECONDS);
log.info("maxTimeMillis: {}ns - {}ns == {}ms", postLastNanos, preFirstNanos, maxTimeMillis);
// NOTE: explicitly using truncated division of longs to round down
// even if evenly divisible, need +1 to account for possible "last" commit triggered by "last" doc
final long maxExpectedSoft = 1L + (maxTimeMillis / softCommitWaitMillis);
final long maxExpectedHard = 1L + (maxTimeMillis / hardCommitWaitMillis);
log.info("maxExpectedSoft={}", maxExpectedSoft);
log.info("maxExpectedHard={}", maxExpectedHard);
// do a loop pool over each monitor queue, asserting that:
// - we get at least one commit
// - we don't get more then the max possible commits expected
// - any commit we do get doesn't happen "too fast" relative the previous commit
// (or first doc added for the first commit)
monitor.assertSaneOffers();
assertRapidMultiCommitQueues("softCommit", preFirstNanos, softCommitWaitMillis,
maxExpectedSoft, monitor.soft);
monitor.assertSaneOffers();
assertRapidMultiCommitQueues("hardCommit", preFirstNanos, hardCommitWaitMillis,
maxExpectedHard, monitor.hard);
// now wait a bit...
// w/o other action we shouldn't see any additional hard/soft commits
assertNull("Got a hard commit we weren't expecting",
monitor.hard.poll(1000, MILLISECONDS));
assertNull("Got a soft commit we weren't expecting",
monitor.soft.poll(0, MILLISECONDS));
monitor.assertSaneOffers();
}
/**
* Helper method
* @see #testSoftAndHardCommitMaxTimeRapidAdds
*/
private static void assertRapidMultiCommitQueues
(final String debug, final long startTimestampNanos, final long commitWaitMillis,
final long maxNumCommits, final BlockingQueue<Long> queue) throws InterruptedException {
assert 0 < maxNumCommits;
// do all our math/comparisons in Nanos...
final long commitWaitNanos = NANOSECONDS.convert(commitWaitMillis, MILLISECONDS);
// these will be modified in each iteration of our assertion loop
long prevTimestampNanos = startTimestampNanos;
int count = 1;
Long commitNanos = queue.poll(commitWaitMillis * 6, MILLISECONDS);
assertNotNull(debug + ": did not find a single commit", commitNanos);
while (null != commitNanos) {
if (commitNanos < prevTimestampNanos + commitWaitMillis) {
fail(debug + ": commit#" + count + " has TS too low relative to previous TS & commitWait: " +
"commitNanos=" + commitNanos + ", prevTimestampNanos=" + prevTimestampNanos +
", commitWaitMillis=" + commitWaitMillis);
}
if (maxNumCommits < count) {
fail(debug + ": commit#" + count + " w/ commitNanos=" + commitNanos +
", but maxNumCommits=" +maxNumCommits);
}
prevTimestampNanos = commitNanos;
count++;
commitNanos = queue.poll(commitWaitMillis * 3, MILLISECONDS);
}
}
/** enum for indicating if a test should use commitWithin, and if so what type: hard or soft */
private static enum CommitWithinType {
NONE {
@Override public int useValue(final int softCommitWaitMillis, final int hardCommitWaitMillis) {
return -1;
}
},
SOFT {
@Override public int useValue(final int softCommitWaitMillis, final int hardCommitWaitMillis) {
return softCommitWaitMillis;
}
},
HARD {
@Override public int useValue(final int softCommitWaitMillis, final int hardCommitWaitMillis) {
return hardCommitWaitMillis;
}
};
public abstract int useValue(final int softCommitWaitMillis, final int hardCommitWaitMillis);
}
public String delI(String id, String... args) {
return TestHarness.deleteById(id, args);
}
public String adoc(int commitWithin, String... fieldsAndValues) {
XmlDoc d = doc(fieldsAndValues);
return add(d, "commitWithin", String.valueOf(commitWithin));
}
}
class MockEventListener implements SolrEventListener {
// use capacity bound Queues just so we're sure we don't OOM
public final BlockingQueue<Long> soft = new LinkedBlockingQueue<>(1000);
public final BlockingQueue<Long> hard = new LinkedBlockingQueue<>(1000);
public final BlockingQueue<Long> searcher = new LinkedBlockingQueue<>(1000);
// if non enpty, then at least one offer failed (queues full)
private StringBuffer fail = new StringBuffer();
public MockEventListener() { /* NOOP */ }
@Override
public void init(@SuppressWarnings({"rawtypes"})NamedList args) {}
@Override
public void newSearcher(SolrIndexSearcher newSearcher,
SolrIndexSearcher currentSearcher) {
Long now = System.nanoTime();
if (!searcher.offer(now)) fail.append(", newSearcher @ " + now);
}
@Override
public void postCommit() {
Long now = System.nanoTime();
if (!hard.offer(now)) fail.append(", hardCommit @ " + now);
}
@Override
public void postSoftCommit() {
Long now = System.nanoTime();
if (!soft.offer(now)) fail.append(", softCommit @ " + now);
}
public void clear() {
soft.clear();
hard.clear();
searcher.clear();
fail.setLength(0);
}
public void assertSaneOffers() {
assertEquals("Failure of MockEventListener" + fail.toString(),
0, fail.length());
}
}