You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-commits@jackrabbit.apache.org by mk...@apache.org on 2019/10/31 07:04:51 UTC

svn commit: r1869201 - in /jackrabbit/oak/trunk/oak-lucene/src: main/java/org/apache/jackrabbit/oak/plugins/index/lucene/ test/java/org/apache/jackrabbit/oak/plugins/index/lucene/

Author: mkataria
Date: Thu Oct 31 07:04:51 2019
New Revision: 1869201

URL: http://svn.apache.org/viewvc?rev=1869201&view=rev
Log:
OAK-8718: LuceneIndexStatsUpdateCallback is slow and synchronous which leads to slowness

Added:
    jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java   (with props)
    jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java   (with props)
    jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java   (with props)
Modified:
    jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorProvider.java
    jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexProviderService.java
    jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexStatsUpdateCallback.java

Added: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java?rev=1869201&view=auto
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java (added)
+++ jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java Thu Oct 31 07:04:51 2019
@@ -0,0 +1,45 @@
+/*
+ * 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.jackrabbit.oak.plugins.index.lucene;
+
+public interface AsyncIndexesSizeStatsUpdate {
+
+    AsyncIndexesSizeStatsUpdate NOOP = new AsyncIndexesSizeStatsUpdate() {
+
+        @Override
+        public long getScheduleTimeInMillis() {
+            return -1;
+        }
+
+        @Override
+        public long getLastStatsUpdateTime(String indexName) {
+            return Long.MAX_VALUE;
+        }
+
+        @Override
+        public void setLastStatsUpdateTime(String indexName, long timeInMillis) {
+        }
+    };
+
+    long getScheduleTimeInMillis();
+
+    long getLastStatsUpdateTime(String indexName);
+
+    void setLastStatsUpdateTime(String indexName, long timeInMillis);
+}

Propchange: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdate.java
------------------------------------------------------------------------------
    svn:eol-style = native

Added: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java?rev=1869201&view=auto
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java (added)
+++ jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java Thu Oct 31 07:04:51 2019
@@ -0,0 +1,46 @@
+/*
+ * 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.jackrabbit.oak.plugins.index.lucene;
+
+import java.util.HashMap;
+import java.util.Map;
+
+public class AsyncIndexesSizeStatsUpdateImpl implements AsyncIndexesSizeStatsUpdate {
+
+
+    private final Map<String, Long> lastStatsUpdateTime = new HashMap<>();
+    private final long scheduleTimeInMillis;
+
+    public long getScheduleTimeInMillis() {
+        return scheduleTimeInMillis;
+    }
+
+    public AsyncIndexesSizeStatsUpdateImpl(long scheduleTimeInMillis) {
+        this.scheduleTimeInMillis = scheduleTimeInMillis;
+    }
+
+    public long getLastStatsUpdateTime(String indexName) {
+        Long lastStatsUpdateTimeInMillis = lastStatsUpdateTime.get(indexName);
+        return lastStatsUpdateTimeInMillis == null ? 0 : lastStatsUpdateTimeInMillis;
+    }
+
+    public void setLastStatsUpdateTime(String indexName, long timeInMillis) {
+        lastStatsUpdateTime.put(indexName, timeInMillis);
+    }
+}

Propchange: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexesSizeStatsUpdateImpl.java
------------------------------------------------------------------------------
    svn:eol-style = native

Modified: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorProvider.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorProvider.java?rev=1869201&r1=1869200&r2=1869201&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorProvider.java (original)
+++ jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexEditorProvider.java Thu Oct 31 07:04:51 2019
@@ -93,6 +93,7 @@ public class LuceneIndexEditorProvider i
      * is bounded
      */
     private int inMemoryDocsLimit = Integer.getInteger("oak.lucene.inMemoryDocsLimit", 500);
+    private AsyncIndexesSizeStatsUpdate asyncIndexesSizeStatsUpdate;
 
     public LuceneIndexEditorProvider() {
         this(null);
@@ -141,6 +142,11 @@ public class LuceneIndexEditorProvider i
         this.statisticsProvider = statisticsProvider;
     }
 
