[pLog-svn] r2887 - in plog/trunk: . class/cache class/database/pdb/drivers class/misc config

oscar at devel.lifetype.net oscar at devel.lifetype.net
Thu Feb 2 22:39:51 GMT 2006


Author: oscar
Date: 2006-02-02 22:39:51 +0000 (Thu, 02 Feb 2006)
New Revision: 2887

Modified:
   plog/trunk/admin.php
   plog/trunk/class/cache/cache.class.php
   plog/trunk/class/database/pdb/drivers/pdbdriverbase.class.php
   plog/trunk/class/database/pdb/drivers/pdbmysqldriver.class.php
   plog/trunk/class/misc/info.class.php
   plog/trunk/config/logging.properties.php
   plog/trunk/index.php
Log:
Added some options for performance logging. There is a new log file called tmp/metrics.log that contains a rows of comma-seaparated values with several different metrics/values. The meaning of the columns is as follows:

- memory usage
- total execution time of the script
- number of included files
- number of SQL queries executed
- number of cache queries
- number of cache hits
- number of cache misses
- script executing the request
- uri of the request

If somebody has any suggestion about logging other useful information, let me know.


Modified: plog/trunk/admin.php
===================================================================
--- plog/trunk/admin.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/admin.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -11,6 +11,7 @@
     include_once( PLOG_CLASS_PATH."class/dao/userinfo.class.php" );
     include_once( PLOG_CLASS_PATH."class/dao/bloginfo.class.php" );
     include_once( PLOG_CLASS_PATH."class/plugin/pluginmanager.class.php" );
+    include_once( PLOG_CLASS_PATH."class/misc/info.class.php" );
 
     ini_set("arg_seperator.output", "&");
     ini_set("magic_quotes_runtime", 0 );
@@ -37,4 +38,7 @@
 
     // give control to the, ehem, controller :)
     $controller->process( HttpVars::getRequest(), "op");
+	
+    // log statistics, only for debugging purposes
+    Info::logMetrics();
 ?>

Modified: plog/trunk/class/cache/cache.class.php
===================================================================
--- plog/trunk/class/cache/cache.class.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/class/cache/cache.class.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -8,6 +8,9 @@
     * Provides a singleton for storing and retrieving data from a global cache.
     */
 
+	$__cache_hits = 0;
+	$__cache_misses = 0;
+	$__cache_queries = 0;
 
     class Cache extends Loggable
     {
@@ -56,19 +59,30 @@
 
         function getData( $id, $group )
         {
+			global $__cache_hits;			
+			global $__cache_queries;
+			global $__cache_misses;		
+		
             if( $this->_cacheCategoryEnabled($group) ) {
+			
+				$__cache_queries++;
 
                 $inCache = $this->cache->get( $id, $group );
 
                 if( DEBUG_ENABLED && DEBUG_CHANNELS & DEBUG_CHANNEL_CACHE )
-                    if ($inCache)
+                    if ($inCache) {
                         $this->debug->log("Cache hit for $id ($group): $data", LOGGER_PRIO_INFO );
-                    else
+						$__cache_hits++;
+					}
+                    else {
                         $this->debug->log("Cache miss for $id ($group)", LOGGER_PRIO_WARN );
+						$__cache_misses++;						
+					}
 
                 return $inCache;
-            } else
+            } else {
                 return false;
+			}
 
         }
 
@@ -123,5 +137,22 @@
             } else
                 return true;
         }
+		
+		/**
+		 * returns the total count of cache hits, miss and total queries over the lifetime of the
+		 * script so far.
+		 *
+		 * @return An array with 3 keys: "hits", "total" and "miss"
+		 */
+		function getCacheStats()
+		{
+			global $__cache_hits;
+			global $__cache_misses;
+			global $__cache_queries;
+		
+			return( Array( "total" => $__cache_queries,
+			               "hits"  => $__cache_hits,
+						   "miss"  => $__cache_misses )); 
+		}
     }
 ?>

