Performance counters: records number of total and unique cache get/set/incr/deletes and queries, and logs to syslog.

$config['site']['logperf'] = true; // to record & dump total hits of each type and the runtime to syslog
$config['site']['logperf_detail'] = true; // very verbose -- dump the individual cache keys and queries as they get used (may contain private info in some queries)

Seeing 180 cache gets on a timeline page seems not unusual currently; since these run in serial, even relatively small roundtrip times can add up heavily.
We should consider ways to reduce the number of round trips, such as more frequently storing compound objects or the output of processing in memcached.
Doing parallel multi-key lookups could also help by collapsing round-trip times, but might not be easy to fit into SN's object model. (For things like streams this should actually work pretty well -- grab the list, then when it's returned go grab all the individual items in parallel and return the list)

classes/Memcached_DataObject.php

@@ -340,6 +340,7 @@ class Memcached_DataObject extends Safe_DataObject
         $start = microtime(true);
         $result = null;
         if (Event::handle('StartDBQuery', array($this, $string, &$result))) {
+            common_perf_counter('query', $string);
             $result = parent::_query($string);
             Event::handle('EndDBQuery', array($this, $string, &$result));
         }

index.php

@@ -38,6 +38,7 @@
  */
 
 $_startTime = microtime(true);
+$_perfCounters = array();
 
 define('INSTALLDIR', dirname(__FILE__));
 define('STATUSNET', true);
@@ -45,6 +46,8 @@ define('LACONICA', true); // compatibility
 
 require_once INSTALLDIR . '/lib/common.php';
 
+register_shutdown_function('common_log_perf_counters');
+
 $user = null;
 $action = null;
 

lib/cache.php

@@ -164,6 +164,7 @@ class Cache
     {
         $value = false;
 
+        common_perf_counter('Cache::get', $key);
         if (Event::handle('StartCacheGet', array(&$key, &$value))) {
             if (array_key_exists($key, $this->_items)) {
                 $value = unserialize($this->_items[$key]);
@@ -188,6 +189,7 @@ class Cache
     {
         $success = false;
 
+        common_perf_counter('Cache::set', $key);
         if (Event::handle('StartCacheSet', array(&$key, &$value, &$flag,
                                                  &$expiry, &$success))) {
 
@@ -214,6 +216,7 @@ class Cache
     function increment($key, $step=1)
     {
         $value = false;
+        common_perf_counter('Cache::increment', $key);
         if (Event::handle('StartCacheIncrement', array(&$key, &$step, &$value))) {
             // Fallback is not guaranteed to be atomic,
             // and may original expiry value.
@@ -239,6 +242,7 @@ class Cache
     {
         $success = false;
 
+        common_perf_counter('Cache::delete', $key);
         if (Event::handle('StartCacheDelete', array(&$key, &$success))) {
             if (array_key_exists($key, $this->_items)) {
                 unset($this->_items[$key]);

lib/default.php

@@ -39,6 +39,8 @@ $default =
               'logo' => null,
               'ssllogo' => null,
               'logdebug' => false,
+              'logperf' => false, // Enable to dump performance counters to syslog
+              'logperf_detail' => false, // Enable to dump every counter hit
               'fancy' => false,
               'locale_path' => INSTALLDIR.'/locale',
               'language' => 'en',

lib/util.php

@@ -2184,3 +2184,40 @@ function common_nicknamize($str)
     $str = preg_replace('/\W/', '', $str);
     return strtolower($str);
 }
+
+function common_perf_counter($key, $val=null)
+{
+    global $_perfCounters;
+    if (isset($_perfCounters)) {
+        if (common_config('site', 'logperf')) {
+            if (array_key_exists($key, $_perfCounters)) {
+                $_perfCounters[$key][] = $val;
+            } else {
+                $_perfCounters[$key] = array($val);
+            }
+            if (common_config('site', 'logperf_detail')) {
+                common_log(LOG_DEBUG, "PERF COUNTER HIT: $key $val");
+            }
+        }
+    }
+}
+
+function common_log_perf_counters()
+{
+    if (common_config('site', 'logperf')) {
+        global $_startTime, $_perfCounters;
+
+        if (isset($_startTime)) {
+            $endTime = microtime(true);
+            $diff = round(($endTime - $_startTime) * 1000);
+            common_log(LOG_DEBUG, "PERF runtime: ${diff}ms");
+        }
+        $counters = $_perfCounters;
+        ksort($counters);
+        foreach ($counters as $key => $values) {
+            $count = count($values);
+            $unique = count(array_unique($values));
+            common_log(LOG_DEBUG, "PERF COUNTER: $key $count ($unique unique)");
+        }
+    }
+}