#
#
# add_file "cache_logger.cc"
#  content [f963c6395c69e91d9b6e85fe3e106524a59f44ef]
# 
# add_file "cache_logger.hh"
#  content [9da9583f7d90aec49b87d2419d295a0cada175f7]
# 
# patch "Makefile.am"
#  from [b64f1bb21ea623267925f28d086205263a36e3f1]
#    to [2a65b561e8fc7ecd02ad248aebeba2cb7e77f84a]
# 
# patch "constants.hh"
#  from [e391543c177b7c136f3f8d3660343026994f5a7e]
#    to [4c48291dadb8d80630a8781fd729860ceb564f51]
# 
# patch "database.cc"
#  from [9e4afbdbfa43b40b5b61090574f548647c5bd916]
#    to [ba0efb380dfc9c0582b0368b0e6a1073ebf4122d]
# 
# patch "lru_writeback_cache.hh"
#  from [d659c6cf2b06fb3ec5324e50c1448571a8676712]
#    to [cfa4c94526bd19a2084d2f1086f1fe85364d0062]
# 
# patch "options_list.hh"
#  from [85e9dc9fe8a836c20eed806b14253ca0a557c199]
#    to [0da409d4f6519266ac604cf9bb31f91416294bb9]
#
============================================================
--- cache_logger.cc	f963c6395c69e91d9b6e85fe3e106524a59f44ef
+++ cache_logger.cc	f963c6395c69e91d9b6e85fe3e106524a59f44ef
@@ -0,0 +1,87 @@
+#include "base.hh"
+#include "cache_logger.hh"
+
+#include <fstream>
+
+using std::ofstream;
+using std::endl;
+using std::string;
+
+class cache_logger_impl
+{
+public:
+  ofstream stream;
+
+  explicit cache_logger_impl(string const & filename)
+    : stream(filename.c_str())
+  { }
+};
+
+cache_logger::cache_logger(string const & filename, int max_size)
+  : max_size(max_size)
+{
+  if (!filename.empty())
+    {
+      _impl.reset(new cache_logger_impl(filename));
+    }
+}
+
+void cache_logger::log_exists(bool exists, int position,
+                              int item_count, int est_size) const
+{
+  if (_impl)
+    {
+      _impl->stream << "Exists: " << (exists?"ok":"missing")
+                    << "; position: " << position
+                    << "; count: " << item_count
+                    << "; size: " << est_size << " of " << max_size
+                    << endl;
+    }
+}
+
+void cache_logger::log_touch(bool exists, int position,
+                             int item_count, int est_size) const
+{
+  if (_impl)
+    {
+      _impl->stream << "Touch: " << (exists?"ok":"missing")
+                    << "; position: " << position
+                    << "; count: " << item_count
+                    << "; size: " << est_size << " of " << max_size
+                    << endl;
+    }
+}
+
+void cache_logger::log_fetch(bool exists, int position,
+                             int item_count, int est_size) const
+{
+  if (_impl)
+    {
+      _impl->stream << "Fetch: " << (exists?"ok":"missing")
+                    << "; position: " << position
+                    << "; count: " << item_count
+                    << "; size: " << est_size << " of " << max_size
+                    << endl;
+    }
+}
+
+void cache_logger::log_insert(int items_removed,
+                             int item_count, int est_size) const
+{
+  if (_impl)
+    {
+      _impl->stream << "Insert... "
+                    << " dropped items: " << items_removed
+                    << "; count: " << item_count
+                    << "; size: " << est_size << " of " << max_size
+                    << endl;
+    }
+}
+
+// Local Variables:
+// mode: C++
+// fill-column: 76
+// c-file-style: "gnu"
+// indent-tabs-mode: nil
+// End:
+// vim: et:sw=2:sts=2:ts=2:cino=>2s,{s,\:s,+s,t0,g0,^-2,e-2,n-2,p2s,(0,=s:
============================================================
--- cache_logger.hh	9da9583f7d90aec49b87d2419d295a0cada175f7
+++ cache_logger.hh	9da9583f7d90aec49b87d2419d295a0cada175f7
@@ -0,0 +1,33 @@
+#ifndef __CACHE_LOGGER_HH__
+#define __CACHE_LOGGER_HH__
+
+#include <boost/shared_ptr.hpp>
+
+class cache_logger_impl;
+
+class cache_logger
+{
+  boost::shared_ptr<cache_logger_impl> _impl;
+  int max_size;
+public:
+  // if given the empty filename, do nothing
+  explicit cache_logger(std::string const & filename, int max_size);
+
+  bool logging() const { return _impl; }
+
+  void log_exists(bool exists, int position, int item_count, int est_size) const;
+  void log_touch(bool exists, int position, int item_count, int est_size) const;
+  void log_fetch(bool exists, int position, int item_count, int est_size) const;
+  void log_insert(int items_removed, int item_count, int est_size) const;
+};
+
+#endif
+
+
+// Local Variables:
+// mode: C++
+// fill-column: 76
+// c-file-style: "gnu"
+// indent-tabs-mode: nil
+// End:
+// vim: et:sw=2:sts=2:ts=2:cino=>2s,{s,\:s,+s,t0,g0,^-2,e-2,n-2,p2s,(0,=s:
============================================================
--- Makefile.am	b64f1bb21ea623267925f28d086205263a36e3f1
+++ Makefile.am	2a65b561e8fc7ecd02ad248aebeba2cb7e77f84a
@@ -42,6 +42,7 @@ MOST_SOURCES = 								\
 	automate_ostream_demuxed.hh					\
 	automate_reader.hh automate_reader.cc				\
 	botan_pipe_cache.hh						\
