timing and benchmarking

I just commited a new version of includes/debug.inc, having added a little utility to allow benchmarking of areas of code. I will include my comments below. This is a very useful way to identify where bottlenecks are occurring. Remember, 90% of the work is generally performed in 10% of the code; I hope this will allow us to identify the hot spots so we can concentrate where the most need for optimiztion is required. # function bm_time($label, $squirt=0) # # A utility debugging function that allows timing of areas of code. # # Input: # $label = command (see below) or benchmark label # $squirt set non-zero to send dump output to squirt log; otherwise

#            it will be displayed on the screen.

# # Usage: # This function has three modes of operation. # 1) Calling it with a label argument of "INIT" must be performed to

#      initialize it; this will reset internal variables.

# # 2) Calling it with a label other than "INIT" or "DUMP" will

#      record the time elapsed since the last call and associate
#      this time with the specified label.

# # 3) Calling it with an argument of "DUMP" will display the history

#      of calls since the function was initialized, followed by a total
#      elapsed time.

# # Timing has a resolution of microseconds. DUMP will not reset the internal # variables, you must explicitly INIT it again to do so. This allows # presenting the DUMP information more than once throughout the program. # # # Sample code: # ------------ # bm_time('INIT'); # # sleep(1); # bm_time('point 1'); # # for ($i=1; $i<10000; $i++) { $j = log($i); } # bm_time('point 2'); # # for ($i=1; $i<10000; $i++) { $j = tan($i); } # bm_time('point 3'); # # bm_time('DUMP'); # # Output: # ------- # Timing results: #

#     point 1              0.995969
#     point 2              0.831739
#     point 3              0.847677

# # total: 2.67538 function bm_time($label, $squirt=0) { global $basetime,$totaltime,$rpttimes; if ($label=='INIT') {

    $rpttimes = array();
    $basetime = microtime();
    ereg("^([^ ]+) (.+)",$basetime, $r);
    $basetime = doubleval($r[2])+doubleval($r[1]);
    return;

} if ($label=='DUMP') {

    if ($squirt) {
      # send to squirt log
      squirt ("======================================");
      squirt ("===== Timing results:");
      for ($i=0; $i < count($rpttimes); $i++) {
        squirt ("  ".$rpttimes[$i]);
      }
      squirt ("TOTAL TIME: $totaltime");
      squirt ("======================================");
    } else {
      # send to screen
      echo "<B>Timing results:</B><BR>\n";
      echo "<PRE>";
      for ($i=0; $i < count($rpttimes); $i++) {
        echo "  ".$rpttimes[$i]."\n";
      }
      echo "\ntotal: $totaltime\n";
      echo "</PRE>";
    }

    return;

} # record current elpased time, accumulate $newtime = microtime(); ereg("^([^ ]+) (.+)",$newtime, $r); $newtime = doubleval($r[2])+doubleval($r[1]); $diff = $newtime - $basetime; $rpttimes[] = sprintf("%-20s %s",$label,$diff); $basetime = $newtime; $totaltime += $diff; }