#!/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 |