[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 & 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