#!/usr/bin/env php \n\n\n"); fwrite($htmlFh, "\n"); fwrite($htmlFh, "\n"); fwrite($htmlFh, "Average Wait
\n"); fwrite($htmlFh, "Read/Write Percentage
\n"); fwrite($htmlFh, "Start/End Time
\n"); fwrite($htmlFh, "Longest Compute Phases
\n"); fwrite($htmlFh, "Most I/O
\n"); fwrite($htmlFh, "Longest Lock Hold Times
\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); // close output file and db print "Done!\n\n"; fwrite($htmlFh,"\n"); fclose( $outFh ); fclose( $htmlFh ); $db->close(); } /** * Execute SQL and write it to a file handler */ function exec_log_sql($db, $sqlFh, $sql) { /* echo $sql; */ fwrite( $sqlFh, $sql."\n"); $db->exec($sql); } /** * Print command help */ function prt_help() { $help = "\nlog_analyzer revision " . '$Change: 7621 $'; $help .= "\n" . str_repeat( "-", strlen( $help ) ) . "\n\n"; $help .= "log_analyzer takes a VTRACK log file (server version 2005.2 \n" . "or greater) as input, and produces an SQL file, sqlite3 database, \n" . "and a formatted text report as output.\n" . "For more information, such as the schema and example queries,\n" . "visit: \n\n " . "http://public.perforce.com/guest/stewart_lord/track2sql/README\n\n" . "Usage: \n " . "php log_analyzer.php [ logFile ] [ sqlFile ] [ dbFile ] [ outFile ] [ stateFile ]\n\n" . " Options: \n" . " logFile name of input log file \n" . " sqlFile name of output SQL file \n" . " dbFile name of database file to create \n" . " outFile name of output report file \n" . " stateFile name of output state file, useful for repeat runs \n" . " -v|V|h view version and usage information \n\n" . " Examples: \n" . " $ track2sql.php log.txt track.sql track.db track.txt track.state\n\n"; echo $help; } /** * 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, "

LONGEST COMPUTE PHASES

\n"); fwrite( $htmlFh, "\n\n\n\n\n\n"); fwrite( $htmlFh, "\n\n\n\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, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); } fwrite( $htmlFh, "
userclientcommanddatecompute (ms)argsprocess
$row[3]$row[1]$row[4]$row[5]$row[6]$row[2]$row[0]
\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, "

MOST I/O

\n"); fwrite( $htmlFh, "\n\n\n\n\n"); fwrite( $htmlFh, "\n\n\n\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, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); } fwrite( $htmlFh, "
userclientcommandpagesargsprocess
$row[0]$row[4]$row[1]$row[2]$row[5]$row[3]
\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, "

Average wait (ms)

\n"); while ($row = $results->fetchArray(SQLITE3_NUM)) { fwrite( $outFh, sprintf("%f\n", $row[0])); fwrite( $htmlFh, "
$row[0]\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, "

Read/write percentage

\n"); while ($row = $results->fetchArray(SQLITE3_NUM)) { fwrite( $outFh, sprintf("%f\t%f\n", $row[0],$row[1])); fwrite( $htmlFh, "
$row[0]
$row[1]\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, "

LONGEST LOCK HOLD TIMES

\n"); fwrite( $htmlFh, "\n\n\n\n\n"); while ($row = $results->fetchArray(SQLITE3_NUM)) { fwrite( $outFh, sprintf("%30s %15.1f\n", $row[0], $row[1])); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); fwrite( $htmlFh, "\n"); } fwrite( $htmlFh, "
userhold time (ms)
$row[0]$row[1]
\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 FROM process"; // execute the sql statement $results = $db->query( $sql ); fwrite( $outFh, "------------------------------------------------------------\n"); fwrite( $outFh, "Start/end time\n"); fwrite( $htmlFh, "

Start/end time

\n"); while ($row = $results->fetchArray(SQLITE3_NUM)) { fwrite( $outFh, sprintf("%s\t%s\n", $row[0],$row[1])); fwrite( $htmlFh, "
$row[0]
$row[1]\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 ); } // 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 ) . "'"; } ?>