+    public LuceneIndexEditorProvider withAsyncIndexesSizeStatsUpdate(AsyncIndexesSizeStatsUpdate asyncIndexesSizeStatsUpdate) {
+        this.asyncIndexesSizeStatsUpdate = asyncIndexesSizeStatsUpdate;
+        return this;
+    }
+
     @Override
     public Editor getIndexEditor(
         @NotNull String type, @NotNull NodeBuilder definition, @NotNull NodeState root,
@@ -234,7 +240,11 @@ public class LuceneIndexEditorProvider i
                 callbacks.add(propertyIndexUpdateCallback);
             }
             if (mbean != null && statisticsProvider != null) {
-                callbacks.add(new LuceneIndexStatsUpdateCallback(indexPath, mbean, statisticsProvider));
+                // Below mentioned callback (LuceneIndexStatsUpdateCallback) is only executed
+                // in async indexing flow. There is a check on
+                // indexingContext.isAsync()
+                callbacks.add(new LuceneIndexStatsUpdateCallback(indexPath, mbean, statisticsProvider,
+                        asyncIndexesSizeStatsUpdate, indexingContext));
             }
 
             if (!callbacks.isEmpty()) {

Modified: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexProviderService.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexProviderService.java?rev=1869201&r1=1869200&r2=1869201&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexProviderService.java (original)
+++ jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexProviderService.java Thu Oct 31 07:04:51 2019
@@ -86,9 +86,7 @@ import org.apache.jackrabbit.oak.spi.sta
 import org.apache.jackrabbit.oak.spi.whiteboard.Registration;
 import org.apache.jackrabbit.oak.spi.whiteboard.Whiteboard;
 import org.apache.jackrabbit.oak.stats.Clock;
-import org.apache.jackrabbit.oak.stats.MeterStats;
 import org.apache.jackrabbit.oak.stats.StatisticsProvider;
-import org.apache.jackrabbit.oak.stats.StatsOptions;
 import org.apache.lucene.analysis.util.CharFilterFactory;
 import org.apache.lucene.analysis.util.TokenFilterFactory;
 import org.apache.lucene.analysis.util.TokenizerFactory;
@@ -262,6 +260,14 @@ public class LuceneIndexProviderService
     )
     private static final String PROP_NAME_DELETED_BLOB_COLLECTION_DEFAULT_ENABLED = "deletedBlobsCollectionEnabled";
 
+    private static final int LUCENE_INDEX_STATS_UPDATE_INTERVAL_DEFAULT = 300;
+    @Property(
+            intValue = LUCENE_INDEX_STATS_UPDATE_INTERVAL_DEFAULT,
+            label = "Lucene index stats update interval (seconds)",
+            description = "Delay in seconds after which Lucene stats are updated in async index update cycle."
+    )
+    private static final String LUCENE_INDEX_STATS_UPDATE_INTERVAL = "luceneIndexStatsUpdateInterval";
+
     private static final int PROP_INDEX_CLEANER_INTERVAL_DEFAULT = 10*60;
     @Property(
             intValue = PROP_INDEX_CLEANER_INTERVAL_DEFAULT,
@@ -357,10 +363,14 @@ public class LuceneIndexProviderService
     private IndexTracker tracker;
 
     private PropertyIndexCleaner cleaner;
+    private AsyncIndexesSizeStatsUpdate asyncIndexesSizeStatsUpdate;
 
     @Activate
     private void activate(BundleContext bundleContext, Map<String, ?> config)
             throws NotCompliantMBeanException, IOException {
+        asyncIndexesSizeStatsUpdate = new AsyncIndexesSizeStatsUpdateImpl(
+                PropertiesUtil.toLong(config.get(LUCENE_INDEX_STATS_UPDATE_INTERVAL),
+                        LUCENE_INDEX_STATS_UPDATE_INTERVAL_DEFAULT) * 1000); // convert seconds to millis
         boolean disabled = PropertiesUtil.toBoolean(config.get(PROP_DISABLED), PROP_DISABLED_DEFAULT);
         hybridIndex = PropertiesUtil.toBoolean(config.get(PROP_HYBRID_INDEXING), PROP_DISABLED_DEFAULT);
 
@@ -410,7 +420,6 @@ public class LuceneIndexProviderService
 
         LuceneIndexFileSystemStatistics luceneIndexFSStats = new LuceneIndexFileSystemStatistics(statisticsProvider, indexCopier);
         registerLuceneFileSystemStats(luceneIndexFSStats, PropertiesUtil.toLong(config.get(PROP_INDEX_FILESYSTEM_STATS_INTERVAL),PROP_INDEX_FILESYSTEM_STATS_INTERVAL_DEFAULT));
-
     }
 
     private File getIndexCheckDir() {
@@ -521,6 +530,7 @@ public class LuceneIndexProviderService
                     mountInfoProvider, activeDeletedBlobCollector, mBean, statisticsProvider);
         }
         editorProvider.setBlobStore(blobStore);