+	cache_logger.hh cache_logger.cc					\
 	commands.cc commands.hh $(CMD_SOURCES)				\
 	diff_output.cc diff_output.hh					\
 	lua_hooks.cc lua_hooks.hh 					\
============================================================
--- constants.hh	e391543c177b7c136f3f8d3660343026994f5a7e
+++ constants.hh	4c48291dadb8d80630a8781fd729860ceb564f51
@@ -63,6 +63,11 @@ namespace constants
   // not doing any testing at all - it could be tweaked further.
   std::size_t const db_roster_cache_sz = 7 * (1 << 20);
 
+  // minimum number of items in the roster cache
+  // when receiving even a perfectly linear history, the cache needs
+  // to have at least 2 entries to be effective
+  std::size_t const db_roster_cache_min_count = 2;
+
   // estimated number of bytes taken for a node_t and its corresponding
   // marking_t.  used to estimate the current size of the write-back roster
   // cache.    the calculation is:
============================================================
--- database.cc	9e4afbdbfa43b40b5b61090574f548647c5bd916
+++ database.cc	ba0efb380dfc9c0582b0368b0e6a1073ebf4122d
@@ -208,7 +208,8 @@ public:
 
   // for scoped_ptr's sake
 public:
-  explicit database_impl(system_path const & f, bool mem);
+  explicit database_impl(system_path const & f, bool mem,
+                         system_path const & roster_cache_performance_log);
   ~database_impl();
 
 private:
@@ -457,15 +458,18 @@ sqlite3_hex_fn(sqlite3_context *f, int n
 }
 #endif
 
-database_impl::database_impl(system_path const & f, bool mem) :
+database_impl::database_impl(system_path const & f, bool mem,
+                             system_path const & roster_cache_performance_log) :
   filename(f),
   use_memory_db(mem),
   __sql(NULL),
   transaction_level(0),
   roster_cache(constants::db_roster_cache_sz,
-               roster_writeback_manager(*this)),
+               constants::db_roster_cache_min_count,
+               roster_writeback_manager(*this),
+               roster_cache_performance_log.as_external()),
   delayed_writes_size(0),
-  vcache(constants::db_version_cache_sz)
+  vcache(constants::db_version_cache_sz, 1)
 {}
 
 database_impl::~database_impl()
@@ -500,7 +504,8 @@ database::database(app_state & app)
 
   boost::shared_ptr<database_impl> & i = app.dbcache->dbs[app.opts.dbname];
   if (!i)
-    i.reset(new database_impl(app.opts.dbname, app.opts.dbname_is_memory));
+    i.reset(new database_impl(app.opts.dbname, app.opts.dbname_is_memory,
+                              app.opts.roster_cache_performance_log));
 
   imp = i;
 }
============================================================
--- lru_writeback_cache.hh	d659c6cf2b06fb3ec5324e50c1448571a8676712
+++ lru_writeback_cache.hh	cfa4c94526bd19a2084d2f1086f1fe85364d0062
@@ -14,6 +14,7 @@
 #include <map>
 #include <list>
 
+#include "cache_logger.hh"
 #include "sanity.hh"
 #include "safe_map.hh"
 
@@ -81,19 +82,32 @@ private:
   /// Current abstract size of the cache
   unsigned long _curr_size;
 
+  /// Minimum number of items in the cache (overrides the abstract size limit)
+  unsigned long _min_items;
+
+  cache_logger logger;
+
 public:
   /** @brief Creates a cache that holds at most Size worth of elements.
    *  @param Size maximum size of cache
    */
