Enhance WindowCache statistics

Add the following statistics
- cache hit count and hit ratio
- cache miss count and miss ratio
- count of successful and failed loads
- rate of failed loads
- load, eviction and request count
- average and total load time

Use LongAdder instead of AtomicLong to implement counters in order to
improve scalability.

Optionally expose these metrics via JMX, they are registered with the
platform MBean server if the config option jmx.WindowCacheStats = true
in the user or system level git config.

Bug: 553573
Change-Id: Ia2d5246ef69b9c2bd594a23934424bc5800774aa
Signed-off-by: Matthias Sohn <matthias.sohn@sap.com>

5 files changed, 510 insertions, 35 deletions

diff --git a/org.eclipse.jgit/.settings/.api_filters b/org.eclipse.jgit/.settings/.api_filters
index 56edd61d75..9ee9ff7b68 100644
--- a/org.eclipse.jgit/.settings/.api_filters
+++ b/org.eclipse.jgit/.settings/.api_filters
@@ -45,6 +45,12 @@
     <resource path="src/org/eclipse/jgit/lib/ConfigConstants.java" type="org.eclipse.jgit.lib.ConfigConstants">
         <filter id="1142947843">
             <message_arguments>
+                <message_argument value="5.1.13"/>
+                <message_argument value="CONFIG_JMX_SECTION"/>
+            </message_arguments>
+        </filter>
+        <filter id="1142947843">
+            <message_arguments>
                 <message_argument value="5.1.9"/>
                 <message_argument value="CONFIG_FILESYSTEM_SECTION"/>
             </message_arguments>
@@ -78,6 +84,15 @@
             </message_arguments>
         </filter>
     </resource>
+    <resource path="src/org/eclipse/jgit/storage/file/WindowCacheStats.java" type="org.eclipse.jgit.storage.file.WindowCacheStats">
+        <filter id="337809484">
+            <message_arguments>
+                <message_argument value="org.eclipse.jgit.storage.file.WindowCacheStats"/>
+                <message_argument value="4"/>
+                <message_argument value="8"/>
+            </message_arguments>
+        </filter>
+    </resource>
     <resource path="src/org/eclipse/jgit/storage/pack/PackConfig.java" type="org.eclipse.jgit.storage.pack.PackConfig">
         <filter id="336658481">
             <message_arguments>
@@ -232,6 +247,14 @@
             </message_arguments>
         </filter>
     </resource>
+    <resource path="src/org/eclipse/jgit/util/Monitoring.java" type="org.eclipse.jgit.util.Monitoring">
+        <filter id="1109393411">
+            <message_arguments>
+                <message_argument value="5.1.13"/>
+                <message_argument value="org.eclipse.jgit.util.Monitoring"/>
+            </message_arguments>
+        </filter>
+    </resource>
     <resource path="src/org/eclipse/jgit/util/SimpleLruCache.java" type="org.eclipse.jgit.util.SimpleLruCache">
         <filter id="1109393411">
             <message_arguments>
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/WindowCache.java b/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/WindowCache.java
index 8cf1d4e219..6cf5bd948a 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/WindowCache.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/WindowCache.java
@@ -48,13 +48,16 @@ import java.io.IOException;
 import java.lang.ref.ReferenceQueue;
 import java.lang.ref.SoftReference;
 import java.util.Random;
-import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.atomic.AtomicReferenceArray;
+import java.util.concurrent.atomic.LongAdder;
 import java.util.concurrent.locks.ReentrantLock;
 
+import org.eclipse.jgit.annotations.NonNull;
 import org.eclipse.jgit.internal.JGitText;
 import org.eclipse.jgit.storage.file.WindowCacheConfig;
+import org.eclipse.jgit.storage.file.WindowCacheStats;
+import org.eclipse.jgit.util.Monitoring;
 
 /**
  * Caches slices of a {@link org.eclipse.jgit.internal.storage.file.PackFile} in
@@ -124,6 +127,196 @@ import org.eclipse.jgit.storage.file.WindowCacheConfig;
  * other threads.
  */
 public class WindowCache {
+
+	/**
+	 * Record statistics for a cache
+	 */
+	static interface StatsRecorder {
+		/**
+		 * Record cache hits. Called when cache returns a cached entry.
+		 *
+		 * @param count
+		 *            number of cache hits to record
+		 */
+		void recordHits(int count);
+
+		/**
+		 * Record cache misses. Called when the cache returns an entry which had
+		 * to be loaded.
+		 *
+		 * @param count
+		 *            number of cache misses to record
+		 */
+		void recordMisses(int count);
+
+		/**
+		 * Record a successful load of a cache entry
+		 *
+		 * @param loadTimeNanos
+		 *            time to load a cache entry
+		 */
+		void recordLoadSuccess(long loadTimeNanos);
+
+		/**
+		 * Record a failed load of a cache entry
+		 *
+		 * @param loadTimeNanos
+		 *            time used trying to load a cache entry
+		 */
+		void recordLoadFailure(long loadTimeNanos);
+
+		/**
+		 * Record cache evictions due to the cache evictions strategy
+		 *
+		 * @param count
+		 *            number of evictions to record
+		 */
+		void recordEvictions(int count);
+
+		/**
+		 * Record files opened by cache
+		 *
+		 * @param count
+		 *            delta of number of files opened by cache
+		 */
+		void recordOpenFiles(int count);
+
+		/**
+		 * Record cached bytes
+		 *
+		 * @param count
+		 *            delta of cached bytes
+		 */
+		void recordOpenBytes(int count);
+
+		/**
+		 * Returns a snapshot of this recorder's stats. Note that this may be an
+		 * inconsistent view, as it may be interleaved with update operations.
+		 *
+		 * @return a snapshot of this recorder's stats
+		 */
+		@NonNull
+		WindowCacheStats getStats();
+	}
+
+	static class StatsRecorderImpl
+			implements StatsRecorder, WindowCacheStats {
+		private final LongAdder hitCount;
+		private final LongAdder missCount;
+		private final LongAdder loadSuccessCount;
+		private final LongAdder loadFailureCount;
+		private final LongAdder totalLoadTime;
+		private final LongAdder evictionCount;
+		private final LongAdder openFileCount;
+		private final LongAdder openByteCount;
+
+		/**
+		 * Constructs an instance with all counts initialized to zero.
+		 */
+		public StatsRecorderImpl() {
+			hitCount = new LongAdder();
+			missCount = new LongAdder();
+			loadSuccessCount = new LongAdder();
+			loadFailureCount = new LongAdder();
+			totalLoadTime = new LongAdder();
+			evictionCount = new LongAdder();
+			openFileCount = new LongAdder();
+			openByteCount = new LongAdder();
+		}
+
+		@Override
+		public void recordHits(int count) {
+			hitCount.add(count);
+		}
+
+		@Override
+		public void recordMisses(int count) {
+			missCount.add(count);
+		}
+
+		@Override
+		public void recordLoadSuccess(long loadTimeNanos) {
+			loadSuccessCount.increment();
+			totalLoadTime.add(loadTimeNanos);
+		}
+
+		@Override
+		public void recordLoadFailure(long loadTimeNanos) {
+			loadFailureCount.increment();
+			totalLoadTime.add(loadTimeNanos);
+		}
+
+		@Override
+		public void recordEvictions(int count) {
+			evictionCount.add(count);
+		}
+
+		@Override
+		public void recordOpenFiles(int count) {
+			openFileCount.add(count);
+		}
+
+		@Override
+		public void recordOpenBytes(int count) {
+			openByteCount.add(count);
+		}
+
+		@Override
+		public WindowCacheStats getStats() {
+			return this;
+		}
+
+		@Override
+		public long getHitCount() {
+			return hitCount.sum();
+		}
+
+		@Override
+		public long getMissCount() {
+			return missCount.sum();
+		}
+
+		@Override
+		public long getLoadSuccessCount() {
+			return loadSuccessCount.sum();
+		}
+
+		@Override
+		public long getLoadFailureCount() {
+			return loadFailureCount.sum();
+		}
+
+		@Override
+		public long getEvictionCount() {
+			return evictionCount.sum();
+		}
+
+		@Override
+		public long getTotalLoadTime() {
+			return totalLoadTime.sum();
+		}
+
+		@Override
+		public long getOpenFileCount() {
+			return openFileCount.sum();
+		}
+
+		@Override
+		public long getOpenByteCount() {
+			return openByteCount.sum();
+		}
+
+		@Override
+		public void resetCounters() {
+			hitCount.reset();
+			missCount.reset();
+			loadSuccessCount.reset();
+			loadFailureCount.reset();
+			totalLoadTime.reset();
+			evictionCount.reset();
+		}
+	}
+
 	private static final int bits(int newSize) {
 		if (newSize < 4096)
 			throw new IllegalArgumentException(JGitText.get().invalidWindowSize);
@@ -228,9 +421,9 @@ public class WindowCache {
 
 	private final int windowSize;
 
-	private final AtomicInteger openFiles;
+	private final StatsRecorder statsRecorder;
 
-	private final AtomicLong openBytes;
+	private final StatsRecorderImpl mbean;
 
 	private WindowCache(WindowCacheConfig cfg) {
 		tableSize = tableSize(cfg);
@@ -263,8 +456,9 @@ public class WindowCache {
 		windowSizeShift = bits(cfg.getPackedGitWindowSize());
 		windowSize = 1 << windowSizeShift;
 
-		openFiles = new AtomicInteger();
-		openBytes = new AtomicLong();
+		mbean = new StatsRecorderImpl();
+		statsRecorder = mbean;
+		Monitoring.registerMBean(WindowCacheStats.class, "block_cache"); //$NON-NLS-1$
 
 		if (maxFiles < 1)
 			throw new IllegalArgumentException(JGitText.get().openFilesMustBeAtLeast1);
@@ -273,61 +467,63 @@ public class WindowCache {
 	}
 
 	/**
-	 * @return the number of open files.
+	 * @return cache statistics for the WindowCache
 	 */
-	public int getOpenFiles() {
-		return openFiles.get();
+	public WindowCacheStats getStats() {
+		return statsRecorder.getStats();
 	}
 
 	/**
-	 * @return the number of open bytes.
+	 * Reset stats. Does not reset open bytes and open files stats.
 	 */
-	public long getOpenBytes() {
-		return openBytes.get();
+	public void resetStats() {
+		mbean.resetCounters();
 	}
 
 	private int hash(int packHash, long off) {
 		return packHash + (int) (off >>> windowSizeShift);
 	}
 
-	private ByteWindow load(PackFile pack, long offset)
-			throws IOException {
+	private ByteWindow load(PackFile pack, long offset) throws IOException {
+		long startTime = System.nanoTime();
 		if (pack.beginWindowCache())
-			openFiles.incrementAndGet();
+			statsRecorder.recordOpenFiles(1);
 		try {
 			if (mmap)
 				return pack.mmap(offset, windowSize);
-			return pack.read(offset, windowSize);
-		} catch (IOException e) {
-			close(pack);
-			throw e;
-		} catch (RuntimeException e) {
-			close(pack);
-			throw e;
-		} catch (Error e) {
+			ByteArrayWindow w = pack.read(offset, windowSize);
+			statsRecorder.recordLoadSuccess(System.nanoTime() - startTime);
+			return w;
+		} catch (IOException | RuntimeException | Error e) {
 			close(pack);
+			statsRecorder.recordLoadFailure(System.nanoTime() - startTime);
 			throw e;
+		} finally {
+			statsRecorder.recordMisses(1);
 		}
 	}
 
 	private Ref createRef(PackFile p, long o, ByteWindow v) {
 		final Ref ref = new Ref(p, o, v, queue);
-		openBytes.addAndGet(ref.size);
+		statsRecorder.recordOpenBytes(ref.size);
 		return ref;
 	}
 
 	private void clear(Ref ref) {
-		openBytes.addAndGet(-ref.size);
+		statsRecorder.recordOpenBytes(-ref.size);
+		statsRecorder.recordEvictions(1);
 		close(ref.pack);
 	}
 
 	private void close(PackFile pack) {
-		if (pack.endWindowCache())
-			openFiles.decrementAndGet();
+		if (pack.endWindowCache()) {
+			statsRecorder.recordOpenFiles(-1);
+		}
 	}
 
 	private boolean isFull() {
-		return maxFiles < openFiles.get() || maxBytes < openBytes.get();
+		return maxFiles < mbean.getOpenFileCount()
+				|| maxBytes < mbean.getOpenByteCount();
 	}
 
 	private long toStart(long offset) {
@@ -365,15 +561,19 @@ public class WindowCache {
 		final int slot = slot(pack, position);
 		final Entry e1 = table.get(slot);
 		ByteWindow v = scan(e1, pack, position);
-		if (v != null)
+		if (v != null) {
+			statsRecorder.recordHits(1);
 			return v;
+		}
 
 		synchronized (lock(pack, position)) {
 			Entry e2 = table.get(slot);
 			if (e2 != e1) {
 				v = scan(e2, pack, position);
-				if (v != null)
+				if (v != null) {
+					statsRecorder.recordHits(1);
 					return v;
+				}
 			}
 
 			v = load(pack, position);
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ConfigConstants.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ConfigConstants.java
index 82ccd7b034..43776e0817 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ConfigConstants.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ConfigConstants.java
@@ -451,4 +451,10 @@ public final class ConfigConstants {
 	 * @since 5.1.9
 	 */
 	public static final String CONFIG_KEY_MIN_RACY_THRESHOLD = "minRacyThreshold";
+
+	/**
+	 * The "jmx" section
+	 * @since 5.1.13
+	 */
+	public static final String CONFIG_JMX_SECTION = "jmx";
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/storage/file/WindowCacheStats.java b/org.eclipse.jgit/src/org/eclipse/jgit/storage/file/WindowCacheStats.java
index 3570733e41..b7f6394df6 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/storage/file/WindowCacheStats.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/storage/file/WindowCacheStats.java
@@ -40,29 +40,193 @@
  * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF
  * ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  */
-
 package org.eclipse.jgit.storage.file;
 
+import javax.management.MXBean;
+
 import org.eclipse.jgit.internal.storage.file.WindowCache;
 
 /**
- * Accessor for stats about {@link WindowCache}.
+ * Cache statistics for {@link WindowCache}.
  *
  * @since 4.11
- *
  */
-public class WindowCacheStats {
+@MXBean
+public interface WindowCacheStats {
 	/**
 	 * @return the number of open files.
+	 * @deprecated use {@link #getOpenFileCount()} instead
 	 */
+	@Deprecated
 	public static int getOpenFiles() {
-		return WindowCache.getInstance().getOpenFiles();
+		return (int) WindowCache.getInstance().getStats().getOpenFileCount();
 	}
 
 	/**
 	 * @return the number of open bytes.
+	 * @deprecated use {@link #getOpenByteCount()} instead
 	 */
+	@Deprecated
 	public static long getOpenBytes() {
-		return WindowCache.getInstance().getOpenBytes();
+		return WindowCache.getInstance().getStats().getOpenByteCount();
+	}
+
+	/**
+	 * @return cache statistics for the WindowCache
+	 * @since 5.1.13
+	 */
+	public static WindowCacheStats getStats() {
+		return WindowCache.getInstance().getStats();
+	}
+
+	/**
+	 * Number of cache hits
+	 *
+	 * @return number of cache hits
+	 */
+	long getHitCount();
+
+	/**
+	 * Ratio of cache requests which were hits defined as
+	 * {@code hitCount / requestCount}, or {@code 1.0} when
+	 * {@code requestCount == 0}. Note that {@code hitRate + missRate =~ 1.0}.
+	 *
+	 * @return the ratio of cache requests which were hits
+	 */
+	default double getHitRatio() {
+		long requestCount = getRequestCount();
+		return (requestCount == 0) ? 1.0
+				: (double) getHitCount() / requestCount;
+	}
+
+	/**
+	 * Number of cache misses.
+	 *
+	 * @return number of cash misses
+	 */
+	long getMissCount();
+
+	/**
+	 * Ratio of cache requests which were misses defined as
+	 * {@code missCount / requestCount}, or {@code 0.0} when
+	 * {@code requestCount == 0}. Note that {@code hitRate + missRate =~ 1.0}.
+	 * Cache misses include all requests which weren't cache hits, including
+	 * requests which resulted in either successful or failed loading attempts.
+	 *
+	 * @return the ratio of cache requests which were misses
+	 */
+	default double getMissRatio() {
+		long requestCount = getRequestCount();
+		return (requestCount == 0) ? 0.0
+				: (double) getMissCount() / requestCount;
+	}
+
+	/**
+	 * Number of successful loads
+	 *
+	 * @return number of successful loads
+	 */
+	long getLoadSuccessCount();
+
+	/**
+	 * Number of failed loads
+	 *
+	 * @return number of failed loads
+	 */
+	long getLoadFailureCount();
+
+	/**
+	 * Ratio of cache load attempts which threw exceptions. This is defined as
+	 * {@code loadFailureCount / (loadSuccessCount + loadFailureCount)}, or
+	 * {@code 0.0} when {@code loadSuccessCount + loadFailureCount == 0}.
+	 *
+	 * @return the ratio of cache loading attempts which threw exceptions
+	 */
+	default double getLoadFailureRatio() {
+		long loadFailureCount = getLoadFailureCount();
+		long totalLoadCount = getLoadSuccessCount() + loadFailureCount;
+		return (totalLoadCount == 0) ? 0.0
+				: (double) loadFailureCount / totalLoadCount;
 	}
+
+	/**
+	 * Total number of times that the cache attempted to load new values. This
+	 * includes both successful load operations, as well as failed loads. This
+	 * is defined as {@code loadSuccessCount + loadFailureCount}.
+	 *
+	 * @return the {@code loadSuccessCount + loadFailureCount}
+	 */
+	default long getLoadCount() {
+		return getLoadSuccessCount() + getLoadFailureCount();
+	}
+
+	/**
+	 * Number of cache evictions
+	 *
+	 * @return number of evictions
+	 */
+	long getEvictionCount();
+
+	/**
+	 * Ratio of cache evictions. This is defined as
+	 * {@code evictionCount / requestCount}, or {@code 0.0} when
+	 * {@code requestCount == 0}.
+	 *
+	 * @return the ratio of cache loading attempts which threw exceptions
+	 */
+	default double getEvictionRatio() {
+		long evictionCount = getEvictionCount();
+		long requestCount = getRequestCount();
+		return (requestCount == 0) ? 0.0
+				: (double) evictionCount / requestCount;
+	}
+
+	/**
+	 * Number of times the cache returned either a cached or uncached value.
+	 * This is defined as {@code hitCount + missCount}.
+	 *
+	 * @return the {@code hitCount + missCount}
+	 */
+	default long getRequestCount() {
+		return getHitCount() + getMissCount();
+	}
+
+	/**
+	 * Average time in nanoseconds for loading new values. This is
+	 * {@code totalLoadTime / (loadSuccessCount + loadFailureCount)}.
+	 *
+	 * @return the average time spent loading new values
+	 */
+	default double getAverageLoadTime() {
+		long totalLoadCount = getLoadSuccessCount() + getLoadFailureCount();
+		return (totalLoadCount == 0) ? 0.0
+				: (double) getTotalLoadTime() / totalLoadCount;
+	}
+
+	/**
+	 * Total time in nanoseconds the cache spent loading new values.
+	 *
+	 * @return the total number of nanoseconds the cache has spent loading new
+	 *         values
+	 */
+	long getTotalLoadTime();
+
+	/**
+	 * Number of pack files kept open by the cache
+	 *
+	 * @return number of files kept open by cache
+	 */
+	long getOpenFileCount();
+
+	/**
+	 * Number of bytes cached
+	 *
+	 * @return number of bytes cached
+	 */
+	long getOpenByteCount();
+
+	/**
+	 * Reset counters. Does not reset open bytes and open files counters.
+	 */
+	void resetCounters();
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/util/Monitoring.java b/org.eclipse.jgit/src/org/eclipse/jgit/util/Monitoring.java
new file mode 100644
index 0000000000..a3c8f3e047
--- /dev/null
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/util/Monitoring.java
@@ -0,0 +1,82 @@
+/*
+ * Copyright (c) 2019 Matthias Sohn <matthias.sohn@sap.com>
+ *
+ * This program and the accompanying materials are made available under the
+ * terms of the Eclipse Distribution License v. 1.0 which is available at
+ * https://www.eclipse.org/org/documents/edl-v10.php.
+ *
+ * SPDX-License-Identifier: BSD-3-Clause
+ */
+package org.eclipse.jgit.util;
+
+import java.io.IOException;
+import java.lang.management.ManagementFactory;
+
+import javax.management.InstanceAlreadyExistsException;
+import javax.management.InstanceNotFoundException;
+import javax.management.MBeanRegistrationException;
+import javax.management.MBeanServer;
+import javax.management.MalformedObjectNameException;
+import javax.management.NotCompliantMBeanException;
+import javax.management.ObjectInstance;
+import javax.management.ObjectName;
+
+import org.eclipse.jgit.annotations.Nullable;
+import org.eclipse.jgit.errors.ConfigInvalidException;
+import org.eclipse.jgit.lib.ConfigConstants;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Enables monitoring JGit via JMX
+ *
+ * @since 5.1.13
+ */
+public class Monitoring {
+	private final static Logger LOG = LoggerFactory.getLogger(Monitoring.class);
+
+	/**
+	 * Register a MBean with the platform MBean server
+	 *
+	 * @param mbean
+	 *            the mbean interface to register
+	 * @param metricName
+	 *            name of the JGit metric, will be prefixed with
+	 *            "org.eclipse.jgit/"
+	 * @return the registered mbean's object instance
+	 */
+	public static @Nullable ObjectInstance registerMBean(Class mbean,
+			String metricName) {
+		boolean register;
+		try {
+			register = SystemReader.getInstance().getUserConfig().getBoolean(
+					ConfigConstants.CONFIG_JMX_SECTION,
+					mbean.getSimpleName(), false);
+		} catch (IOException | ConfigInvalidException e) {
+			LOG.error(e.getMessage(), e);
+			return null;
+		}
+		if (!register) {
+			return null;
+		}
+		MBeanServer server = ManagementFactory.getPlatformMBeanServer();
+		try {
+			ObjectName mbeanName = objectName(mbean, metricName);
+			if (server.isRegistered(mbeanName)) {
+				server.unregisterMBean(mbeanName);
+			}
+			return server.registerMBean(mbean, mbeanName);
+		} catch (MalformedObjectNameException | InstanceAlreadyExistsException
+				| MBeanRegistrationException | NotCompliantMBeanException
+				| InstanceNotFoundException e) {
+			LOG.error(e.getMessage(), e);
+			return null;
+		}
+	}
+
+	private static ObjectName objectName(Class mbean, String metricName)
+			throws MalformedObjectNameException {
+		return new ObjectName(String.format("org.eclipse.jgit/%s:type=%s", //$NON-NLS-1$
+				metricName, mbean.getSimpleName()));
+	}
+}