• View
• Edit
• History
• Print

00896: Make StopWatch more informative and more flexible

I am trying to revive this old proposal by suggesting a slightly different StopWatch with three main changes to the one in core:

1. Move formatting to StopWatchHTML(), so that customizing the output is possible without editing pmwiki.php.
2. Show time deltas instead of total times (and include total elapsed time at the end), because this way it is easier to notice abnormalities.
3. Change time format to miliseconds, because:
   • benchmarking web applications in the second range is strange: if a page takes longer than a second to generate, consider an angry visitor;
   • it helps to notice that PmWiki is sometimes rather slow and, perhaps, prompts to investigate the bottlenecks.

Proposed code below. -- Rogut279s October 05, 2009, at 06:00 PM

function StopWatch($x) {
  global $StopWatch, $EnableStopWatch;
  if (!$EnableStopWatch) return;
  static $wlast=0, $ulast=0, $n=0;
  list($us,$wtime)=explode(' ', microtime());
  $wtime+=$us;
  if (!$wlast) $wlast=$wtime;
  $StopWatch[++$n] = array($x, ($wtime-$wlast)*1000);
  $wlast=$wtime;
  if ($EnableStopWatch!=2) return;
  $dat = getrusage();
  $utime = $dat['ru_utime.tv_sec']*1000+$dat['ru_utime.tv_usec']/1000;
  if (!$ulast) $ulast=$utime;
  $StopWatch[$n][] = $utime-$ulast;
  $ulast=$utime;
}

function StopWatchHTML($pagename, $print=0) {
  global $StopWatch, $EnableStopWatch;
  StopWatch('now');
  $out='<pre>';
  $wsum=0; $usum=0;
  foreach ((array)$StopWatch as $t) {
    $wsum+=$t[1];
    if (isset($t[2])) {
      $usum+=$t[2];
      $out.=sprintf("%3d %3d %s\n", $t[1], $t[2], $t[0]);
    }
    else $out.=sprintf("%3d %s\n", $t[1], $t[0]);
  }
  if ($usum) $out.=sprintf("%3d %3d SUM\n", $wsum, $usum);
  elseif ($wsum) $out.=sprintf("%3d SUM\n", $wsum);
  $out.='</pre>';
  if (is_array($StopWatch)) array_pop($StopWatch);
  if ($print) echo $out;
  return $out;
}

The original proposal below. Sorry for hijacking, but it lay here for 2.5 years without any activity...

Description: This adds a nice header to the StopWatch output and a time delta (makes the length of time that each step requires is clear).

Patch:

	--- /home/rairighd/Desktop/pmwiki-2.1.27/pmwiki.php	2006-12-11 09:56:21.000000000 -0500
	+++ notes/pmwiki.php	2007-03-01 10:29:01.000000000 -0500
	 -382,17 +382,24 
	 function StopWatch($x) { 
	   global $StopWatch, $EnableStopWatch;
	   if (!$EnableStopWatch) return;
	-  static $wstart = 0, $ustart = 0;
	+  static $wstart = 0, $ustart = 0, $last=0;
	   list($usec,$sec) = explode(' ',microtime());
	-  $wtime = ($sec+$usec); 
	-  if (!$wstart) $wstart = $wtime;
	+  $wtime = ((float)$sec+(float)$usec); 
	+  if (!$wstart) { 
	+    $last = $wstart = $wtime;
	+    $StopWatch[] = ($EnableStopWatch == 2)? sprintf("%5s %5s %5s Desc.", 'Elaps', 'Delta', 'CPU') :
	+    			sprintf("%5s %5s Desc.", 'Elaps', 'Delta');
	+  }
	+  $delta = $wtime - $last;
	+  $last = $wtime;
	+
	   if ($EnableStopWatch != 2) 
	-    { $StopWatch[] = sprintf("%05.2f %s", $wtime-$wstart, $x); return; }
	+    { $StopWatch[] = sprintf("%05.2f %05.2f %s", $wtime-$wstart, $delta, $x); return; }
	   $dat = getrusage();
	   $utime = ($dat['ru_utime.tv_sec']+$dat['ru_utime.tv_usec']/1000000);
	   if (!$ustart) $ustart=$utime;
	   $StopWatch[] = 
	-    sprintf("%05.2f %05.2f %s", $wtime-$wstart, $utime-$ustart, $x);
	+    sprintf("%05.2f %05.2f %05.2f %s", $wtime-$wstart, $delta, $utime-$ustart, $x);
	 }

	 ## AsSpaced converts a string with WikiWords into a spaced version