Improving performance of fetching git objects by using git cat-file --batch through a pipe. Also improved debug output and added destructor-based auto-timers
[gitphp.git] / include / DebugLog.class.php
blob:a/include/DebugLog.class.php -> blob:b/include/DebugLog.class.php
<?php <?php
/** /**
* Debug logging class * Debug logging class
* *
* @author Christopher Han <xiphux@gmail.com> * @author Christopher Han <xiphux@gmail.com>
* @copyright Copyright (c) 2010 Christopher Han * @copyright Copyright (c) 2010 Christopher Han
* @package GitPHP * @package GitPHP
*/ */
class GitPHP_DebugLog implements GitPHP_Observer_Interface class GitPHP_DebugLog implements GitPHP_Observer_Interface
{ {
/** /**
* Stores whether logging is enabled * Stores whether logging is enabled
* *
* @var boolean * @var boolean
*/ */
protected $enabled = false; protected $enabled = false;
   
/** /**
* Stores whether benchmarking is enabled * Stores whether benchmarking is enabled
* *
* @var boolean * @var boolean
*/ */
protected $benchmark = false; protected $benchmark = false;
   
/** /**
* Stores the starting instant * Stores the starting instant
* *
* @var float * @var float
*/ */
protected $startTime; protected $startTime;
   
/** /**
* Stores the starting memory * Stores the starting memory
* *
* @var int * @var int
*/ */
protected $startMem; protected $startMem;
   
/** /**
* Stores the log entries * Stores the log entries
* *
* @var string[] * @var string[]
*/ */
protected $entries = array(); protected $entries = array();
   
/** /**
  * Stores the timers
  *
  * @var float[]
  */
  protected $timers = array();
   
  /**
  * @return GitPHP_DebugLog
  */
  public static function GetInstance()
  {
  static $instance;
  if (!$instance) $instance = new self();
  return $instance;
  }
   
  /**
  * You must use GetInstance()
  */
  private function __construct()
  {
  }
   
  /**
* Constructor * Constructor
* *
* @param boolean $enabled whether log should be enabled * @param boolean $enabled whether log should be enabled
* @param boolean $benchmark whether benchmarking should be enabled * @param boolean $benchmark whether benchmarking should be enabled
*/ */
public function __construct($enabled = false, $benchmark = false) public function init($enabled = false, $benchmark = false)
{ {
$this->startTime = microtime(true); $this->startTime = microtime(true);
$this->startMem = memory_get_usage(); $this->startMem = memory_get_usage();
   
$this->enabled = $enabled; $this->enabled = $enabled;
$this->benchmark = $benchmark; $this->benchmark = $benchmark;
} }
   
/** /**
* Sets start time * Sets start time
* *
* @param float $start starting microtime * @param float $start starting microtime
*/ */
public function SetStartTime($start) public function SetStartTime($start)
{ {
$this->startTime = $start; $this->startTime = $start;
} }
   
/** /**
* Sets start memory * Sets start memory
* *
* @param integer $start starting memory * @param integer $start starting memory
*/ */
public function SetStartMemory($start) public function SetStartMemory($start)
{ {
$this->startMem = $start; $this->startMem = $start;
} }
   
/** /**
  * Shortcut to start timer
  */
  public function TimerStart()
  {
  if (!$this->benchmark) return;
  $this->Log('', '', 'start');
  }
   
  /**
  * Shortcut to stop timer
  *
  * @param $msg
  * @param $msg_data
  */
  public function TimerStop($msg, $msg_data = '')
  {
  if (!$this->benchmark) return;
  $this->Log($msg, $msg_data, 'stop');
  }
   
  /**
* Log an entry * Log an entry
* *
* @param string $message message to log * @param string $msg message to log
*/ */
public function Log($message) public function Log($msg, $msg_data = '', $type = 'ts')
{ {
if (!$this->enabled) if (!$this->enabled)
return; return;
   
$entry = array(); $entry = array();
   
if ($this->benchmark) { if ($type == 'start') {
$entry['time'] = microtime(true); array_push($this->timers, microtime(true));
$entry['mem'] = memory_get_usage(); return;
  } else if ($type == 'stop') {
  $timer = array_pop($this->timers);
  $entry['time'] = $duration = microtime(true) - $timer;
  foreach ($this->timers as &$item) $item += $duration;
  } else {
  if ($this->benchmark) {
  $entry['time'] = (microtime(true) - $this->startTime);
  $entry['reltime'] = true;
  $entry['mem'] = memory_get_usage();
  }
} }
   
$entry['msg'] = $message; $entry['name'] = $msg;
  $entry['value'] = $msg_data;
  $bt = explode("\n", new Exception());
  array_shift($bt);
  array_shift($bt);
  $entry['bt'] = implode("\n", $bt);
$this->entries[] = $entry; $this->entries[] = $entry;
} }
   
/** /**
* Gets whether logging is enabled * Gets whether logging is enabled
* *
* @return boolean true if logging is enabled * @return boolean true if logging is enabled
*/ */
public function GetEnabled() public function GetEnabled()
{ {
return $this->enabled; return $this->enabled;
} }
   
/** /**
* Sets whether logging is enabled * Sets whether logging is enabled
* *
* @param boolean $enable true if logging is enabled * @param boolean $enable true if logging is enabled
*/ */
public function SetEnabled($enable) public function SetEnabled($enable)
{ {
$this->enabled = $enable; $this->enabled = $enable;
} }
   
/** /**
* Gets whether benchmarking is enabled * Gets whether benchmarking is enabled
* *
* @return boolean true if benchmarking is enabled * @return boolean true if benchmarking is enabled
*/ */
public function GetBenchmark() public function GetBenchmark()
{ {
return $this->benchmark; return $this->benchmark;
} }
   
/** /**
* Sets whether benchmarking is enabled * Sets whether benchmarking is enabled
* *
* @param boolean $bench true if benchmarking is enabled * @param boolean $bench true if benchmarking is enabled
*/ */
public function SetBenchmark($bench) public function SetBenchmark($bench)
{ {
$this->benchmark = $bench; $this->benchmark = $bench;
}  
   
/**  
* Gets log entries  
*  
* @return string[] log entries  
*/  
public function GetEntries()  
{  
$data = array();  
   
if ($this->enabled) {  
   
if ($this->benchmark) {  
$endTime = microtime(true);  
$endMem = memory_get_usage();  
   
$lastTime = $this->startTime;  
$lastMem = $this->startMem;  
   
$data[] = 'DEBUG: [' . $this->startTime . '] [' . $this->startMem . ' bytes] Start';  
   
}  
   
foreach ($this->entries as $entry) {  
if ($this->benchmark) {  
$data[] = 'DEBUG: [' . $entry['time'] . '] [' . ($entry['time'] - $this->startTime) . ' sec since start] [' . ($entry['time'] - $lastTime) . ' sec since last] [' . $entry['mem'] . ' bytes] [' . ($entry['mem'] - $this->startMem) . ' bytes since start] [' . ($entry['mem'] - $lastMem) . ' bytes since last] ' . $entry['msg'];  
$lastTime = $entry['time'];  
$lastMem = $entry['mem'];  
} else {  
$data[] = 'DEBUG: ' . $entry['msg'];  
}  
}  
   
if ($this->benchmark) {  
$data[] = 'DEBUG: [' . $endTime . '] [' . ($endTime - $this->startTime) . ' sec since start] [' . ($endTime - $lastTime) . ' sec since last] [' . $endMem . ' bytes] [' . ($endMem - $this->startMem) . ' bytes since start] [' . ($endMem - $lastMem) . ' bytes since last] End';  
}  
}  
   
return $data;  
} }
   
/** /**
* Clears the log * Clears the log
*/ */
public function Clear() public function Clear()
{ {
$this->entries = array(); $this->entries = array();
} }
   
/** /**
* Notify that observable object changed * Notify that observable object changed
* *
* @param GitPHP_Observable_Interface $object object * @param GitPHP_Observable_Interface $object object
* @param int $changeType type of change * @param int $changeType type of change
* @param array $args argument array * @param array $args argument array
*/ */
public function ObjectChanged($object, $changeType, $args = array()) public function ObjectChanged($object, $changeType, $args = array())
{ {
if ($changeType !== GitPHP_Observer_Interface::LoggableChange) if ($changeType !== GitPHP_Observer_Interface::LoggableChange)
return; return;
   
if (!$this->enabled) if (!$this->enabled)
return; return;
   
if (!isset($args[0]) || empty($args[0])) if (!isset($args[0]) || empty($args[0]))
return; return;
   
$msg = $args[0]; $msg = $args[0];
  $msg_data = isset($args[1]) ? $args[1] : '';
$this->Log($msg); $type = isset($args[2]) ? $args[2] : 'ts';
}  
  $this->Log($msg, $msg_data, $type);
  }
   
  public function PrintHtml()
  {
  if (!$this->enabled) return;
   
  foreach ($this->entries as $i => $e) {
  $bt_id = 'bt_' . $i;
  if (strlen($e['value']) > 512) {
  $contents = htmlspecialchars(substr($e['value'], 0, 512) . "...");
  $contents .= "\n\n<i>" . (strlen($e['value']) - 512) . " bytes more in output</i>";
  } else {
  $contents = htmlspecialchars($e['value']);
  }
  echo "<tr>
  <td class='debug_key'>$e[name]</td>
  <td class='debug_value'>
  " . nl2br($contents) . ($contents != "" ? "<br§ />" : "") . "
  <span class='debug_toggle' onclick='bt_toggle(\"$bt_id\");'>trace</span>&nbsp;
  <div style='display: none;' class='debug_bt' id='$bt_id'>$e[bt]</div>
  </td>
  <td class='debug_time'>
  " . ($e['time'] ? sprintf("%.1f", $e['time'] * 1000) : '') . "
  " . ($e['time'] ? (!empty($e['reltime']) ? " ms from start" : " ms") : '') . "
  </td>
  </tr>";
  }
  }
   
  public function PrintHtmlHeader()
  {
  if (!$this->enabled) return;
   
  echo
  <<<HEREDOC
  <script type="text/javascript">
  function bt_toggle(id) {
  var el = document.getElementById(id);
  el.style.display = ((el.style.display == 'none') ? 'block' : 'none');
  }
  </script>
  <style type="text/css">
  .debug {
  border: 0;
  border-spacing: 0;
  width: 100%;
  }
  .debug_toggle {
  color: #88a; border-bottom: 1px dashed blue;
  display: inline-block;
  margin: 3px;
  cursor: pointer;
  }
  .debug_key {
  background: #ccf; border-bottom: 1px solid #888;
  max-width: 100px;
  word-wrap: break-word;
  }
  .debug_value {
  background: #ccc; border-bottom: 1px solid #888;
  max-width: 900px;
  word-wrap: break-word;
  }
  .debug_bt {
  white-space: pre;
  }
  .debug_time {
  background: #cff; border-bottom: 1px solid #888;
  }
  </style>
  <table class="debug"><tbody>
  HEREDOC;
  }
   
  public function PrintHtmlFooter()
  {
  if (!$this->enabled) return;
  echo '</tbody></table>';
  }
} }
   
comments