Added logging to ConcurrentCache

Author: veloman-yunkan

src/concurrent_cache.h

@@ -22,6 +22,7 @@
 #define ZIM_CONCURRENT_CACHE_H
 
 #include "lrucache.h"
+#include "log.h"
 
 #include <chrono>
 #include <cstddef>
@@ -88,15 +89,21 @@ class ConcurrentCache: private lru_cache<Key, std::shared_future<Value>, FutureT
   template<class F>
   Value getOrPut(const Key& key, F f)
   {
+    log_debug_func_call("ConcurrentCache::getOrPut", key);
+
     std::promise<Value> valuePromise;
     std::unique_lock<std::mutex> l(lock_);
     auto shared_future = valuePromise.get_future().share();
     const auto x = Impl::getOrPut(key, shared_future);
     l.unlock();
+    log_debug("Obtained the cache slot");
     if ( x.miss() ) {
+      log_debug("It was a cache miss. Going to obtain the value...");
       try {
         valuePromise.set_value(f());
+        log_debug("Value was successfully obtained. Computing its cost...");
         auto cost = CostEstimation::cost(x.value().get());
+        log_debug("cost=" << cost << ". Committing to cache...");
         // There is a small window when the valuePromise may be drop from lru cache after
         // we set the value but before we increase the size of the cache.
         // In this case we decrease the size of `cost` before increasing it.
@@ -117,17 +124,20 @@ class ConcurrentCache: private lru_cache<Key, std::shared_future<Value>, FutureT
             Impl::increaseCost(cost);
           }
         }
+        log_debug("Done. Cache cost is at " << getCurrentCost() );
       } catch (std::exception& e) {
+        log_debug("Evaluation failed. Releasing the cache slot...");
         drop(key);
         throw;
       }
     }
 
-    return x.value().get();
+    return log_debug_return_value(x.value().get());
   }
 
   bool drop(const Key& key)
   {
+    log_debug_func_call("ConcurrentCache::drop", key);
     std::unique_lock<std::mutex> l(lock_);
     return Impl::drop(key);
   }

test/concurrentcache.cpp

@@ -17,6 +17,8 @@
  *
  */
 
+#define LIBZIM_ENABLE_LOGGING
+
 #include "concurrent_cache.h"
 #include "gtest/gtest.h"
 
@@ -38,3 +40,31 @@ TEST(ConcurrentCacheTest, handleException) {
     EXPECT_THROW(cache.getOrPut(8, ExceptionSource()), std::runtime_error);
     EXPECT_EQ(cache.getOrPut(8, LazyValue(888)), 888);
 }
+
+TEST(ConcurrentCacheXRayTest, simpleFlow) {
+    zim::Logging::logIntoMemory();
+    zim::ConcurrentCache<int, int, zim::UnitCostEstimation> cache(10);
+    EXPECT_EQ(cache.getOrPut(3, LazyValue(2025)), 2025);
+    EXPECT_EQ(cache.getOrPut(3, LazyValue(123)),  2025);
+    EXPECT_THROW(cache.getOrPut(2, ExceptionSource()), std::runtime_error);
+
+    ASSERT_EQ(zim::Logging::getInMemLogContent(),
+R"(thread#0: ConcurrentCache::getOrPut(3) {
+thread#0:  Obtained the cache slot
+thread#0:  It was a cache miss. Going to obtain the value...
+thread#0:  Value was successfully obtained. Computing its cost...
+thread#0:  cost=1. Committing to cache...
+thread#0:  Done. Cache cost is at 1
+thread#0: } (return value: 2025)
+thread#0: ConcurrentCache::getOrPut(3) {
+thread#0:  Obtained the cache slot
+thread#0: } (return value: 2025)
+thread#0: ConcurrentCache::getOrPut(2) {
+thread#0:  Obtained the cache slot
+thread#0:  It was a cache miss. Going to obtain the value...
+thread#0:  Evaluation failed. Releasing the cache slot...
+thread#0:  ConcurrentCache::drop(2) {
+thread#0:  } (return value: )
+thread#0: } (return value: )
+)");
+}