From 495399fc66e02ac8f47e2917190602ca0b76f330 Mon Sep 17 00:00:00 2001
From: Par Winzell <zell@threerings.net>
Date: Wed, 28 Jan 2009 05:54:23 +0000
Subject: [PATCH] A little more information in our paranoid logging.

---
 .../com/samskivert/depot/EHCacheAdapter.java  | 21 +++++++++++++++----
 1 file changed, 17 insertions(+), 4 deletions(-)

diff --git a/src/java/com/samskivert/depot/EHCacheAdapter.java b/src/java/com/samskivert/depot/EHCacheAdapter.java
index 3c20fa9..f81f905 100644
--- a/src/java/com/samskivert/depot/EHCacheAdapter.java
+++ b/src/java/com/samskivert/depot/EHCacheAdapter.java
@@ -79,8 +79,9 @@ public class EHCacheAdapter
         long dT = System.currentTimeMillis() - now;
         if (dT > 50) {
             log.warning("Aii! A simple ehcache lookup took over 50 ms!", "cacheId", cacheId,
-                "key", key, "dT", dT);
+                        "key", key, "dT", dT, "lookups", _lookups);
         }
+        _lookups ++;
         return result;
     }
 
@@ -102,8 +103,9 @@ public class EHCacheAdapter
         long dT = System.currentTimeMillis() - now;
         if (dT > 50) {
             log.warning("Aii! A simple ehcache store took over 50 ms!", "cacheId", cacheId,
-                "key", key, "dT", dT);
+                        "key", key, "dT", dT, "stores", _stores);
         }
+        _stores ++;
     }
 
     // from CacheAdapter
@@ -117,20 +119,29 @@ public class EHCacheAdapter
         long dT = System.currentTimeMillis() - now;
         if (dT > 50) {
             log.warning("Aii! A simple ehcache remove took over 50 ms!", "cacheId", cacheId,
-                "key", key, "dT", dT);
+                        "key", key, "dT", dT, "removes", _removes);
         }
+        _removes ++;
     }
 
     // from CacheAdapter
     public <T> Iterable<Serializable> enumerate (final String cacheId)
     {
+        long now = System.currentTimeMillis();
         EHCacheBin<?> bin = _bins.get(cacheId);
         if (bin == null) {
             return Collections.emptySet();
         }
         
         // let's return a simple copy of the bin's fancy concurrent hashset
-        return Sets.newHashSet(bin.getKeys());
+        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 ++;
+        return result;
     }
 
     // from CacheAdapter
@@ -171,6 +182,8 @@ public class EHCacheAdapter
         return cache;
     }
 
+    protected int _lookups, _stores, _removes, _enumerations;
+
     protected Map<CacheCategory, Ehcache> _categories =
         Collections.synchronizedMap(Maps.<CacheCategory, Ehcache>newHashMap());
     protected Map<String, EHCacheBin<?>> _bins =