[pLog-svn] r2887 - in plog/trunk: . class/cache
class/database/pdb/drivers class/misc config
Jon Daley
plogworld at jon.limedaley.com
Mon Feb 20 16:01:34 GMT 2006
I see the log file that it makes, and notice the recent trackbacks
to your blog - that also caused a CPU spike. I was reading an article
that was talking about making rss feeds go slower/less priority, since
people don't really care so much about how fast an RSS feed takes to load,
at least not usually. The same sort of goes for trackbacks too, I guess,
though maybe it depends on how it is done. If the trackback could respond
back to the client success and then work on adding it, I don't know if
that is possible or desired.
Presumably the trackbacks you just got were spam, particularly
since there was a handful of them. I wonder what the spammer did to cause
the trackback to take so long in executing.
On Thu, 2 Feb 2006, oscar at devel.lifetype.net wrote:
> 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();
> ?>
>
> _______________________________________________
> pLog-svn mailing list
> pLog-svn at devel.lifetype.net
> http://devel.lifetype.net/mailman/listinfo/plog-svn
>
**************************************
Jon Daley
http://jon.limedaley.com/
He who asks is a fool for five minutes,
but he who does not ask remains a fool forever.
-- Chinese proverb
More information about the pLog-svn
mailing list