From de7726dd0037ea3cee91bf64162fc8b19853ec7a Mon Sep 17 00:00:00 2001
From: Brion Vibber <brion@pobox.com>
Date: Mon, 31 Jan 2011 13:12:56 -0800
Subject: [PATCH] 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 |  1 +
 index.php                        |  3 +++
 lib/cache.php                    |  4 ++++
 lib/default.php                  |  2 ++
 lib/util.php                     | 37 ++++++++++++++++++++++++++++++++
 5 files changed, 47 insertions(+)

diff --git a/classes/Memcached_DataObject.php b/classes/Memcached_DataObject.php
index a3c2de8e64..867b40cf3c 100644
--- a/classes/Memcached_DataObject.php
+++ b/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));
         }
diff --git a/index.php b/index.php
index 37c157b01f..7f2afffb5a 100644
--- a/index.php
+++ b/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;
 
diff --git a/lib/cache.php b/lib/cache.php
index dc667654ab..bf0603c62d 100644
--- a/lib/cache.php
+++ b/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]);
diff --git a/lib/default.php b/lib/default.php
index 405213fbea..2ddc47bd17 100644
--- a/lib/default.php
+++ b/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',
diff --git a/lib/util.php b/lib/util.php
index da36121ffd..85f49e4c59 100644
--- a/lib/util.php
+++ b/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)");
+        }
+    }
+}