#!/usr/bin/env php
<?php
/**
* $Id: //guest/perforce_software/utils/log_analyzer/log_analyzer.php#3 $
* $DateTime: 2014/10/20 16:50:39 $
* $Author: lester_cheung $
*
* Copyright (c) 2008-2012, Perforce Software, Inc. All rights reserved.
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions are met:
*
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
*
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
*
* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
* AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL PERFORCE SOFTWARE, INC. BE LIABLE FOR ANY
* DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
* (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
* LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
* ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
* (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
* THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
*
*
* log_analyzer.php
* ---------------------------
*
* log_analyzer takes a VTRACK log file as input, and produces a
* formatted text report listing the commands with longest compute
* phases, longest database lock times, and so on.
*
* log_analyzer uses sqlite3 as its database, and leaves the
* sqlite3 database file for future reference.
*
* log_analyzer is based on track2sql, with a modified table
* definitions to speed up SQL queries.
*
* Requires the SQLite3 PHP package, which is standard as of PHP 5.3.
*
* See also: http://public.perforce.com/guest/stewart_lord/track2sql/README
*
*
* U S A G E
* -----------
*
* php log_analyzer.php [options] < logFile|- >
*
* See "php log_analyzer.php -h" for details.
*
* Examples:
* $ zcat log.gz | log_analyzer.php -b logrpt -
*
*
* O U T P U T
* -------------
*
* The main output is a formatted text file with several
* canned queries.
*
* Also produces an SQL file and database with the following
* tables:
*
* +------------+---------------+------+-----+
* | P R O C E S S |
* +------------+---------------+------+-----+
* | Field | Type | Null | Key |
* +------------+---------------+------+-----+
* | processKey | int | NO | YES |
* | time | int(11) | NO | |
* | pid | int(11) | NO | |
* | user | varchar(255) | NO | |
* | client | varchar(255) | NO | |
* | ip | varchar(255) | NO | |
* | app | varchar(255) | NO | |
* | cmd | varchar(255) | NO | |
* | args | text | YES | |
* | lapse | decimal(10,3) | YES | |
* | uCpu | int(11) | YES | |
* | sCpu | int(11) | YES | |
* | diskIn | int(11) | YES | |
* | diskOut | int(11) | YES | |
* | ipcIn | int(11) | YES | |
* | ipcOut | int(11) | YES | |
* | maxRss | int(11) | YES | |
* | pageFaults | int(11) | YES | |
* | rpcMsgsIn | int(11) | YES | |
* | rpcMsgsOut | int(11) | YES | |
* | rpcSizeIn | int(11) | YES | |
* | rpcSizeOut | int(11) | YES | |
* +------------+---------------+------+-----+
*
* +-------------+--------------+------+-----+
* | T A B L E U S E |
* +-------------+--------------+------+-----+
* | Field | Type | Null | Key |
* +-------------+--------------+------+-----+
* | processKey | int | NO | YES |
* | tableName | varchar(255) | NO | YES |
* | pagesIn | int(11) | YES | |
* | pagesOut | int(11) | YES | |
* | pagesCached | int(11) | YES | |
* | readLocks | int(11) | YES | |
* | writeLocks | int(11) | YES | |
* | getRows | int(11) | YES | |
* | posRows | int(11) | YES | |
* | scanRows | int(11) | YES | |
* | putRows | int(11) | YES | |
* | delRows | int(11) | YES | |
* | readWait | int(11) | YES | |
* | readHeld | int(11) | YES | |
* | writeWait | int(11) | YES | |
* | writeHeld | int(11) | YES | |
* +-------------+--------------+------+-----+
*
*/
ini_set("memory_limit","2G"); // the more the better - just in case
// the sqlite module needs it (it
// shouldn't). ;-)
// relax error reporting to suppress notices.
error_reporting( E_ALL & ~E_NOTICE );
// set default timezone to silence warnings when using date/time funcs.
date_default_timezone_set('UTC');
main( $argv, $argc ); // run it!
/**
* The main function.
* loops over input file - writes to output file.
*
* @param array argv the options given to dictate behavior.
* @param int argc the number of arguments.
*/
function main( $argv, $argc )
{
// Defaults
$cfg = array('sql' => false,
'force' => false,
'append' => false,
'basename' => 'logrpt' // prefix for auto-generated output files.
);
$shortopts = 'hqfab:s:d:o:H:S:';
$operand_pos = 1;
foreach ( getopt($shortopts) as $opt => $val) {
switch ($opt) {
case 'q':
$cfg['quiet'] = true;
$operand_pos++;
break;
case 'f':
$cfg['force'] = true;
$operand_pos++;
break;
case 'a':
$cfg['append'] = true;
$operand_pos++;
break;
case 'b':
$cfg['basename'] = $val;
$operand_pos += 2;
break;
case 's':
$cfg['sql'] = $val;
$operand_pos += 2;
break;
case 'd':
$cfg['db'] = $val;
$operand_pos += 2;
break;
case 'o':
$cfg['rpt'] = $val;
$operand_pos += 2;
break;
case 'H':
$cfg['rpt.html'] = $val;
$operand_pos += 2;
break;
case 'S':
$cfg['statefile'] = $val;
$operand_pos += 2;
break;
case 'h':
$printHelp = true;
$operand_pos++;
break;
}
}
$cfg['logfiles'] = array_slice($argv, $operand_pos);
if(!isset($cfg['db'])) { $cfg['db'] = $cfg['basename'].'.db'; }
if(!isset($cfg['rpt'])) { $cfg['rpt'] = $cfg['basename'].'.txt'; }
if(!isset($cfg['rpt.html'])) { $cfg['rpt.html'] = $cfg['basename'].'.html'; }
if(!isset($cfg['state'])) { $cfg['state'] = $cfg['basename'].'.state'; }
if(!isset($cfg['badlog'])) { $cfg['badlog'] = $cfg['basename'].'.badlog.gz'; }
if($printHelp) { help($cfg); }
// remove output files if exists
if ($cfg['force']) {
if (is_file($cfg['db']))
unlink($cfg['db']);
if (is_file($cfg['rpt']))
unlink($cfg['rpt']);
if (is_file($cfg['rpt.html']))
unlink($cfg['rpt.html']);
if (is_file($cfg['state']))
unlink($cfg['state']);
if (is_file($cfg['badlog']))
unlink($cfg['badlog']);
}
global $badlogFh;
if (is_file($cfg['badlog'])) {
$badlogFh = gzopen($cfg['badlog'], "a+");
} else {
$badlogFh = gzopen($cfg['badlog'], "w");
}
echo "Writing ignored lines to ".$cfg['badlog'].".\n";
if (is_file($cfg['state'])) {
try {
$processKey = trim(fgets(fopen($cfg['state'], "r")));
} catch (Exception $e) {
echo "Problem reading $statefile, using 1 instead. ($e)";
$processKey = 1; /* default */
}
} else { $processKey = 1; }
if (!$cfg['quiet'])
echo "Using $processKey as the next \$processKey.\n";
$sqlfile = $cfg['sql'];
$opt_fb_text = " Use the -f option to overwrite it or use the -b option to specify a different prefix.\n";
if ( is_file($sqlfile) && !$cfg['force'] ) {
die ("$sqlfile exists!".$opt_fb_text);
}
if ($sqlfile && !$cfg['quiet']) { echo "Writing SQL to file $sqlfile\n"; }
$dbfile = $cfg['db'];
if ( is_file($dbfile) && !$cfg['append'] ) {
die ("$dbfile exists! Either remove the file or append to the file with the -a option.\n");
}
if (!$cfg['quiet'])
echo "Creating/writing to sqlite3 db ", $dbfile, ".\n";
$rptfile = $cfg['rpt'];
$htmlrptfile = $cfg['rpt.html'];
if ( (is_file($rptfile) || is_file($htmlrptfile)) && !$cfg['force']) {
die ("Either $rptfile or $htmlrptfile exists!".$opt_fb_text);
}
if (!$cfg['quiet'])
echo "Writing report to $rptfile and $htmlrptfile.\n";
$sqlfile = $cfg['sql'];
if ( is_file($sqlfile) && !$cfg['force']) {
die ("$sqlfile exists!".$opt_fb_text);
}
if ($sqlfile) {
$sqlFh = fopen( $sqlfile, 'a' );
if ( !is_resource( $sqlFh ) )
die( "Error: Unable to open SQL output stream.\n" );
} else {
$sqlFh = false;
}
// open database
$db = new SQLite3($dbfile);
// SQLite tuning...
exec_log_sql($db, $sqlFh, 'PRAGMA page_size=65536;'); // 64KiB - max page size
exec_log_sql($db, $sqlFh, 'PRAGMA cache_size=-2097152;'); // 2GiB cache
exec_log_sql($db, $sqlFh, 'PRAGMA synchronous=0;'); // no fsync thank you very much
exec_log_sql($db, $sqlFh, 'PRAGMA temp_store = MEMORY;'); // avoid on disk temp storage
exec_log_sql($db, $sqlFh, 'PRAGMA journal_mode=OFF;'); // not writing (slow) journal
// write out the create table statements.
exec_log_sql($db, $sqlFh, getCreateStatements());
// the big loop.....
foreach($cfg['logfiles'] as $logfile) {
if ($logfile == '-') { $logfile = 'php://stdin'; }
$processKey = ingest($logfile, $db, $sqlFh, $processKey, $cfg);
}
$outFh = fopen( $cfg['rpt'], 'w' );
$htmlFh = fopen( $cfg['rpt.html'], 'w' );
if ( !is_resource( $outFh ) )
die( "Error: Unable to open report output stream.\n" );
if ( !is_resource( $htmlFh ) )
die( "Error: Unable to open HTML report output stream.\n" );
// write out state file
fwrite(fopen($cfg['state'], "w"), "$processKey\n");
// create index
if (!$cfg['append']) {
if (!$cfg['quiet'])
print "Creating index on table process...\n";
exec_log_sql($db, $sqlFh,
'CREATE INDEX IF NOT EXISTS idx_p_process_key ON process (processKey);');
if (!$cfg['quiet'])
print "Creating index on table tableUse... ";
exec_log_sql($db, $sqlFh,
'CREATE INDEX IF NOT EXISTS idx_t_processkey ON tableUse (processKey);');
exec_log_sql($db, $sqlFh,
'CREATE INDEX IF NOT EXISTS idx_t_tablename ON tableUse (tableName);');
exec_log_sql($db, $sqlFh,
'CREATE INDEX IF NOT EXISTS idx_t_readheld ON tableUse (readHeld);');
exec_log_sql($db, $sqlFh,
'CREATE INDEX IF NOT EXISTS idx_t_writeheld ON tableUse (writeHeld);');
}
if (!$cfg['quiet'])
echo "Done!\n";
if (is_resource( $sqlFh ) )
fclose( $sqlFh );
// run queries
if (!$cfg['quiet'])
echo "Running queries...\n\n";
fwrite($htmlFh,"<html>\n<head>\n</head>\n");
fwrite($htmlFh, "<style TYPE='text/css'>\n" .
"table {\n\t" .
"border:1px solid;\n" .
"border-collapse:collapse;\n" .
"}\n" .
"table td {\n\t" .
"border:1px solid;\n" .
"background-color:white;\n" .
"}\n" .
"table th {\n\t" .
"border:1px solid;\n" .
"background-color:blue;\n" .
"color:white;\n" .
"}\n" .
"</style>\n");
fwrite($htmlFh, "<body>\n");
fwrite($htmlFh, "<a href='#avgwait'>Average Wait</a><br>\n");
fwrite($htmlFh, "<a href='#readpct'>Read/Write Percentage</a><br>\n");
fwrite($htmlFh, "<a href='#startend'>Start/End Time</a><br>\n");
fwrite($htmlFh, "<a href='#compute'>Longest Compute Phases</a><br>\n");
fwrite($htmlFh, "<a href='#mostio'>Most I/O</a><br>\n");
fwrite($htmlFh, "<a href='#held'>Longest Lock Hold Times</a><br>\n");
fwrite($htmlFh, "<a href='#peakhours'>Peak hours</a><br>\n");
rpt_avg_wait($db,$outFh,$htmlFh);
rpt_read_pct($db,$outFh,$htmlFh);
rpt_start_end($db,$outFh,$htmlFh);
rpt_long_computes($db,$outFh,$htmlFh);
rpt_most_io($db,$outFh,$htmlFh);
rpt_held_time($db,$outFh,$htmlFh);
rpt_peak_hours($db,$outFh,$htmlFh);
// close output file and db
if (!$cfg['quiet'])
print "Done!\n\n";
fwrite($htmlFh,"</body>\n</html>");
fclose( $outFh );
fclose( $htmlFh );
if ( is_resource($sqlFh) ) { fclose($sqlFh); }
$db->close();
}
function ingest($logfile, &$db, &$sqlFh, $processKey, &$cfg)
{
$started = time();
// open the files and test handles.
$in = gzopen( $logfile, 'r' );
if ( !is_resource( $in ) )
die( "Error: Unable to open $logfile.\n" );
if (!$cfg['quiet'])
echo "Processing $logfile... ";
// do all inserts in a (possibly huge) transaction!
exec_log_sql($db, $sqlFh, 'BEGIN TRANSACTION;');
// start reading lines - recognize 'info' blocks, buffer and parse them.
while ( $line = gzgets( $in ) )
{
// Some P4V sends version strings with NULL chars in places
// where slashes should be used, we are working around it by
// replacing all NULL chars to slashes. ;-)
// See job037665 for details.
$line = str_replace("\0", "/", $line);
// if not inside info block, look for start of block.
if ( !$inInfo )
{
if ( isInfoStart( $line ) )
$inInfo = TRUE;
}
// if inside info block, buffer and look for end of block.
else if ( $inInfo )
{
if ( isInfoEnd( $line ) )
{
$sql = parseInfo( $buffer, $processKey++ );
if ( $sql ) {
exec_log_sql($db, $sqlFh, $sql);
}
if ( !isInfoStart( $line ) )
$inInfo = FALSE;
$buffer = NULL;
} else {
$buffer .= $line;
}
}
}
fclose( $in );
if (!$cfg['quiet'])
print "committing... ";
exec_log_sql( $db, $sqlFh, 'COMMIT;');
if (!$cfg['quiet'])
echo "took ", time()-$started," seconds.\n";
return $processKey;
}
/**
* Execute SQL and write it to a file handler
*/
function exec_log_sql($db, &$sqlFh, $sql) {
if ($sqlFh)
fwrite( $sqlFh, $sql."\n");
$db->exec($sql);
}
/**
* Print command help
*/
function help($cfg)
{
$basename = $cfg['basename'];
$db = $cfg['db'];
$rpt = $cfg['rpt'];
$htmlrpt = $cfg['rpt.html'];
$sql = $cfg['sql'];
$state = $cfg['state'];
die("
Perforce Server Log Analyzer - a tool based on TRACK2SQL.
Usage: $argv[0] [OPTION]... < logfile|- > [logs...]
-h: this help.
-q: be quiet.
-f: overwrites any existing output files.
-a: appends data to the SQLite database.
-b: prefix used to auto-generate output names below. Defaults
to '$basename'.
-d: name of the generated SQLite3 database. Defaults to '$db'.
-o: name of generated report, in plain-text. Defaults to
'$rpt'.
-H: name of generated report, in HTML. Defaults to '$htmlrpt'.
-s: writes generated SQL to file. Not created by default.
-S: name of a file that keeps the last processKey
used. Defaults to '$state'.
Note that combining options (like \"-qb foo\") is not supported. Patch welcome!
Examples:
log_analyzer.php -b logrpt log0.gz log1.gz
xzcat log.xz log1.xz| log_analyzer.php -b logrpt -
");
}
/**
* Runs query for 25 longest compute phases
*/
function rpt_long_computes($db,$outFh,$htmlFh)
{
$sql = "
SELECT
process.processKey,
process.client,
process.args,
user,
cmd,
datetime(time, 'unixepoch') AS time,
CASE WHEN MAX( readHeld + writeHeld ) > MAX( readWait + writeWait ) THEN
MAX( readHeld + writeHeld ) - MAX( readWait + writeWait )
ELSE
MAX( readHeld + writeHeld )
END
AS compute
FROM tableUse JOIN process USING (processKey)
GROUP BY tableUse.processKey
ORDER BY compute DESC LIMIT 25";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "LONGEST COMPUTE PHASES\n");
fwrite( $outFh, sprintf("%20s %30s %30s %25s %15s\n", "user", "client", "command", "date", "compute (ms)"));
fwrite( $htmlFh, "<h1>LONGEST COMPUTE PHASES</h1><a name='compute'></a>\n");
fwrite( $htmlFh, "<table>\n<tr>\n<th>user</th>\n<th>client</th>\n<th>command</th>\n<th>date</th>\n");
fwrite( $htmlFh, "<th>compute (ms)</th>\n<th>args</th>\n<th>process</th>\n</tr>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%20s %30s %30s %25s %15.1f\n", $row[3], $row[1], $row[4], $row[5], $row[6]));
fwrite( $htmlFh, "<tr>\n");
fwrite( $htmlFh, "<td>$row[3]</td>\n");
fwrite( $htmlFh, "<td>$row[1]</td>\n");
fwrite( $htmlFh, "<td>$row[4]</td>\n");
fwrite( $htmlFh, "<td>$row[5]</td>\n");
fwrite( $htmlFh, "<td>$row[6]</td>\n");
fwrite( $htmlFh, "<td>$row[2]</td>\n");
fwrite( $htmlFh, "<td>$row[0]</td>\n");
fwrite( $htmlFh, "</tr>\n");
}
fwrite( $htmlFh, "</table>\n");
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Runs query for most i/o
*/
function rpt_most_io($db,$outFh,$htmlFh)
{
$sql = "
SELECT
user,cmd,SUM(pagesIn+pagesOut) as io, process.processKey, process.client, process.args
FROM tableUse JOIN process USING (processKey)
GROUP BY tableUse.processKey ORDER BY io
DESC LIMIT 25";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "MOST I/O\n");
fwrite( $outFh, sprintf("%20s %30s %30s %12s\n", "user", "client", "command", "pages"));
fwrite( $htmlFh, "<h1>MOST I/O</h1><a name='mostio'></a>\n");
fwrite( $htmlFh, "<table>\n<tr>\n<th>user</th>\n<th>client</th>\n<th>command</th>\n");
fwrite( $htmlFh, "<th>pages</th>\n<th>args</th>\n<th>process</th>\n</tr>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%20s %30s %30s %12d\n", $row[0], $row[4], $row[1], $row[2]));
fwrite( $htmlFh, "<tr>\n");
fwrite( $htmlFh, "<td>$row[0]</td>\n");
fwrite( $htmlFh, "<td>$row[4]</td>\n");
fwrite( $htmlFh, "<td>$row[1]</td>\n");
fwrite( $htmlFh, "<td>$row[2]</td>\n");
fwrite( $htmlFh, "<td>$row[5]</td>\n");
fwrite( $htmlFh, "<td>$row[3]</td>\n");
fwrite( $htmlFh, "</tr>\n");
}
fwrite( $htmlFh, "</table>\n");
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Runs query for average wait time
*/
function rpt_avg_wait($db,$outFh,$htmlFh)
{
$sql = "
SELECT
AVG(readWait+writeWait) as wait FROM tableUse";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "Average wait (ms)\n");
fwrite( $htmlFh, "<h1>Average wait (ms)</h1><a name='avgwait'></a>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%f\n", $row[0]));
fwrite( $htmlFh, "<br><b>$row[0]</b>\n");
}
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Runs query for read/write percentage
*/
function rpt_read_pct($db,$outFh,$htmlFh)
{
$sql = "
SELECT
CAST(SUM(pagesIn) as float)/CAST(SUM(pagesIn+pagesOut) as float) * CAST(100 as float) as readPct,
CAST(SUM(pagesOut) as float)/CAST(SUM(pagesIn+pagesOut) as float) * CAST(100 as float) as writePct
FROM tableUse";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "Read/write percentage\n");
fwrite( $htmlFh, "<h1>Read/write percentage</h1><a name='readpct'></a>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%f\t%f\n", $row[0],$row[1]));
fwrite( $htmlFh, "<br><b>$row[0]</b><br><b>$row[1]</b>\n");
}
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Runs query for 25 longest lock holds
*/
function rpt_held_time($db,$outFh,$htmlFh)
{
$sql = "
SELECT
user,SUM(readHeld+writeHeld) as held
FROM tableUse JOIN process USING (processKey)
GROUP BY user ORDER BY held DESC LIMIT 25";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "LONGEST LOCK HOLD TIMES\n");
fwrite( $outFh, sprintf("%30s %15s\n", "user", "hold time (ms)"));
fwrite( $htmlFh, "<h1>LONGEST LOCK HOLD TIMES</h1><a name='held'></a>\n");
fwrite( $htmlFh, "<table>\n<tr>\n<th>user</th>\n<th>hold time (ms)</th>\n</tr>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%30s %15.1f\n", $row[0], $row[1]));
fwrite( $htmlFh, "<tr>\n");
fwrite( $htmlFh, "<td>$row[0]</td>\n");
fwrite( $htmlFh, "<td>$row[1]</td>\n");
fwrite( $htmlFh, "</tr>\n");
}
fwrite( $htmlFh, "</table>\n");
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Runs query for log start/end
*/
function rpt_start_end($db,$outFh,$htmlFh)
{
$sql = "
SELECT
datetime(MIN(time), 'unixepoch') AS start,
datetime(MAX(time), 'unixepoch') AS end,
MAX(time)-MIN(time) FROM process";
// execute the sql statement
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n");
fwrite( $outFh, "Start/end time\n");
fwrite( $htmlFh, "<h1>Start/end time</h1><a name='startend'></a>\n");
fwrite( $htmlFh, "<table><tr><th>started</th><th>ended</th><th>lapsed</th></tr>\n");
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%s\t%s\n", $row[0],$row[1]));
// FIXME :)
$lapsed = $row[2];
$unit = 'second(s)';
if ($lapsed/60 >= 1) {
$lapsed = $lapsed/60;
$unit = 'minute(s)';
if ($lapsed/60 >= 1) {
$lapsed = $lapsed/60;
$unit = 'hour(s)';
if ($lapsed/24>=1) {
$lapsed = $lapsed/24;
$unit = 'day(s)';
if ($lapsed/7>=1) {
$lapsed = $lapsed/7;
$unit = 'week(s)';
}
}
}
}
fwrite( $htmlFh, "<tr><td>$row[0]</td><td>$row[1]</td><td>$lapsed $unit</td></tr>\n");
}
fwrite( $htmlFh, "</table>\n" );
fwrite( $outFh, "------------------------------------------------------------\n\n\n");
}
/**
* Report the top 20 peak hours
*/
function rpt_peak_hours($db, $outFh, $htmlFh)
{
// FXIME!!!
$sql = "
SELECT datetime(time/3600*3600, 'unixepoch'), count(*)
FROM process
GROUP BY datetime(time/3600*3600, 'unixepoch')
HAVING count(*) IN
(SELECT count(*)
FROM process
GROUP BY datetime(time/3600*3600, 'unixepoch')
ORDER BY count(*) DESC
LIMIT 20)
ORDER BY datetime(time/3600*3600, 'unixepoch')
;
";
$results = $db->query( $sql );
fwrite( $outFh, "------------------------------------------------------------\n" );
fwrite( $outFh, "Top 20 peark hours\n" );
fwrite( $htmlFh, "<h1>Top 20 peak hours</h1><a name='peakhours'></a>\n" );
fwrite( $htmlFh, "<table><tr><th>hour</th><th>commands</th></tr>\n" );
while ($row = $results->fetchArray(SQLITE3_NUM)) {
fwrite( $outFh, sprintf("%s\t%s\n", $row[0], $row[1]) );
fwrite( $htmlFh, "<tr><td>$row[0]</td><td>$row[1]</td></tr>" );
}
fwrite( $htmlFh, "</table>\n" );
fwrite( $outFh, "------------------------------------------------------------\n\n\n" );
}
/**
* Quick test for the beginning of an info block.
*
* @param string line the line to test.
* @return bool the result of the test.
*/
function isInfoStart( $line )
{
if ( ( $line === "Perforce server info:\n" ) or
( $line === "Perforce server info:\r\n" ) )
return TRUE;
}
/**
* Quick test for the end of an info block.
*
* @param string line the line to test.
* @return bool the result of the test.
*/
function isInfoEnd( $line )
{
if ( !trim( $line ) || isInfoStart( $line ) )
return TRUE;
}
/**
* Extract track information from info block.
*
* @param string info the info block to parse.
*/
function parseInfo( $info, $processId )
{
// early exit if not track output.
if ( !isTrackOutput( $info ) ) return;
// lcheung - uuid is good however it's slow(er) to use a string as
// primary key
/* // manufacture a key for joining process */
/* // and table records. */
/* $key = quote( makeProcessKey() ); */
$key = $processId; /* so we use an integer instead. ;-) */
// build the process record.
$processInfo = extractProcessInfo( $info );
$sql =
"INSERT INTO process " .
"VALUES ( " . $key . "," . implode( ",", $processInfo ) . " );\n";
// build the table records.
$tablesInfo = extractTablesInfo( $info );
if ( !is_array( $tablesInfo ) ) return $sql;
foreach ( $tablesInfo as $tableInfo )
{
$sql .=
"INSERT INTO tableUse " .
"VALUES ( " . $key . "," . implode( ",", $tableInfo ) . ");\n";
}
// return the sql.
return $sql;
}
/**
* Test if the given string looks like vtrack output
* with a complete process information line.
*
* @param string info the info block to test.
* @return bool true if the info block appears to be usable track output.
*/
function isTrackOutput( $info )
{
return ( strpos( $info, "\n--- " ) !== FALSE &&
strpos( substr( $info, 0, strpos( $info, "\n" ) ), "@" ) !== FALSE );
}
/**
* Make a unique key (UUID) for joining processes and table use records.
*
* @return string a UUID to use as a process key.
*/
function makeProcessKey()
{
$chars = md5( uniqid( mt_rand(), TRUE ) );
$uuid = substr( $chars, 0, 8 ) . '-';
$uuid .= substr( $chars, 8, 4 ) . '-';
$uuid .= substr( $chars, 12, 4 ) . '-';
$uuid .= substr( $chars, 16, 4 ) . '-';
$uuid .= substr( $chars, 20, 12 );
return $uuid;
}
/**
* Take a vtrack block, and extract process information.
* Resulting array contains 21 elements (quoted where appropriate).
*
* @param string track the vtrack output to parse.
* @return array the exploded process information.
*/
function extractProcessInfo( $track )
{
// break into lines.
$lines = explode( "\n", $track );
// pull apart the first line.
$parts = explode( " ", trim( $lines[0] ), 7 );
list( $user, $client ) = explode( "@", $parts[4], 2 );
list( $app, $command ) = explode( "] '", $parts[6], 2 );
list( $cmd, $args ) = explode( " ", $command, 2 );
$process[] = strtotime( $parts[0] . " " . $parts[1] );
$process[] = intval( $parts[3] );
$process[] = quote( trim( $user ) );
$process[] = quote( trim( $client ) );
$process[] = quote( trim( $parts[5] ) );
$process[] = quote( substr( $app, 1 ) );
if ( $args )
{
$process[] = quote( $cmd );
$process[] = quote( substr( $args, 0, -1 ) );
} else {
$process[] = quote( substr( $cmd, 0, -1 ) );
$process[] = "NULL";
}
// search the next three lines for lapse, usage and rpc.
// -> only first could be lapse.
// -> first or second could be usage.
// -> anyone could be rpc.
for ( $i = 1; ( $i < 4 ) && ( $i < count( $lines ) ); $i++ )
{
if ( $i == 1 && substr( $lines[ $i ], 0, 10 ) == "--- lapse " )
$lapseTime = trim( $lines[ $i ] );
else if ( $i < 3 && substr( $lines[ $i ], 0, 10 ) == "--- usage " )
$usageStats = trim( $lines[ $i ] );
else if ( substr( $lines[ $i ], 0, 8 ) == "--- rpc " )
$rpcStats = trim( $lines[ $i ] );
}
// insert lapse time into process info array - or pad with 'NULL'.
if ( $lapseTime )
{
$process[] = floatval( substr( $lapseTime, 10, -1 ) );
} else {
$process[] = "NULL";
}
// insert usage stats into process info array - or pad with 'NULL'.
if ( $usageStats )
{
$parts = preg_split( "/ |\+/", $usageStats );
for ( $i = 2; $i < 10; $i++ )
$process[] = intval( $parts[ $i ] );
} else {
for ( $i = 0; $i < 8; $i++ )
$process[] = "NULL";
}
// insert rcp stats into process info array - or pad with 'NULL'.
if ( $rpcStats )
{
$parts = preg_split( "/ |\+|\//", $rpcStats );
for ( $i = 6; $i < 10; $i++ )
$process[] = intval( $parts[ $i ] );
} else {
for ( $i = 0; $i < 4; $i++ )
$process[] = "NULL";
}
// return process info array.
return $process;
}
/**
* Take a vtrack block, and extract tables usage information.
*
* @param string track the vtrack output to parse.
* @return array the exploded tables information.
*/
function extractTablesInfo( $track )
{
// break apart track output on tables.
$blocks = explode( "--- db.", $track );
for ( $i = 1; $i < count( $blocks ); $i++ )
{
$tables[] = extractTableInfo( $blocks[ $i ] );
}
return $tables;
}
/**
* Take a snippet of vtrack, and extract single table usage information.
* Returns an array containing 15 elements.
*
* @param string track the vtrack output to parse.
* @return array the exploded table information.
*/
function extractTableInfo( $track )
{
// break into lines.
$lines = explode( "\n", $track );
// first line is table name.
$table[] = "'" . trim( $lines[0] ) . "'";
// search the next four lines for pages, rows and locks.
// -> only first could be pages.
// -> first, second or third could be rows.
// -> anyone could be locks.
for ( $i = 1; ( $i < 5 ) && ( $i < count( $lines ) ); $i++ )
{
if ( $i == 1 && substr( $lines[ $i ], 0, 14 ) == "--- pages in" )
$pageStats = trim( $lines[ $i ] );
else if ( $i < 4 && substr( $lines[ $i ], 0, 12 ) == "--- locks " &&
substr( $lines[ $i ], 0, 16 ) != "--- locks wait" )
$rowStats = trim( $lines[ $i ] );
else if ( substr( $lines[ $i ], 0, 16 ) == "--- locks wait" )
$lockStats = substr( $lines[ $i ], 33 );
else if ( substr( $lines[ $i ], 0, 16 ) == "--- total lock" )
$lockStats = substr( $lines[ $i ], 38 );
else if ($lines[$i] == "" ) {
continue;
}
else {
global $badlogFh;
fwrite($badlogFh, $lines[$i]."\n");
}
}
// insert page stats into table info array - or pad with 'NULL'.
if ( $pageStats )
{
$parts = preg_split( "/[ |\+]+/", $pageStats );
for ( $i = 5; $i < 8; $i++ )
$table[] = intval( $parts[ $i ] );
} else {
for ( $i = 0; $i < 3; $i++ )
$table[] = "NULL";
}
// insert row stats into table info array - or pad with 'NULL'.
if ( $rowStats )
{
// switch for server version.
// -> 14 parts in 2005.2 track output.
// *read/write locks aren't differentiated.
// -> 17 parts in 2006.1+ track output.
// *read/write locks are broken out.
$parts = preg_split( "/[ |\/|\+]+/", $rowStats );
if ( count( $parts ) == 14 )
{
$table[] = intval( $parts[2] );
$table[] = intval( $parts[2] );
for ( $i = 9; $i < 14; $i++ )
$table[] = intval( $parts[ $i ] );
} else {
$table[] = intval( $parts[4] );
$table[] = intval( $parts[5] );
for ( $i = 12; $i < 17; $i++ )
$table[] = intval( $parts[ $i ] );
}
} else {
for ( $i = 0; $i < 7; $i++ )
$table[] = "NULL";
}
// insert lock stats into table info array - or pad with 'NULL'.
if ( $lockStats )
{
$parts = preg_split( "/[ |\/|\+]+/", $lockStats );
for ( $i = 0; $i < 4; $i++ )
$table[] = intval( $parts[ $i ] );
} else {
for ( $i = 0; $i < 4; $i++ )
$table[] = "NULL";
}
// return table info array.
return $table;
}
/**
* Create process and tableUse tables.
*
* @return string the sql to create the tables.
*/
function getCreateStatements()
{
// create syntax for process table.
$sql =
"CREATE TABLE IF NOT EXISTS process ( \n" .
" processKey INTEGER PRIMARY KEY, \n" .
" time INTEGER NOT NULL, \n" .
" pid INTEGER NOT NULL, \n" .
" user varchar(255) NOT NULL, \n" .
" client varchar(255) NOT NULL, \n" .
" ip varchar(255) NOT NULL, \n" .
" app varchar(255) NOT NULL, \n" .
" cmd varchar(255) NOT NULL, \n" .
" args text NULL, \n" .
" lapse decimal(10,3) NULL, \n" .
" uCpu INTEGER NULL, \n" .
" sCpu INTEGER NULL, \n" .
" diskIn INTEGER NULL, \n" .
" diskOut INTEGER NULL, \n" .
" ipcIn INTEGER NULL, \n" .
" ipcOut INTEGER NULL, \n" .
" maxRss INTEGER NULL, \n" .
" pageFaults INTEGER NULL, \n" .
" rpcMsgsIn INTEGER NULL, \n" .
" rpcMsgsOut INTEGER NULL, \n" .
" rpcSizeIn INTEGER NULL, \n" .
" rpcSizeOut INTEGER NULL \n" .
/* " PRIMARY KEY ( processKey ) \n" . */
"); \n";
// create syntax for tableUse table.
$sql .=
"CREATE TABLE IF NOT EXISTS tableUse ( \n" .
" processKey INTEGER, \n" .
" tableName varchar(255) NOT NULL, \n" .
" pagesIn INTEGER NULL, \n" .
" pagesOut INTEGER NULL, \n" .
" pagesCached INTEGER NULL, \n" .
" readLocks INTEGER NULL, \n" .
" writeLocks INTEGER NULL, \n" .
" getRows INTEGER NULL, \n" .
" posRows INTEGER NULL, \n" .
" scanRows INTEGER NULL, \n" .
" putRows INTEGER NULL, \n" .
" delRows INTEGER NULL, \n" .
" readWait INTEGER NULL, \n" .
" readHeld INTEGER NULL, \n" .
" writeWait INTEGER NULL, \n" .
" writeHeld INTEGER NULL \n" .
/* " PRIMARY KEY ( processKey, tableName ) \n" . */
// not having primary key no key constraint checks!
"); \n";
return $sql;
}
/**
* Quote a string for use as a SQL value. Wraps string in
* single quotes and escapes embedded single quotes with a quote.
*
* @param string value the string to quote.
* @return string the quoted and escaped string.
*/
function quote( $value )
{
return "'" . str_replace( "'", "''", $value ) . "'";
}
?>
| # | Change | User | Description | Committed | |
|---|---|---|---|---|---|
| #4 | 25220 | Robert Cowham |
Moved project files to new location: //guest/perforce_software/log-analyzer/psla/... Required by Swarm project structure for workshop. |
||
| #3 | 10726 | Lester Cheung | Little changes that we have made over the last 2 years ^_^ | ||
| #2 | 8261 | michael | Pull in Lester Cheung's enhancements to log_analyzer.php. | ||
| #1 | 8260 | michael | Move Randy Defauw's log analysis script into //public/perforce/utils/. | ||
| //guest/randy_defauw/log_analyzer/log_analyzer.php | |||||
| #1 | 8073 | Randy DeFauw | standalone log analyzer file based on Track2SQL | ||