<?php
/**
* Benchmark
*
* Online documentation at http://www.drlongghost.com/code/benchmarking
*
* This singleton class handles logging method execution time to a file for later analysis
* via Awk using something similar to the following:
* awk '{ tot1 += $1; tot2 += $2; tot3 += $3 } END { print "---- Col1 ----\naverage: ", tot1/NR, " samples: ", NR,"\n---- Col2 ----\naverage: ", tot2/NR, " samples: ", NR,"\n---- Col3 ----\naverage: ", tot3/NR, " samples: ", NR }' /tmp/benchmark_analysis.tsv
*
* This module is intended to allow a developer to place a series of Benchmark::timerStart() and Benchmark::timerEnd()
* calls throughout a program so that multiple iterations of the program will each log to a file.
* This file can then be analyzed via Awk to determine that, for example, out of 1,000 iterations
* of a page/process running, a particular SELECT statement took *on average* 0.005 seconds
* while a particular INSERT averaged 0.17 seconds.
*
* @author DrLongGhost
* @version 1.0.0
* @license http://www.opensource.org/licenses/mit-license.php The MIT License
*/
class Benchmark {
/**
* @var string Filename containing the execution time data for analysis
*/
public static $logFilename = '/tmp/benchmark_analysis.tsv';
/**
* @var string Filename containing a list of the processes which are being timed.
*/
public static $headerFilename = '/tmp/benchmark_headers.tsv';
/**
* @var boolean Allows the output from printStats() to manually suppressed
*/
public static $suppressPrintStatsOutput = false;
/**
* @var array Stores all the items which are being timed
*/
private static $_timers = array();
/**
* @var string Stores the contents of the log file
*/
private static $_logContents = null;
/**
* @var string Stores the contents of the header file
*/
private static $_headerContents = null;
/**
* @var integer Ensures each manually injected value has a unique array index in the $_timers array
*/
private static $_injectedCounter = 0;
/**
* injectValue
*
* Call this method to manually inject a value or statistic into a benchmark data file.
* This allows you to keep track of which a_ids particular benchmarks applied to, for example.
* @param string The value to be printed to the benchmark data file
* @param string A longer description which will be used to describe what you had injected
*/
public function injectValue($value, $description) {
$timerId = "manually_injected_item_" . ++self::$_injectedCounter;
self::$_timers[$timerId] = array(
'id' => $timerId,
'description' => $description,
'injected' => $value,
);
}
/**
* printStats
*
* Call this method at the end of your script once all timers have been closed with timerEnd()
* to append the stats from all completed timers into the statistics file.
*/
public function printStats() {
if (self::$suppressPrintStatsOutput) return;
foreach(self::$_timers as $timer) {
if (!empty($timer['injected'])) {
self::$_logContents .= $timer['injected']."\t";
self::$_headerContents .= $timer['description']."\t";
} else if (!empty($timer['elapsed'])) {
self::$_logContents .= $timer['elapsed']."\t";
self::$_headerContents .= $timer['description']."\t";
}
}
self::$_logContents .= "\n";
self::$_headerContents .= "\n";
// Append stats to our stats file
if ($log = fopen(self::$logFilename, 'a')) {
if (fwrite($log, self::$_logContents)===false) {
trigger_error('[' . __FUNCTION__ . "] Could not write to {self::$logFilename}.", E_USER_WARNING);
} else {
fclose($log);
}
} else {
trigger_error('[' . __FUNCTION__ . "] Could not fopen('{self::$logFilename}', 'a').", E_USER_WARNING);
}
// Append headers to our header file
if (!file_exists(self::$headerFilename)) {
if ($headerFile = fopen(self::$headerFilename, 'a')) {
if (fwrite($headerFile, self::$_headerContents)===false) {
trigger_error('[' . __FUNCTION__ . "] Could not write to {self::$headerFilename}.", E_USER_WARNING);
} else {
fclose($headerFile);
}
} else {
trigger_error('[' . __FUNCTION__ . "] Could not fopen('{self::$headerFilename}', 'a').", E_USER_WARNING);
}
}
// Reset all timers for the next run
self::reset();
}
/**
* reset
*
* Call this method before calling any timerStart() methods inside a given run of a script
* if it's possible that a previous iteration had ended early and left orphaned stats inside
* the @timers object
*/
public function reset() {
// Reset all timers for the next run
self::$_timers = null;
self::$_logContents = null;
self::$_headerContents = null;
}
/**
* timerEnd
*
* Call this method to stop a timer and calculate the elapsed time from Start to End.
* This method accepts 1 argument:
* @param string The same identifier you passed to the timerStart method
*/
public function timerEnd($timerId) {
if (!isset($timerId) || !isset(self::$_timers[$timerId])) return false;
self::$_timers[$timerId]['end'] = microtime();
self::$_timers[$timerId]['elapsed'] = self::_microtimeDiff(self::$_timers[$timerId]['start'], self::$_timers[$timerId]['end']);
}
/**
* timerStart
*
* Call this method to start a timer.
* Example: Benchmark::timerStart( 'proc1', 'SELECT lead data from App Database');
* @param string A short identifier you will pass to the timerEnd method to end the timer
* @param string A longer description which will be used to describe what process is actually being timed
*/
public function timerStart ($timerId, $description) {
if (!$timerId) return false;
self::$_timers[$timerId] = array(
'id' => $timerId,
'description' => $description,
'start' => microtime(),
);
}
/**
* _microtimeDiff
*
* Calculate a precise time difference without losing precision.
* @param string $start result of microtime()
* @param string $end result of microtime(); if NULL/FALSE/0/'' then it's now
* @return flat difference in seconds, calculated with minimum precision loss
*/
private function _microtimeDiff( $start, $end=null ) {
if (!$end) {
$end = microtime();
}
list($startUsec, $startSec) = explode(" ", $start);
list($endUsec, $endSec) = explode(" ", $end);
$diffSec= intval($endSec) - intval($startSec);
$diffUsec= floatval($endUsec) - floatval($startUsec);
return floatval( $diffSec ) + $diffUsec;
}
}
?>