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


Reply via email to