Author: mreutegg Date: Wed Aug 9 10:01:41 2017 New Revision: 1804500 URL: http://svn.apache.org/viewvc?rev=1804500&view=rev Log: OAK-6536: Periodic log message from continuous RGC
Added: jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java (with props) Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java?rev=1804500&r1=1804499&r2=1804500&view=diff ============================================================================== --- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java (original) +++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStoreService.java Wed Aug 9 10:01:41 2017 @@ -73,6 +73,8 @@ import org.apache.jackrabbit.oak.api.jmx import org.apache.jackrabbit.oak.api.jmx.PersistentCacheStatsMBean; import org.apache.jackrabbit.oak.cache.CacheStats; import org.apache.jackrabbit.oak.commons.PropertiesUtil; +import org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.VersionGCStats; +import org.apache.jackrabbit.oak.plugins.document.util.Utils; import org.apache.jackrabbit.oak.spi.commit.ObserverTracker; import org.apache.jackrabbit.oak.osgi.OsgiWhiteboard; import org.apache.jackrabbit.oak.plugins.blob.BlobGC; @@ -929,7 +931,7 @@ public class DocumentNodeStoreService { BlobGCMBean.TYPE, "Document node store blob garbage collection")); } - Runnable startGC = new RevisionGCJob(store, versionGcMaxAgeInSecs, log); + Runnable startGC = new RevisionGCJob(store, versionGcMaxAgeInSecs); Runnable cancelGC = new Runnable() { @Override public void run() { @@ -1003,7 +1005,7 @@ public class DocumentNodeStoreService { if (isContinuousRevisionGC()) { final long versionGcMaxAgeInSecs = toLong(prop(PROP_VER_GC_MAX_AGE), DEFAULT_VER_GC_MAX_AGE); addRegistration(WhiteboardUtils.scheduleWithFixedDelay(whiteboard, - new RevisionGCJob(nodeStore, versionGcMaxAgeInSecs, log), + new RevisionGCJob(nodeStore, versionGcMaxAgeInSecs), MODIFIED_IN_SECS_RESOLUTION, true, true)); } } @@ -1074,27 +1076,37 @@ public class DocumentNodeStoreService { static final class RevisionGCJob implements Runnable, Supplier<String> { + // log as VersionGarbageCollector + private static final Logger LOGGER = LoggerFactory.getLogger(VersionGarbageCollector.class); + + // log every hour + private static final long LOG_INTERVAL = TimeUnit.HOURS.toMillis(1); + private final DocumentNodeStore nodeStore; private final long versionGcMaxAgeInSecs; - private final Logger log; private volatile Object lastResult = ""; + private long lastLogTime; + private VersionGCStats stats; RevisionGCJob(DocumentNodeStore ns, - long versionGcMaxAgeInSecs, - Logger log) { + long versionGcMaxAgeInSecs) { this.nodeStore = ns; this.versionGcMaxAgeInSecs = versionGcMaxAgeInSecs; - this.log = log; + resetStats(); } @Override public void run() { VersionGarbageCollector gc = nodeStore.getVersionGarbageCollector(); try { - lastResult = gc.gc(versionGcMaxAgeInSecs, TimeUnit.SECONDS).toString(); + VersionGCStats s = gc.gc(versionGcMaxAgeInSecs, TimeUnit.SECONDS); + stats.addRun(s); + lastResult = s.toString(); } catch (Exception e) { lastResult = e; - log.warn("Error occurred while executing the Version Garbage Collector", e); + LOGGER.warn("Error occurred while executing the Version Garbage Collector", e); + } finally { + maybeLogStats(); } } @@ -1112,5 +1124,18 @@ public class DocumentNodeStoreService { } return String.valueOf(lastResult); } + + private void resetStats() { + lastLogTime = nodeStore.getClock().getTime(); + stats = new VersionGCStats(); + } + + private void maybeLogStats() { + if (nodeStore.getClock().getTime() > lastLogTime + LOG_INTERVAL) { + LOGGER.info("Garbage collector stats since {}: {}", + Utils.timestampToString(lastLogTime), stats); + resetStats(); + } + } } } Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java?rev=1804500&r1=1804499&r2=1804500&view=diff ============================================================================== --- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java (original) +++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/VersionGarbageCollector.java Wed Aug 9 10:01:41 2017 @@ -310,12 +310,23 @@ public class VersionGarbageCollector { this.splitDocGCCount += run.splitDocGCCount; this.intermediateSplitDocGCCount += run.intermediateSplitDocGCCount; this.updateResurrectedGCCount += run.updateResurrectedGCCount; - this.collectDeletedDocsElapsed += run.collectDeletedDocs.elapsed(MICROSECONDS); - this.checkDeletedDocsElapsed += run.checkDeletedDocs.elapsed(MICROSECONDS); - this.deleteDeletedDocsElapsed += run.deleteDeletedDocs.elapsed(MICROSECONDS); - this.collectAndDeleteSplitDocsElapsed += run.collectAndDeleteSplitDocs.elapsed(MICROSECONDS); - this.sortDocIdsElapsed += run.sortDocIds.elapsed(MICROSECONDS); - this.updateResurrectedDocumentsElapsed += run.updateResurrectedDocuments.elapsed(MICROSECONDS); + if (run.iterationCount > 0) { + // run is cumulative with times in elapsed fields + this.collectDeletedDocsElapsed += run.collectDeletedDocsElapsed; + this.checkDeletedDocsElapsed += run.checkDeletedDocsElapsed; + this.deleteDeletedDocsElapsed += run.deleteDeletedDocsElapsed; + this.collectAndDeleteSplitDocsElapsed += run.collectAndDeleteSplitDocsElapsed; + this.sortDocIdsElapsed += run.sortDocIdsElapsed; + this.updateResurrectedDocumentsElapsed += run.updateResurrectedDocumentsElapsed; + } else { + // single run -> read from stop watches + this.collectDeletedDocsElapsed += run.collectDeletedDocs.elapsed(MICROSECONDS); + this.checkDeletedDocsElapsed += run.checkDeletedDocs.elapsed(MICROSECONDS); + this.deleteDeletedDocsElapsed += run.deleteDeletedDocs.elapsed(MICROSECONDS); + this.collectAndDeleteSplitDocsElapsed += run.collectAndDeleteSplitDocs.elapsed(MICROSECONDS); + this.sortDocIdsElapsed += run.sortDocIds.elapsed(MICROSECONDS); + this.updateResurrectedDocumentsElapsed += run.updateResurrectedDocuments.elapsed(MICROSECONDS); + } } } Added: jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java?rev=1804500&view=auto ============================================================================== --- jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java (added) +++ jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java Wed Aug 9 10:01:41 2017 @@ -0,0 +1,100 @@ +/* + * 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.document; + +import java.util.concurrent.TimeUnit; + +import com.google.common.base.Stopwatch; + +import org.apache.jackrabbit.oak.plugins.document.VersionGarbageCollector.VersionGCStats; +import org.junit.Before; +import org.junit.Test; + +import static java.util.concurrent.TimeUnit.MICROSECONDS; +import static org.junit.Assert.assertEquals; + +public class VersionGCStatsTest { + + private static final Callable START = new Callable() { + @Override + public void call(Stopwatch watch) { + watch.start(); + } + }; + + private static final Callable STOP = new Callable() { + @Override + public void call(Stopwatch watch) { + watch.stop(); + } + }; + + private VersionGCStats stats = new VersionGCStats(); + + @Before + public void before() throws Exception { + forEachStopwatch(stats, START); + while (stats.updateResurrectedDocuments.elapsed(TimeUnit.MILLISECONDS) < 10) { + Thread.sleep(1); + } + forEachStopwatch(stats, STOP); + } + + @Test + public void addRun() { + VersionGCStats cumulative = new VersionGCStats(); + cumulative.addRun(stats); + assertEquals(stats.collectDeletedDocs.elapsed(MICROSECONDS), cumulative.collectDeletedDocsElapsed); + assertEquals(stats.checkDeletedDocs.elapsed(MICROSECONDS), cumulative.checkDeletedDocsElapsed); + assertEquals(stats.deleteDeletedDocs.elapsed(MICROSECONDS), cumulative.deleteDeletedDocsElapsed); + assertEquals(stats.collectAndDeleteSplitDocs.elapsed(MICROSECONDS), cumulative.collectAndDeleteSplitDocsElapsed); + assertEquals(stats.sortDocIds.elapsed(MICROSECONDS), cumulative.sortDocIdsElapsed); + assertEquals(stats.updateResurrectedDocuments.elapsed(MICROSECONDS), cumulative.updateResurrectedDocumentsElapsed); + } + + @Test + public void addRunCumulative() { + VersionGCStats cumulative = new VersionGCStats(); + cumulative.addRun(stats); + // double stats by adding to itself + cumulative.addRun(cumulative); + // now the stats must have doubled + assertEquals(stats.collectDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.collectDeletedDocsElapsed); + assertEquals(stats.checkDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.checkDeletedDocsElapsed); + assertEquals(stats.deleteDeletedDocs.elapsed(MICROSECONDS) * 2, cumulative.deleteDeletedDocsElapsed); + assertEquals(stats.collectAndDeleteSplitDocs.elapsed(MICROSECONDS) * 2, cumulative.collectAndDeleteSplitDocsElapsed); + assertEquals(stats.sortDocIds.elapsed(MICROSECONDS) * 2, cumulative.sortDocIdsElapsed); + assertEquals(stats.updateResurrectedDocuments.elapsed(MICROSECONDS) * 2, cumulative.updateResurrectedDocumentsElapsed); + } + + private void forEachStopwatch(VersionGCStats stats, Callable c) { + c.call(stats.active); + c.call(stats.collectDeletedDocs); + c.call(stats.checkDeletedDocs); + c.call(stats.deleteDeletedDocs); + c.call(stats.collectAndDeleteSplitDocs); + c.call(stats.sortDocIds); + c.call(stats.updateResurrectedDocuments); + } + + private interface Callable { + + void call(Stopwatch watch); + } +} Propchange: jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/plugins/document/VersionGCStatsTest.java ------------------------------------------------------------------------------ svn:eol-style = native