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");

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");

profile-ltrimVsPreg-cutonly.csv

profile-ltrimVsPreg.csv

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;
  }

}
?>

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" );
?>

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""'),
    );
  }
}