-  LRUWritebackCache(const unsigned long Size, Manager manager)
-      : _manager(manager), _max_size(Size), _curr_size(0)
+  LRUWritebackCache(const unsigned long Size,
+                    const unsigned long items,
+                    Manager manager,
+                    std::string const & logname)
+    : _manager(manager), _max_size(Size), _curr_size(0),
+      _min_items(items),
+      logger(logname, _max_size)
   {
   }
 
   // Also allow a default-instantiated manager, for using this as a pure LRU
   // cache with no writeback.
-  LRUWritebackCache(const unsigned long Size)
-      : _max_size(Size), _curr_size(0)
+  LRUWritebackCache(const unsigned long Size,
+                    const unsigned long items)
+    : _max_size(Size), _curr_size(0),
+      _min_items(items),
+      logger("", 0)
   {
   }
 
@@ -164,7 +178,9 @@ public:
    */
   inline bool exists(Key const & key) const
   {
-    return _index.find(key) != _index.end();
+    bool e = _index.find(key) != _index.end();
+    logger.log_exists(e, _position(key), _index.size(), _curr_size);
+    return e;
   }
 
   /** @brief Touches a key in the Cache and makes it the most recently used.
@@ -172,8 +188,10 @@ public:
    */
   inline void touch(Key const & key)
   {
-    // Find the key in the index.
-    Map_Iter miter = this->_touch(key);
+    Map_Iter miter = _index.find(key);
+    logger.log_touch(miter != _index.end(), _position(key),
+                     _index.size(), _curr_size);
+    this->_touch(miter);
   }
 
   /** @brief Fetches a copy of cache data.
@@ -185,6 +203,8 @@ public:
   inline bool fetch(Key const & key, Data & data, bool touch = true)
   {
     Map_Iter miter = _index.find(key);
+    logger.log_fetch(miter != _index.end(), _position(key),
+                     _index.size(), _curr_size);
     if (miter == _index.end())
       return false;
     if (touch)
@@ -212,7 +232,9 @@ public:
     safe_insert(_index, std::make_pair(key, liter));
     _curr_size += Sizefn()(data);
     // Check to see if we need to remove an element due to exceeding max_size
-    while (_curr_size > _max_size)
+    int num_removed = 0;
+    unsigned long curr_size = _list.size();
+    while (_curr_size > _max_size && curr_size > _min_items)
       {
         // Remove the last element.
         liter = _list.end();
@@ -225,8 +247,12 @@ public:
         if (liter == _list.begin())
           break;
         this->_remove(liter->first);
+        ++num_removed;
+        --curr_size;
+        I(curr_size > 0);
       }
     I(exists(key));
+    logger.log_insert(num_removed, _index.size(), _curr_size);
   }
 
   inline void insert_dirty(Key const & key, const Data & data)
@@ -241,9 +267,8 @@ private:
    *  @param key to be touched
    *  @return a Map_Iter pointing to the key that was touched.
    */
-  inline Map_Iter _touch(const Key & key)
+  inline Map_Iter _touch(Map_Iter & miter)
   {
-    Map_Iter miter = _index.find(key);
     if (miter == _index.end())
       return miter;
     // Move the found node to the head of the list.
@@ -273,6 +298,25 @@ private:
     List_Iter const & i = safe_get(_index, key);
     _manager.writeout(i->first, i->second);
   }
+
+  // Determine where in the cache a given item is,
+  // for use with effectiveness logging.
+  inline int _position(Key const & key) const
+  {
+    if (!logger.logging())
+      {
+        return -2;
+      }
+    int pos = 0;
+    for (typename List::const_iterator liter = _list.begin();
+         liter != _list.end(); ++liter)
+      {
+        if (liter->first == key)
+          return pos;
+        ++pos;
+      }
+    return -1;
+  }
 };
 
 #endif // __LRU_WRITEBACK_CACHE_HH__
============================================================
--- options_list.hh	85e9dc9fe8a836c20eed806b14253ca0a557c199
+++ options_list.hh	0da409d4f6519266ac604cf9bb31f91416294bb9
@@ -236,6 +236,14 @@ GOPT(dbname, "db,d", system_path, , gett
 }
 #endif
 
+GOPT(roster_cache_performance_log, "roster-cache-performance-log",
+     system_path, , gettext_noop("log roster cache statistict to the given file"))
+#ifdef option_bodies
+{
+  roster_cache_performance_log = system_path(arg, origin::user);
+}
+#endif
+
 OPTION(globals, debug, false, "debug",
         gettext_noop("print debug log to stderr while running"))
 #ifdef option_bodies