Skip to content

Instantly share code, notes, and snippets.

@bxt

bxt/Profile.php

Forked from supernifty/profile.php
Created February 27, 2011 20:29
Show Gist options
  • Save bxt/846504 to your computer and use it in GitHub Desktop.
Save bxt/846504 to your computer and use it in GitHub Desktop.
Download ZIP
Ultra Simple PHP Profiler writing CSV files (OOP verision)
Raw
arrayIsAssoc.csv
8.416433095932 - intloop 1000001
9.9404051303864 - keyloop 1000001
16.166024923325 - keysx2 1000001
22.479099988937 - range 1000001
22.700661182404 - array_diff_key 1000001
25.694468975067 - preg_match 1000001
29.578541994095 - merge 1000001
60.175529956818 - count 1000001
66.448474168777 - reduce 1000001
8.640517950058 - intloop 1000001
10.394762992859 - keyloop 1000001
13.55481505394 - intloopnobr 1000001
16.789393901825 - keysx2 1000001
22.535210847855 - range 1000001
22.903661966324 - array_diff_key 1000001
26.579383134842 - preg_match 1000001
30.729591846466 - merge 1000001
61.064743995667 - count 1000001
68.082312822342 - reduce 1000001
0.0084710121154785 - intloop 1001
0.26771402359009 - keyloop 1001
0.90295791625977 - intloopnobr 1001
0.63246703147888 - keysx2 1001
0.76140594482422 - range 1001
0.74367809295654 - array_diff_key 1001
0.66588997840881 - preg_match 1001
0.91812801361084 - merge 1001
7.6748130321503 - count 1001
8.5625360012054 - reduce 1001
0.0086629390716553 - intloop 1001
7.8007800579071 - keyloop 1001
16.476301908493 - keyloopnobr 1001
8.796480178833 - intloopnobr 1001
20.92370891571 - keysx2 1001
24.631165981293 - range 1001
22.514696121216 - array_diff_key 1001
18.962918996811 - preg_match 1001
29.189239025116 - merge 1001
94.343507051468 - count 1001
112.76480579376 - reduce 1001
Raw
arrayIsAssoc.php
<?php
// true if arrray is assoc
require_once '../Profile.php';
$profiler=new Profile("arrayIsAssoc.csv",false);
$anz=1000;
/*
$assoc=array(0=>'oho',1=>'c','d'=>array(),'f','x'=>5);
$nummm=array('a','b','c','d','e','f');
*/
for($i=0;$i<=10000;$i++) {
$assoc[]=true;
}
$nummm=$assoc;
$assoc["b"]="muhaha";
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=true;
for($k=count($assoc)-1;$k>=0;$k--) {
if (!isset($assoc[$i])) $result1=true; break;
}
$result2=false;
for($k=count($nummm)-1;$k>=0;$k--) {
if (!isset($assoc[$i])) $result2=true; break;
}
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("intloop $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=false;
foreach(array_keys($assoc) as $key=>$value) {
if ($key!==$value) $result1=true; break;
}
$result2=false;
foreach(array_keys($nummm) as $key=>$value) {
if ($key!==$value) $result2=true; break;
}
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("keyloop $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=false;
foreach(array_keys($assoc) as $key=>$value) {
if ($key!==$value) $result1=true;
}
$result2=false;
foreach(array_keys($nummm) as $key=>$value) {
if ($key!==$value) $result2=true;
}
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("keyloopnobr $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=true;
for($k=count($assoc)-1;$k>=0;$k--) {
if (!isset($assoc[$i])) $result1=true;
}
$result2=false;
for($k=count($nummm)-1;$k>=0;$k--) {
if (!isset($assoc[$i])) $result2=true;
}
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("intloopnobr $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$k=array_keys($assoc);
$result1=$k!==array_keys($k);
$k=array_keys($nummm);
$result2=$k!==array_keys($k);
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("keysx2 $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=array_keys($assoc)!==range(0,sizeof($assoc)-1);
$result2=array_keys($nummm)!==range(0,sizeof($nummm)-1);
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("range $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=!array_diff_key($assoc, array_keys(array_keys($assoc)));
$result2=!array_diff_key($nummm, array_keys(array_keys($nummm)));
if($result1&&!$result2) throw new Exception("wrong");
}
$profiler->end("array_diff_key $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=!empty($assoc) && !preg_match('/^\d+$/', implode('', array_keys($assoc)));
$result2=!empty($nummm) && !preg_match('/^\d+$/', implode('', array_keys($nummm)));
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("preg_match $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result1=(array_merge($assoc) !== $assoc || !is_numeric( implode( array_keys( $assoc ) ) ) );
$result2=(array_merge($nummm) !== $nummm || !is_numeric( implode( array_keys( $nummm ) ) ) );
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("merge $i");
$profiler->start();
function is_assoc_callback($a, $b)
{
return $a === $b ? $a + 1 : 0;
}for($i=0;$i<=$anz;$i++) {
$result1=count($assoc) !== array_reduce(array_keys($assoc), 'is_assoc_callback', 0);
$result2=count($nummm) !== array_reduce(array_keys($nummm), 'is_assoc_callback', 0);
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("count $i");
$profiler->start();
function binary_nor($a,$b) {
return $a&&$b;
}
for($i=0;$i<=$anz;$i++) {
$result1=!array_reduce(array_map("is_numeric", array_keys($assoc)), "binary_nor", true);
$result2=!array_reduce(array_map("is_numeric", array_keys($nummm)), "binary_nor", true);
if(!$result1&&$result2) throw new Exception("wrong");
}
$profiler->end("reduce $i");
Raw
ltrimVsPreg-cutonly.php
<?php
require_once '../Profile.php';
$profiler=new Profile("profile-ltrimVsPreg-cutonly.csv",false);
//$profiler=new Profile(false,false);
$anz=500000;
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
preg_match('/^( *)(.*)/s',$l,$startWs);
if(isset($startWs[0])) {
$neu=$startWs[2];
if(!$neu=="dslkfgj") die("bah!");
}
}
$profiler->end("regexp");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
$neu=ltrim($l," ");
if(!$neu=="dslkfgj") die("bah!");
}
$profiler->end("ltrim");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
$neu=ltrim($l);
$lvl=(strlen($l)-strlen($neu))/2;
if(!$lvl==3) die("bah!");
if(!$neu=="dslkfgj") die("bah!");
}
$profiler->end("ltrim/all");
Raw
ltrimVsPreg.php
<?php
require_once '../Profile.php';
$profiler=new Profile("profile-ltrimVsPreg.csv",false);
//$profiler=new Profile(false,false);
$anz=500000;
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
preg_match('/^( *)(.*)/s',$l,$startWs);
if(isset($startWs[0])) {
$lvl=strlen($startWs[1])/2;
$neu=$startWs[2];
}
if(!$lvl==3) die("bah!");
if(!$neu=="dslkfgj") die("bah!");
}
$profiler->end("regexp");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
$neu=ltrim($l," ");
$lvl=(strlen($l)-strlen($neu))/2;
if(!$lvl==3) die("bah!");
if(!$neu=="dslkfgj") die("bah!");
}
$profiler->end("ltrim");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$l=" dslkfgj";
$neu=ltrim($l);
$lvl=(strlen($l)-strlen($neu))/2;
if(!$lvl==3) die("bah!");
if(!$neu=="dslkfgj") die("bah!");
}
$profiler->end("ltrim/all");
Raw
profile-ltrimVsPreg-cutonly.csv
12.444273948669 - regexp
10.322757005692 - ltrim
27.696735858917 - ltrim/all
Raw
profile-ltrimVsPreg.csv
19.955920934677 - regexp
24.963863134384 - ltrim
25.607894897461 - ltrim/all
Raw
Profile.php
<?php
/**
* A simple class for tracking execution times of PHP scripts and logging them into CVS files
* @author Bernhard Häussner
* @see https://gist.github.com/846504
*/
class Profile {
private $_start = array();
private $_subdata = '';
private $_file=false;
/**
* Initialise, configure
* @param String CSV-file to log times to
* @param boolean If or not to measure time from construction on
*/
public function __construct($file=false,$autostart=true) {
$this->_file=$file;
if($autostart) $this->start();
}
/**
* Start profiling and timekeeping
* @return self this (chainable)
*/
public function start() {
// use a stack of start times to enable nesting
$this->_start[] = microtime(true);
return $this;
}
/**
* End profiling and dump log into CSV file, implicit info()
* @param String Appears in log after final time
* @return float Seconds passed since last call of start()
*/
public function end( $message ) {
if(count($this->_start)==0) return false;
$returnV=$this->info($message);
array_pop($this->_start);
if($this->_file && count($this->_start)==0) {
$fd = fopen($this->_file, "a");
fwrite($fd, $this->_subdata );
fclose($fd);
}
if(count($this->_start)==0) {
$this->_subdata='';
}
return $returnV;
}
/**
* Write current execution time to log
* @param String Appears in log after current time
* @return float Seconds passed since last call of start()
*/
public function info( $message ) {
$lvl=count($this->_start);
if($lvl==0) return false;
$time=microtime(true)-$this->_start[$lvl-1];
$this->_subdata .= $time;
$this->_subdata .= ",\"" . str_repeat("-",$lvl) . " " . str_replace("\"","\"\"",$message) . "\"\n";
return $time;
}
}
?>
Raw
profiler_usage.php
<?php
require_once "Profile.php";
$profiler=new Profile("/tmp/profile.csv");
// ...
$profiler->start();
$q="SELECT * FROM table";
$query = mysql_query($q);
$profiler->end($q);
// ...
$profiler->info( "checkpoint" );
// ...
$profiler->end( "page" );
?>
Raw
ProfileTest.php
<?php
require 'Profile.php';
class ProfileTest extends PHPUnit_Framework_TestCase {
const TESTFILE="unitTestProfile.csv";
/**
* The negative logarithm (base 10) of seconds shortest sleep interval will take
*
* change this to highter value to shorten test time,
* but test wil more often fail depending on system performance
*/
const TESTRESOLUTION=2;
protected $profiler;
protected function setUp() {
if (file_exists(self::TESTFILE)) throw new Exception("found artefact profiling file");
if (!touch(self::TESTFILE)) throw new Exception("couldn't create profiling file");
}
protected function tearDown() {
unlink(self::TESTFILE);
}
/**
* @dataProvider sleepTimes
*/
function testDefaultConstruct($s1,$s2,$s3) {
$p=new Profile();
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$this->assertEquals($s1,floor($p->info("msg")*pow(10,self::TESTRESOLUTION)),"returned time");
usleep($s2*pow(10,6-self::TESTRESOLUTION));
$this->assertEquals($s1+$s2,floor($p->info("msg")*pow(10,self::TESTRESOLUTION)),"returned time");
usleep($s3*pow(10,6-self::TESTRESOLUTION));
$this->assertEquals($s1+$s2+$s3,floor($p->end("msg")*pow(10,self::TESTRESOLUTION)),"returned time");
$this->assertEquals('',file_get_contents(self::TESTFILE));
}
/**
* @dataProvider sleepTimes
*/
function testFileConstruct($s1,$s2,$s3) {
$p=new Profile(self::TESTFILE);
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$endtime=$p->end("msg");
$this->assertEquals($s1,floor($endtime*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime},\"- msg\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"result time $endtime did not math file content: ".$fileContents
);
}
/**
* @dataProvider trickyMessages
*/
function testCsvEscaping($m,$m_esc) {
$s1=2;
$p=new Profile(self::TESTFILE);
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$endtime=$p->end($m);
$this->assertEquals($s1,floor($endtime*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime},\"- ".$m_esc."\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"result time $endtime, message $m_esc did not math file content: ".$fileContents
);
}
/**
* @dataProvider sleepTimes
*/
function testNostartConstruct($s1,$s2,$s3) {
$p=new Profile(false,false);
$this->assertFalse($p->info("bah"));
$this->assertEquals($p,$p->start(),"start chainability");
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$this->assertEquals($s1,floor($p->end("msg")*pow(10,self::TESTRESOLUTION)),"returned time");
$this->assertEquals('',file_get_contents(self::TESTFILE));
}
/**
* @dataProvider sleepTimes
*/
function testFileNostartConstruct($s1,$s2,$s3) {
$p=new Profile(self::TESTFILE,false);
$this->assertFalse($p->info("bah"));
$this->assertEquals($p,$p->start(),"start chainability");
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$endtime=$p->end("msg");
$this->assertEquals($s1,floor($endtime*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime},\"- msg\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad file content: ".$fileContents
);
}
/**
* @dataProvider sleepTimes
*/
function testCheckpointProfiles($s1,$s2,$s3) {
$p=new Profile(self::TESTFILE);
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$infotime1=$p->info("msg1");
$this->assertEquals($s1,floor($infotime1*pow(10,self::TESTRESOLUTION)),"returned time");
usleep($s2*pow(10,6-self::TESTRESOLUTION));
$infotime2=$p->info("msg2");
$this->assertEquals($s1+$s2,floor($infotime2*pow(10,self::TESTRESOLUTION)),"returned time");
$this->assertEquals('',file_get_contents(self::TESTFILE));
usleep($s3*pow(10,6-self::TESTRESOLUTION));
$endtime=$p->end("msg3");
$this->assertEquals($s1+$s2+$s3,floor($endtime*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$infotime1},\"- msg1\"\n{$infotime2},\"- msg2\"\n{$endtime},\"- msg3\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad for eg {$infotime2} file content: ".$fileContents
);
}
/**
* @dataProvider sleepTimes
*/
function testRestarting($s1,$s2,$s3) {
$p=new Profile(self::TESTFILE);
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$endtime1=$p->end("msg1");
$this->assertEquals($s1,floor($endtime1*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime1},\"- msg1\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad file content: ".$fileContents
);
$this->assertEquals($p,$p->start(),"start chainability");
usleep($s2*pow(10,6-self::TESTRESOLUTION));
$endtime2=$p->end("msg2");
$this->assertEquals($s2,floor($endtime2*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime1},\"- msg1\"\n{$endtime2},\"- msg2\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad file content: ".$fileContents
);
$this->assertEquals($p,$p->start(),"start chainability");
usleep($s3*pow(10,6-self::TESTRESOLUTION));
$endtime3=$p->end("msg3");
$this->assertEquals($s3,floor($endtime3*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$endtime1},\"- msg1\"\n{$endtime2},\"- msg2\"\n{$endtime3},\"- msg3\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad file content: ".$fileContents
);
}
/**
* @dataProvider sleepTimes
*/
function testNestedProfiles($s1,$s2,$s3) {
$p=new Profile(self::TESTFILE);
usleep($s1*pow(10,6-self::TESTRESOLUTION));
$infotime1=$p->info("msg1");
$this->assertEquals($s1,floor($infotime1*pow(10,self::TESTRESOLUTION)),"returned time");
$this->assertEquals($p,$p->start(),"start chainability");
usleep($s2*pow(10,6-self::TESTRESOLUTION));
$endtime1=$p->end("msgI");
$this->assertEquals($s2,floor($endtime1*pow(10,self::TESTRESOLUTION)),"nested returned time");
$this->assertEquals('',file_get_contents(self::TESTFILE));
usleep($s3*pow(10,6-self::TESTRESOLUTION));
$endtime2=$p->end("msg3");
$this->assertEquals($s1+$s2+$s3,floor($endtime2*pow(10,self::TESTRESOLUTION)),"returned time");
$expectedFileContents= "{$infotime1},\"- msg1\"\n{$endtime1},\"-- msgI\"\n{$endtime2},\"- msg3\"\n";
$fileContents=file_get_contents(self::TESTFILE);
$this->assertEquals(
$expectedFileContents,$fileContents,
"bad for eg {$endtime1} file content: ".$fileContents
);
}
function sleepTimes() {
return array(
array(1,1,1),
array(1,2,1),
array(2,1,1),
array(1,1,2),
array(1,2,3),
array(2,1,2),
array(3,2,1),
);
}
function trickyMessages() {
return array(
array('untricky','untricky'),
array('containing space','containing space'),
array('containing more space','containing more space'),
array('containing "quotes" too','containing ""quotes"" too'),
array('containing \'quotes\' that dont matter','containing \'quotes\' that dont matter'),
array("containing \n two lines","containing \n two lines"),
array('"cont"aining "lotta" quotes"','""cont""aining ""lotta"" quotes""'),
);
}
}
Raw
strPosVsIf.csv
0.0010960102081299 - if x 1001
0.017470121383667 - strpos x 1001
0.019465923309326 - preg_match x 1001
1.1343450546265 - if x 1000001
17.183837890625 - strpos x 1000001
18.836858987808 - preg_match x 1000001
Raw
strPosVsIf.php
<?php
require_once '../Profile.php';
$profiler=new Profile("strPosVsIf.csv",false);
$anz=1000000;
$l='sdlfgsd';
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result=($l[0]=='s'&&$l[1]=='d');
if(!$result) echo '.';
}
$profiler->end("if x $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result=(strpos($l,'sd')===0);
if(!$result) echo '.';
}
$profiler->end("strpos x $i");
$profiler->start();
for($i=0;$i<=$anz;$i++) {
$result=(preg_match('/^sd/',$l)===1);
if(!$result) echo '.';
}
$profiler->end("preg_match x $i");
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment