From: Brion Vibber <brion@pobox.com>
Date: Mon, 31 Jan 2011 21:12:56 +0000 (-0800)
Subject: Performance counters: records number of total and unique cache get/set/incr/deletes... 
X-Git-Url: https://git.mxchange.org/?a=commitdiff_plain;h=de7726dd0037ea3cee91bf64162fc8b19853ec7a;p=quix0rs-gnu-social.git

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

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)");
+        }
+    }
+}