/* * 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->B was to affect the expectation of * how slow B->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()); } }