Performance counters: records number of total and unique cache get/set/incr/deletes...

$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)

diff --git a/classes/Memcached_DataObject.php b/classes/Memcached_DataObject.php
index a3c2de8e6415857126c759a548de801a77673283..867b40cf3cc0e05363343e9696a3ba56c53437a8 100644 (file)
--- 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 37c157b01fcc68a71ba100fe0032b4d62353ed64..7f2afffb5a01b0cac1a36953f450152150ab20ea 100644 (file)
--- 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 dc667654ab6ef327e8a022ae1b13d7612ecfa1b2..bf0603c62d0ce15c1f1401351668a7d7b48946b6 100644 (file)
--- 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 405213fbea06a9c2bc7d95028b1fd6c96823828c..2ddc47bd17fbef451e16c049a5b18c9335fd24d5 100644 (file)
--- 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 da36121ffd9c74a176a9cefb0847fa1e9503d69f..85f49e4c59f40c57ae2b74c54fffd76a48dcf064 100644 (file)
--- 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)");
+        }
+    }
+}