From db3dd861f4e4fc2323d2b6a3b9a419b1ae8253f9 Mon Sep 17 00:00:00 2001
From: Par Winzell <zell@threerings.net>
Date: Mon, 2 Feb 2009 18:14:26 +0000
Subject: [PATCH] Lose the spammy debug logging, collect some histogram
 information instead. These are not currently hooked up to Depot's Stat
 mechanism.

---
 .../com/samskivert/depot/EHCacheAdapter.java  | 65 ++++++++++---------
 1 file changed, 36 insertions(+), 29 deletions(-)

diff --git a/src/java/com/samskivert/depot/EHCacheAdapter.java b/src/java/com/samskivert/depot/EHCacheAdapter.java
index b69032b..9c40560 100644
--- a/src/java/com/samskivert/depot/EHCacheAdapter.java
+++ b/src/java/com/samskivert/depot/EHCacheAdapter.java
@@ -27,6 +27,7 @@ import java.util.Set;
 
 import com.google.common.collect.Maps;
 import com.google.common.collect.Sets;
+import com.samskivert.util.Histogram;
 
 import net.sf.ehcache.CacheManager;
 import net.sf.ehcache.Ehcache;
@@ -49,10 +50,18 @@ import static com.samskivert.depot.Log.log;
 public class EHCacheAdapter
     implements CacheAdapter
 {
-    protected static final String EHCACHE_RECORD_CACHE = "depotRecord";
-    protected static final String EHCACHE_KEYSET_CACHE = "depotKeyset";
-    protected static final String EHCACHE_RESULT_CACHE = "depotResult";
+    public static final String EHCACHE_RECORD_CACHE = "depotRecord";
+    public static final String EHCACHE_KEYSET_CACHE = "depotKeyset";
+    public static final String EHCACHE_RESULT_CACHE = "depotResult";
 
+    public static class EHCachePerformance
+    {
+        public Histogram lookups;
+        public Histogram stores;
+        public Histogram removes;
+        public Histogram enumerations;
+    }
+    
     /**
      * Creates an adapter using the supplied cache manager. Note: this adapter does not shut down
      * the supplied manager when it is shutdown. The caller is responsible for shutting down the
@@ -75,12 +84,7 @@ public class EHCacheAdapter
             return null;
         }
         CachedValue<T> result = lookup(bin.getCache(), cacheId, key);
-        long dT = System.currentTimeMillis() - now;
-        if (dT > 100) {
-            log.warning("Aii! A simple ehcache lookup took over 100 ms!", "cacheId", cacheId,
-                        "key", key, "dT", dT, "lookups", _lookups);
-        }
-        _lookups ++;
+        _lookups.addValue((int) (System.currentTimeMillis() - now));
         return result;
     }
 
@@ -99,12 +103,7 @@ public class EHCacheAdapter
             _bins.put(cacheId, bin);
         }
         bin.getCache().put(new Element(new EHCacheKey(cacheId, key), value != null ? value : NULL));
-        long dT = System.currentTimeMillis() - now;
-        if (dT > 100) {
-            log.warning("Aii! A simple ehcache store took over 100 ms!", "cacheId", cacheId,
-                        "key", key, "dT", dT, "stores", _stores);
-        }
-        _stores ++;
+        _stores.addValue((int) (System.currentTimeMillis() - now));
     }
 
     // from CacheAdapter
@@ -115,12 +114,7 @@ public class EHCacheAdapter
         if (bin != null) {
             bin.getCache().remove(new EHCacheKey(cacheId, key));
         }
-        long dT = System.currentTimeMillis() - now;
-        if (dT > 100) {
-            log.warning("Aii! A simple ehcache remove took over 100 ms!", "cacheId", cacheId,
-                        "key", key, "dT", dT, "removes", _removes);
-        }
-        _removes ++;
+        _removes.addValue((int) (System.currentTimeMillis() - now));
     }
 
     // from CacheAdapter
@@ -134,18 +128,29 @@ public class EHCacheAdapter
         
         // let's return a simple copy of the bin's fancy concurrent hashset
         Set<Serializable> result = Sets.newHashSet(bin.getKeys());
-        long dT = System.currentTimeMillis() - now;
-        if (dT > 250) {
-            log.warning("Aii! A cache enumeration took over 250 ms!", "cacheId", cacheId,
-                        "dT", dT, "enumerations", _enumerations);
-        }
-        _enumerations ++;
+        _enumerations.addValue((int) (System.currentTimeMillis() - now));
         return result;
     }
 
     // from CacheAdapter
     public void shutdown ()
     {
+        log.info("EHCacheAdapter shutting down", "lookups", _lookups, 
+            "stores", _stores, "removes", _removes, "enumerations", _enumerations);
+    }
+    
+    /**
+     * Return a snapshot of the current histograms detailing how much time the different
+     * operations lookup, store, remove and enumerate take.
+     */
+    public EHCachePerformance getPerformanceSnapshot ()
+    {
+        EHCachePerformance result = new EHCachePerformance();
+        result.lookups = _lookups.clone();
+        result.stores = _stores.clone();
+        result.removes = _removes.clone();
+        result.enumerations = _enumerations.clone();
+        return result;
     }
 
     protected <T> CachedValue<T> lookup (Ehcache cache, String cacheId, Serializable key)
@@ -166,7 +171,6 @@ public class EHCacheAdapter
                 return String.valueOf(value);
             }
         };
-
     }
 
     protected Ehcache bindEHCache (CacheManager cachemgr, CacheCategory category, String cacheName)
@@ -181,7 +185,10 @@ public class EHCacheAdapter
         return cache;
     }
 
-    protected int _lookups, _stores, _removes, _enumerations;
+    protected Histogram _lookups = new Histogram(0, 50, 20);
+    protected Histogram _stores = new Histogram(0, 50, 20);
+    protected Histogram _removes = new Histogram(0, 50, 20);
+    protected Histogram _enumerations = new Histogram(0, 50, 20);
 
     protected Map<CacheCategory, Ehcache> _categories =
         Collections.synchronizedMap(Maps.<CacheCategory, Ehcache>newHashMap());