Modified: plog/trunk/class/database/pdb/drivers/pdbdriverbase.class.php
===================================================================
--- plog/trunk/class/database/pdb/drivers/pdbdriverbase.class.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/class/database/pdb/drivers/pdbdriverbase.class.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -11,6 +11,13 @@
      * whether we're going to use paging or not.
      */
     define( "DEFAULT_PAGING_ENABLED", -1 );	
+	
+	/**
+	 * number of SQL queries executed so far. It is up to the driver classes
+	 * to keep this number updated!!
+	 */
+	$__pdb_num_queries = 0;
+	
     /**
      * \ingroup PDb
      *
@@ -466,6 +473,15 @@
                 foreach($objarr as $v) $arr[strtoupper($v->name)] = $v->name;
     
             return $arr;
-        }        
+        }
+		
+		/**
+		 * Returns the number of queries executed so far
+		 */
+		function getNumQueries()
+		{
+			global $__pdb_num_queries;
+			return( $__pdb_num_queries );
+		}
 	}
 ?>

Modified: plog/trunk/class/database/pdb/drivers/pdbmysqldriver.class.php
===================================================================
--- plog/trunk/class/database/pdb/drivers/pdbmysqldriver.class.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/class/database/pdb/drivers/pdbmysqldriver.class.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -29,6 +29,8 @@
 		 */
 		function Execute( $query, $page = -1, $itemsPerPage = 15 )
 		{
+			global $__pdb_num_queries;
+		
 		    if( $page > -1 ) {
                 $start = (($page - 1) * $itemsPerPage);
                 $limits = " LIMIT $start, $itemsPerPage";
@@ -43,8 +45,11 @@
 			// connection parameters, we either need to select the database *everytime* we want to make 
 			// a query or use slightly different connection paramters. I am not sure if this has any
 			// performance hit, though.
-			mysql_select_db( $this->_dbname, $this->_res );				
+			mysql_select_db( $this->_dbname, $this->_res );
 			
+			// increment the number of queries executed so far, regardless of what they were
+			$__pdb_num_queries++;
+			
 			$result = mysql_query( $query, $this->_res );
 			if( !$result ) {
 			    if( $this->_debug ) {

Modified: plog/trunk/class/misc/info.class.php
===================================================================
--- plog/trunk/class/misc/info.class.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/class/misc/info.class.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -1,6 +1,12 @@
 <?php
 
 	/**
+	 * global variables to take care of the timing stuff
+	 */
+	$__metrics_start_time = 0;
+	$__metrics_end_time = 0;
+
+	/**
 	 * Basic class for obtaining certain information about the script and the server
 	 * itself. This class will in the future have benchmarking methods, etc.
 	 */
@@ -16,5 +22,62 @@
 				return( memory_get_usage());
 			}
 		}
+		
+		function startMetrics()
+		{
+			global $__metrics_start_time;
+			
+			$mtime = microtime(); 
+			$mtime = explode(" ",$mtime); 
+			$mtime = $mtime[1] + $mtime[0]; 
+			$__metrics_start_time = $mtime;
+			
+			return( true );
+		}
+		
+		function logMetrics()
+		{
+			include_once( PLOG_CLASS_PATH."class/logger/loggermanager.class.php" );
+			include_once( PLOG_CLASS_PATH."class/cache/cachemanager.class.php" );
+			include_once( PLOG_CLASS_PATH."class/database/db.class.php" );
+		
+			global $__metrics_start_time;
+			
+			$mtime = microtime(); 
+			$mtime = explode(" ",$mtime); 
+			$mtime = $mtime[1] + $mtime[0]; 
+			$__metrics_end_time = $mtime;			
+			
+			// calculate the execution time
+			$totalTime = ( $__metrics_end_time - $__metrics_start_time );
+			
+			// load cache statistics
+			$cache =& CacheManager::getCache();
+			$cacheData = $cache->getCacheStats();
+			
+			// get information from the request
+			$script = $_SERVER["SCRIPT_NAME"];
+			$requestUri = $_SERVER["REQUEST_URI"];
+			
+			// get the number of sql queries
+			$db =& Db::getDb();
+			$numQueries = $db->getNumQueries();
+			if( $numQueries == "" ) $numQueries = 0;
+			
+			// build the message
+			$message = Info::getMemoryUsage().",".
+			           $totalTime.",".
+					   count(get_included_files()).",".
+					   $numQueries.",".
+					   $cacheData["total"].",".
+					   $cacheData["hits"].",".
+					   $cacheData["miss"].",\"".
+					   $script."\",\"".
+					   $requestUri."\"";
+			
+			// get the logger and log the message
+			$logger =& LoggerManager::getLogger( "metricslog" );
+			$logger->debug( $message );
+		}
 	}
 ?>
\ No newline at end of file

Modified: plog/trunk/config/logging.properties.php
===================================================================
--- plog/trunk/config/logging.properties.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/config/logging.properties.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -14,7 +14,7 @@
 // debug output sent to debug.log by default. 
   
 $config["debug"] = Array( 
-    "layout"   => "%S %d %N - [%f:%l (%c:%F)] %m%n", 
+    "layout"   => "%d %N - [%f:%l (%c:%F)] %m%n", 
     "appender" => "file",
 	"file"     => "tmp/debug.log",
     "prio"     => "info"  
@@ -25,7 +25,7 @@
 # to the file tmp/sql_error.log
 #
 $config["sqlerr"] = Array( 
-    "layout" => "%d %N - %m%n", 
+    "layout" => "%S%n %d %N - %m%n", 
     "appender" => "file",
 	"file" => "tmp/sql_error.log",
     "prio" => "error"
@@ -41,5 +41,15 @@
 	"file" => "tmp/trackback.log",
     "prio" => "debug"
   );
+  
+#
+# special logger for metrics and performance statistics
+#
+$config["metricslog"] = Array(
+    "layout" => "%m%n", 
+    "appender" => "file",
+	"file" => "tmp/metrics.log",
+    "prio" => "debug"
+  );  
 
-?>
\ No newline at end of file
+?>

Modified: plog/trunk/index.php
===================================================================
--- plog/trunk/index.php	2006-02-02 12:52:03 UTC (rev 2886)
+++ plog/trunk/index.php	2006-02-02 22:39:51 UTC (rev 2887)
@@ -9,7 +9,7 @@
     if (!defined( "PLOG_CLASS_PATH" )) {
         define( "PLOG_CLASS_PATH", dirname(__FILE__)."/");
     }
-
+    
     include_once( PLOG_CLASS_PATH."class/controller/blogcontroller.class.php" );
     include_once( PLOG_CLASS_PATH."class/net/http/session/sessionmanager.class.php" );
     include_once( PLOG_CLASS_PATH."class/dao/userinfo.class.php" );
@@ -17,6 +17,9 @@
     include_once( PLOG_CLASS_PATH."class/plugin/pluginmanager.class.php" );
     include_once( PLOG_CLASS_PATH."class/data/timestamp.class.php" );
     include_once( PLOG_CLASS_PATH."class/misc/info.class.php" );
+    
+    // start gathering statistics
+    Info::startMetrics();    
 
     // just to make php use &amp; as the separator when adding the PHPSESSID
     // variable to our requests
@@ -46,7 +49,6 @@
     // give control to the, ehem, controller :)
     $controller->process( HttpVars::getRequest(), "op");	
 
-    // print memory information only if available, and only if we're not resserver.php,
-    // or else we'd break image stuff!
-    if( !strstr($_SERVER["SCRIPT_NAME"], "resserver.php" )) print(Info::getMemoryUsage());  
+    // log statistics, only for debugging purposes
+    Info::logMetrics();
 ?>



More information about the pLog-svn mailing list