+        editorProvider.withAsyncIndexesSizeStatsUpdate(asyncIndexesSizeStatsUpdate);
 
         if (hybridIndex){
             editorProvider.setIndexingQueue(checkNotNull(documentQueue));

Modified: jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexStatsUpdateCallback.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexStatsUpdateCallback.java?rev=1869201&r1=1869200&r2=1869201&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexStatsUpdateCallback.java (original)
+++ jackrabbit/oak/trunk/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/LuceneIndexStatsUpdateCallback.java Thu Oct 31 07:04:51 2019
@@ -18,8 +18,8 @@
  */
 package org.apache.jackrabbit.oak.plugins.index.lucene;
 
-import org.apache.jackrabbit.oak.api.CommitFailedException;
 import org.apache.jackrabbit.oak.api.PropertyState;
+import org.apache.jackrabbit.oak.plugins.index.IndexingContext;
 import org.apache.jackrabbit.oak.plugins.index.search.PropertyDefinition;
 import org.apache.jackrabbit.oak.plugins.index.search.PropertyUpdateCallback;
 import org.apache.jackrabbit.oak.stats.HistogramStats;
@@ -45,12 +45,18 @@ public class LuceneIndexStatsUpdateCallb
     private final String indexPath;
     private final LuceneIndexMBean luceneIndexMBean;
     private final StatisticsProvider statisticsProvider;
+    private final AsyncIndexesSizeStatsUpdate asyncIndexesSizeStatsUpdate;
+    private final IndexingContext indexingContext;
 
     LuceneIndexStatsUpdateCallback(String indexPath, @NotNull LuceneIndexMBean luceneIndexMBean,
-                                   @NotNull StatisticsProvider statisticsProvider) {
+                                   @NotNull StatisticsProvider statisticsProvider,
+                                   AsyncIndexesSizeStatsUpdate asyncIndexesSizeStatsUpdate,
+                                   IndexingContext indexingContext) {
         this.indexPath = indexPath;
         this.luceneIndexMBean = luceneIndexMBean;
         this.statisticsProvider = statisticsProvider;
+        this.asyncIndexesSizeStatsUpdate = asyncIndexesSizeStatsUpdate;
+        this.indexingContext = indexingContext;
     }
 
     @Override
@@ -59,19 +65,40 @@ public class LuceneIndexStatsUpdateCallb
     }
 
     @Override
-    public void done() throws CommitFailedException {
-        try {
-            int docCount = Integer.parseInt(luceneIndexMBean.getDocCount(indexPath));
-            HistogramStats docCountHistogram = statisticsProvider.getHistogram(indexPath + NO_DOCS, StatsOptions.METRICS_ONLY);
-            docCountHistogram.update(docCount);
-
-            long indexSize = Long.parseLong(luceneIndexMBean.getSize(indexPath));
-            HistogramStats indexSizeHistogram = statisticsProvider.getHistogram(indexPath + INDEX_SIZE, StatsOptions.METRICS_ONLY);
-            indexSizeHistogram.update(indexSize);
-
-            log.debug("{} stats updated; docCount {}, size {}", indexPath, docCount, indexSize);
-        } catch (IOException e) {
-            log.debug("could not update no_docs/index_size stats for index at {}", indexPath, e);
+    public void done() {
+        if (shouldUpdateStats()) {
+            try {
+                long startTime = System.currentTimeMillis();
+                int docCount = Integer.parseInt(luceneIndexMBean.getDocCount(indexPath));
+                HistogramStats docCountHistogram = statisticsProvider.getHistogram(indexPath + NO_DOCS, StatsOptions.METRICS_ONLY);
+                docCountHistogram.update(docCount);
+                log.trace("{} stats updated, docCount {}, timeToUpdate {}", indexPath, docCount, System.currentTimeMillis() - startTime);
+                long indexSize = Long.parseLong(luceneIndexMBean.getSize(indexPath));
+                HistogramStats indexSizeHistogram = statisticsProvider.getHistogram(indexPath + INDEX_SIZE, StatsOptions.METRICS_ONLY);
+                indexSizeHistogram.update(indexSize);
+                long endTime = System.currentTimeMillis();
+                asyncIndexesSizeStatsUpdate.setLastStatsUpdateTime(indexPath, endTime);
+                log.debug("{} stats updated; docCount {}, size {}, timeToUpdate {}", indexPath, docCount, indexSize, endTime - startTime);
+            } catch (IOException e) {
+                log.warn("could not update no_docs/index_size stats for index at {}", indexPath, e);
+            }
         }
     }
+
+    private boolean shouldUpdateStats() {
+        boolean timeToUpdate = false;
+        if (indexingContext.isAsync()
+                && asyncIndexesSizeStatsUpdate != null
+                && asyncIndexesSizeStatsUpdate.getScheduleTimeInMillis() >= 0
+                && isScheduled()) {
+            timeToUpdate = true;
+        }
+        return timeToUpdate;
+    }
+
+    private boolean isScheduled() {
+        long lastStatsUpdateTime = asyncIndexesSizeStatsUpdate.getLastStatsUpdateTime(indexPath);
+        long defaultStatsUpdateTime = asyncIndexesSizeStatsUpdate.getScheduleTimeInMillis();
+        return System.currentTimeMillis() > lastStatsUpdateTime + defaultStatsUpdateTime;
+    }
 }

Added: jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java?rev=1869201&view=auto
==============================================================================
--- jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java (added)
+++ jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java Thu Oct 31 07:04:51 2019
@@ -0,0 +1,168 @@
+/*
+ * 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.jackrabbit.oak.plugins.index.lucene;
+
+import ch.qos.logback.classic.Level;
+import org.apache.jackrabbit.oak.InitialContent;
+import org.apache.jackrabbit.oak.Oak;
+import org.apache.jackrabbit.oak.api.ContentRepository;
+import org.apache.jackrabbit.oak.api.ContentSession;
+import org.apache.jackrabbit.oak.api.Root;
+import org.apache.jackrabbit.oak.commons.junit.LogCustomizer;
+import org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate;
+import org.apache.jackrabbit.oak.plugins.index.counter.NodeCounterEditorProvider;
+import org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory;
+import org.apache.jackrabbit.oak.plugins.index.lucene.util.IndexDefinitionBuilder;
+import org.apache.jackrabbit.oak.plugins.index.nodetype.NodeTypeIndexProvider;
+import org.apache.jackrabbit.oak.plugins.index.property.PropertyIndexEditorProvider;
+import org.apache.jackrabbit.oak.plugins.memory.MemoryNodeStore;
+import org.apache.jackrabbit.oak.plugins.metric.MetricStatisticsProvider;
+import org.apache.jackrabbit.oak.spi.commit.Observer;
+import org.apache.jackrabbit.oak.spi.mount.Mounts;
+import org.apache.jackrabbit.oak.spi.query.QueryIndexProvider;
+import org.apache.jackrabbit.oak.spi.security.OpenSecurityProvider;
+import org.apache.jackrabbit.oak.spi.state.NodeStore;
+import org.apache.jackrabbit.oak.stats.StatisticsProvider;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+import org.mockito.Mockito;
+
+import java.io.IOException;
+import java.util.List;
+
+import static com.google.common.collect.Lists.newArrayList;
+import static org.apache.jackrabbit.oak.plugins.index.CompositeIndexEditorProvider.compose;
+import static org.hamcrest.CoreMatchers.containsString;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertNull;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
+
+/**
+ * Tests AsyncIndexStatsUpdateCallback works as scheduled callback
+ */
+public class AsyncIndexStatsUpdateCallbackTest {
+    private int SCHEDULED_CALLBACK_TIME_IN_MILLIS = 1000; //1 second
+    protected Root root;
+    private AsyncIndexUpdate asyncIndexUpdate;
+    private LuceneIndexEditorProvider luceneIndexEditorProvider;
+    private LogCustomizer customLogger;
+    private AsyncIndexesSizeStatsUpdateImpl asyncIndexesSizeStatsUpdate =
+            new AsyncIndexesSizeStatsUpdateImpl(SCHEDULED_CALLBACK_TIME_IN_MILLIS);
+    private LuceneIndexMBeanImpl mBean = Mockito.mock(LuceneIndexMBeanImpl.class);
+
+    @Before
+    public void before() throws Exception {
+        customLogger = LogCustomizer
+                .forLogger(
+                        "org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexStatsUpdateCallback")
+                .enable(Level.DEBUG).create();
+        ContentSession session = createRepository().login(null, null);
+        Mockito.when(mBean.getDocCount("/oak:index/lucenePropertyIndex")).thenReturn("100");
+        Mockito.when(mBean.getSize("/oak:index/lucenePropertyIndex")).thenReturn("100");
+        root = session.getLatestRoot();
+    }
+
+    @After
+    public void shutDown() {
+        customLogger.finished();
+    }
+
+    protected ContentRepository createRepository() throws IOException {
+        NodeStore nodeStore = new MemoryNodeStore();
+        luceneIndexEditorProvider = new LuceneIndexEditorProvider(null, null,
+                null,
+                null, Mounts.defaultMountInfoProvider(),
+                ActiveDeletedBlobCollectorFactory.NOOP, mBean, StatisticsProvider.NOOP);
+
+        asyncIndexUpdate = new AsyncIndexUpdate("async", nodeStore, compose(newArrayList(
+                luceneIndexEditorProvider,
+                new NodeCounterEditorProvider()
+        )), StatisticsProvider.NOOP, false);
+        return new Oak(nodeStore)
+                .with(new InitialContent())
+                .with(new OpenSecurityProvider())
+                .createContentRepository();
+    }
+
+    @Test
+    public void testCallbackWorksAsScheduled() throws Exception {
+        luceneIndexEditorProvider.withAsyncIndexesSizeStatsUpdate(asyncIndexesSizeStatsUpdate);
+        IndexDefinitionBuilder idxb = new IndexDefinitionBuilder();
+        idxb.indexRule("nt:base")
+                .property("foo").analyzed().nodeScopeIndex().ordered().useInExcerpt().propertyIndex();
+        idxb.build(root.getTree("/oak:index").addChild("lucenePropertyIndex"));
+
+        // Add content and index it successfully
+        root.getTree("/").addChild("content").addChild("c1").setProperty("foo", "bar");
+        root.commit();
+        customLogger.starting();
+        asyncIndexUpdate.run();
+        List<String> logs = customLogger.getLogs();
+        assertTrue(logs.size() == 1);
+        root.getTree("/content").addChild("c2").setProperty("foo", "bar");
+        root.commit();
+        asyncIndexUpdate.run();
+        assertTrue(logs.size() == 1);
+        root.getTree("/content").addChild("c3").setProperty("foo", "bar");
+        root.commit();
+        Thread.sleep(2000);
+        asyncIndexUpdate.run();
+        assertTrue(logs.size() == 2);
+        validateLogs(logs);
+    }
+
+    @Test
+    public void testNOOPDonotPerformCallbackStatsUpdate() throws Exception {
+        luceneIndexEditorProvider.withAsyncIndexesSizeStatsUpdate(AsyncIndexesSizeStatsUpdate.NOOP);
+        IndexDefinitionBuilder idxb = new IndexDefinitionBuilder();
+        idxb.indexRule("nt:base")
+                .property("foo").analyzed().nodeScopeIndex().ordered().useInExcerpt().propertyIndex();
+        idxb.build(root.getTree("/oak:index").addChild("lucenePropertyIndex"));
+
+        // Add content and index it successfully
+        root.getTree("/").addChild("content").addChild("c1").setProperty("foo", "bar");
+        root.commit();
+        customLogger.starting();
+        asyncIndexUpdate.run();
+        List<String> logs = customLogger.getLogs();
+        assertTrue(logs.size() == 0);
+        root.getTree("/content").addChild("c2").setProperty("foo", "bar");
+        root.commit();
+        asyncIndexUpdate.run();
+        assertTrue(logs.size() == 0);
+        root.getTree("/content").addChild("c3").setProperty("foo", "bar");
+        root.commit();
+        Thread.sleep(2000);
+        asyncIndexUpdate.run();
+        assertTrue(logs.size() == 0);
+        //validateLogs(logs);
+    }
+
+
+    private void validateLogs(List<String> logs) {
+        for (String log : logs) {
+            assertThat("logs were recorded by custom logger", log,
+                    containsString("/oak:index/lucenePropertyIndex stats updated; docCount 100, size 100, timeToUpdate"));
+        }
+    }
+}

Propchange: jackrabbit/oak/trunk/oak-lucene/src/test/java/org/apache/jackrabbit/oak/plugins/index/lucene/AsyncIndexStatsUpdateCallbackTest.java
------------------------------------------------------------------------------
    svn:eol-style = native