lib/profilerlib.php

   1 <?php
   2
   3 // This file is part of Moodle - http://moodle.org/
   4 //
   5 // Moodle is free software: you can redistribute it and/or modify
   6 // it under the terms of the GNU General Public License as published by
   7 // the Free Software Foundation, either version 3 of the License, or
   8 // (at your option) any later version.
   9 //
  10 // Moodle is distributed in the hope that it will be useful,
  11 // but WITHOUT ANY WARRANTY; without even the implied warranty of
  12 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  13 // GNU General Public License for more details.
  14 //
  15 // You should have received a copy of the GNU General Public License
  16 // along with Moodle.  If not, see <http://www.gnu.org/licenses/>.
  17
  18 /**
  19  * @package   moodlecore
  20  * @copyright 1999 onwards Martin Dougiamas  {@link http://moodle.com}
  21  * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  22  */
  23
  24 /** Includes */
  25 require_once('Console/Getopt.php');
  26
  27 /**
  28  * Profiler adapted from Pear::APD's pprofp script. Not quite there yet, I need
  29  * to get this to accept a similar list of arguments as the script does,
  30  * and process them the same way. Also make sure that the file being loaded
  31  * is the right one. Also support multiple pids used in one page load (up to 4 so far).
  32  * Then output all this in a nicely formatted table.
  33  *
  34  * @package   moodlecore
  35  * @copyright 1999 onwards Martin Dougiamas  {@link http://moodle.com}
  36  * @license   http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  37  */
  38 class Profiler
  39 {
  40     var $stimes;
  41     var $utimes;
  42     var $calls;
  43     var $c_stimes;
  44     var $c_utimes;
  45     var $mem;
  46
  47     /**
  48      * Concatenates all the pprof files generated by apd_set_pprof_trace()
  49      * and returns the resulting string, which can then be processed by
  50      * get_profiling();
  51      * It also deletes these files once finished, in order to limit
  52      * cluttering of the filesystem. This can be switched off by
  53      * providing "false" as the only argument to this function.
  54      *
  55      * WARNING: If you switch cleanup off, profiling data will
  56      * accumulate from one pageload to the next.
  57      *
  58      * @global object
  59      * @global object
  60      * @param boolean $cleanup Whether to delete pprof files or not.
  61      * @return String Profiling raw data
  62      */
  63     function _get_pprofp($cleanup = true)
  64     {
  65         global $CFG, $USER;
  66         // List all files under our temporary directory
  67         $tempdir = $CFG->dataroot . '/temp/profile/' . $USER->id;
  68         if ($files = scandir($tempdir)) {
  69             // Concatenate the files
  70             print_r($files);
  71         } else {
  72             print "Error: Profiler could not read the directory $tempdir.";
  73             return false;
  74         }
  75
  76
  77         // Return a handle to the resulting file
  78
  79
  80         if(($DATA = fopen($dataFile, "r")) == FALSE) {
  81             return "Failed to open $dataFile for reading\n";
  82         }
  83         return $handle;
  84     }
  85
  86
  87     /**
  88      * Returns profiling information gathered using APD functions.
  89      * Accepts a numerical array of command-line arguments.
  90      *
  91      * Profiler::get_profiling($args)
  92      *  Sort options
  93      *  -a          Sort by alphabetic names of subroutines.
  94      *  -l          Sort by number of calls to subroutines
  95      *  -m          Sort by memory used in a function call.
  96      *  -r          Sort by real time spent in subroutines.
  97      *  -R          Sort by real time spent in subroutines (inclusive of child calls).
  98      *  -s          Sort by system time spent in subroutines.
  99      *  -S          Sort by system time spent in subroutines (inclusive of child calls).
 100      *  -u          Sort by user time spent in subroutines.
 101      *  -U          Sort by user time spent in subroutines (inclusive of child calls).
 102      *  -v          Sort by average amount of time spent in subroutines.
 103      *  -z          Sort by user+system time spent in subroutines. (default)
 104      *
 105      *  Display options
 106      *  -c          Display Real time elapsed alongside call tree.
 107      *  -i          Suppress reporting for php builtin functions
 108      *  -O <cnt>    Specifies maximum number of subroutines to display. (default 15)
 109      *  -t          Display compressed call tree.
 110      *  -T          Display uncompressed call tree.
 111      *
 112      *  Example array: array('-a', '-l');
 113      *
 114      * @param Array $args
 115      * @return String Profiling info
 116      */
 117     function get_profiling($args)
 118     {
 119         $con = new Console_Getopt;
 120         array_shift($args);
 121
 122         $shortoptions = 'acg:hiIlmMrRsStTuUO:vzZ';
 123         $retval = $con->getopt( $args, $shortoptions);
 124         if(is_object($retval)) {
 125             usage();
 126         }
 127
 128         $opt['O'] = 20;
 129         foreach ($retval[0] as $kv_array) {
 130             $opt[$kv_array[0]] = $kv_array[1];
 131         }
 132
 133         $DATA = Profiler::_get_pprofp();
 134
 135         $cfg = array();
 136         $this->parse_info('HEADER', $DATA, $cfg);
 137
 138         $callstack = array();
 139         $calls = array();
 140         $indent_cur = 0;
 141         $file_hash = array();
 142         $this->mem = array();
 143         $t_rtime = 0;
 144         $t_stime = 0;
 145         $t_utime = 0;
 146         $c_rtimes = array();
 147         $this->c_stimes = array();
 148         $this->c_utimes = array();
 149         $rtimes = array();
 150         $this->stimes = array();
 151         $this->utimes = array();
 152         $rtotal = 0;
 153         $stotal = 0;
 154         $utotal = 0;
 155         $last_memory = 0;
 156
 157         $symbol_hash = array();
 158         $symbol_type = array();
 159
 160         while($line = fgets($DATA)) {
 161             $line = rtrim($line);
 162             if(preg_match("/^END_TRACE/", $line)){
 163                 break;
 164             }
 165             list($token, $data) = preg_split("/ /",$line, 2);
 166             if($token == '!') {
 167             list ($index, $file) = preg_split("/ /", $data, 2);
 168             $file_hash[$index] = $file;
 169             continue;
 170             }
 171             if( $token == '&') {
 172                 list ($index, $name, $type) = preg_split("/ /", $data, 3);
 173                 $symbol_hash[$index] = $name;
 174             $symbol_type[$index] = $type;
 175                 continue;
 176             }
 177             if( $token == '+') {
 178                 list($index, $file, $line) = preg_split("/ /",$data, 3);
 179                 if(array_key_exists('i',$opt) && $symbol_type[$index] == 1) {
 180                     continue;
 181                 }
 182                 $index_cur = $index;
 183                 $calls[$index_cur]++;
 184                 array_push($callstack, $index_cur);
 185                 if(array_key_exists('T', $opt)) {
 186                     if(array_key_exists('c', $opt)) {
 187                        $retstring .= sprintf("%2.02f ", $rtotal/1000000);
 188                     }
 189                     $retstring .= str_repeat("  ", $indent_cur).$symbol_hash[$index_cur]."\n";
 190                 if(array_key_exists('m', $opt)) {
 191                 $retstring .= str_repeat("  ", $indent_cur)."C: $file_hash[$file]:$line M: $memory\n";
 192                 }
 193             }
 194                 elseif(array_key_exists('t', $opt)) {
 195                     if ( $indent_last == $indent_cur && $index_last == $index_cur ) {
 196                         $repcnt++;
 197                     }
 198                     else {
 199                         if ( $repcnt ) {
 200                             $repstr = ' ('.++$repcnt.'x)';
 201                         }
 202                         if(array_key_exists('c', $opt)) {
 203                             $retstring .= sprintf("%2.02f ", $rtotal/1000000);
 204                         }
 205                         $retstring .= str_repeat("  ", $indent_last).$symbol_hash[$index_last].$repstr."\n";
 206                 if(array_key_exists('m', $opt)) {
 207                    $retstring .= str_repeat("  ", $indent_cur)."C: $file_hash[$file_last]:$line_last M: $memory\n";
 208                 }
 209                         $repstr = '';
 210                         $repcnt = 0;
 211                         $index_last = $index_cur;
 212                         $indent_last = $indent_cur;
 213                 $file_last = $file;
 214                 $line_last = $line;
 215                     }
 216                 }
 217             $indent_cur++;
 218                 continue;
 219             }
 220             if( $token == '@') {
 221                 list($file_no, $line_no, $ut, $st, $rt) = preg_split("/ /", $data);
 222                 $top = array_pop($callstack);
 223                 $this->utimes[$top] += $ut;
 224                 $utotal += $ut;
 225                 $this->stimes[$top] += $st;
 226                 $stotal += $st;
 227                 $rtimes[$top] += $rt;
 228                 $rtotal += $rt;
 229                 array_push($callstack, $top);
 230             foreach ($callstack as $stack_element) {
 231                     $this->c_utimes[$stack_element] += $ut;
 232                     $this->c_stimes[$stack_element] += $st;
 233                     $c_rtimes[$stack_element] += $rt;
 234                 }
 235                 continue;
 236             }
 237             if ($token == '-') {
 238                 list  ($index, $memory) = preg_split("/ /", $data, 2);
 239                 if(array_key_exists('i',$opt) && $symbol_type[$index] == 1)
 240                 {
 241                     continue;
 242                 }
 243                 $this->mem[$index] += ($memory - $last_memory);
 244                 $last_memory = $memory;
 245                 $indent_cur--;
 246                 $tmp = array_pop($callstack);
 247                 continue;
 248             }
 249         }
 250         $this->parse_info('FOOTER', $DATA, $cfg);
 251         $sort = 'by_time';
 252         if(array_key_exists('l', $opt)) { $sort = 'by_calls'; }
 253         if(array_key_exists('m', $opt)) { $sort = 'by_mem'; }
 254         if(array_key_exists('a', $opt)) { $sort = 'by_name'; }
 255         if(array_key_exists('v', $opt)) { $sort = 'by_avgcpu'; }
 256         if(array_key_exists('r', $opt)) { $sort = 'by_rtime'; }
 257         if(array_key_exists('R', $opt)) { $sort = 'by_c_rtime'; }
 258         if(array_key_exists('s', $opt)) { $sort = 'by_stime'; }
 259         if(array_key_exists('S', $opt)) { $sort = 'by_c_stime'; }
 260         if(array_key_exists('u', $opt)) { $sort = 'by_utime'; }
 261         if(array_key_exists('U', $opt)) { $sort = 'by_c_utime'; }
 262         if(array_key_exists('Z', $opt)) { $sort = 'by_c_time'; }
 263         if( !count($symbol_hash)) {
 264             return NULL;
 265         }
 266
 267         $retstring .= sprintf("
 268         Trace for %s
 269         Total Elapsed Time = %4.2f
 270         Total System Time  = %4.2f
 271         Total User Time    = %4.2f
 272         ", $cfg['caller'], $rtotal/1000000, $stotal/1000000, $utotal/1000000);
 273
 274         $retstring .= "\n
 275                  Real         User        System             secs/    cumm
 276         %Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
 277         --------------------------------------------------------------------------------------\n";
 278         $l = 0;
 279         $itotal = 0;
 280         $percall = 0;
 281         $cpercall = 0;
 282
 283         uksort($symbol_hash, $sort);
 284         foreach (array_keys($symbol_hash) as $j) {
 285             if(array_key_exists('i', $opt) && $symbol_type[$j] == 1) {
 286                 continue;
 287             }
 288             if ($l++ <  $opt['O']) {
 289                 $pcnt = 100*($this->stimes[$j] + $this->utimes[$j])/($utotal + $stotal + $itotal);
 290                 $c_pcnt = 100* ($this->c_stimes[$j] + $this->c_utimes[$j])/($utotal + $stotal + $itotal);
 291                 $rsecs = $rtimes[$j]/1000000;
 292                 $ssecs = $this->stimes[$j]/1000000;
 293                 $usecs = $this->utimes[$j]/1000000;
 294                 $c_rsecs = $c_rtimes[$j]/1000000;
 295                 $c_ssecs = $this->c_stimes[$j]/1000000;
 296                 $c_usecs = $this->c_utimes[$j]/1000000;
 297                 $ncalls = $calls[$j];
 298             if(array_key_exists('z', $opt)) {
 299                     $percall = ($usecs + $ssecs)/$ncalls;
 300                     $cpercall = ($c_usecs + $c_ssecs)/$ncalls;
 301                         if($utotal + $stotal) {
 302                     $pcnt = 100*($this->stimes[$j] + $this->utimes[$j])/($utotal + $stotal);
 303                         }
 304                         else {
 305                             $pcnt = 100;
 306                         }
 307             }
 308             if(array_key_exists('Z', $opt)) {
 309                     $percall = ($usecs + $ssecs)/$ncalls;
 310                     $cpercall = ($c_usecs + $c_ssecs)/$ncalls;
 311                         if($utotal + $stotal) {
 312                     $pcnt = 100*($this->c_stimes[$j] + $this->c_utimes[$j])/($utotal + $stotal);
 313                         }
 314                         else {
 315                             $pcnt = 100;
 316                         }
 317             }
 318             if(array_key_exists('r', $opt)) {
 319                     $percall = ($rsecs)/$ncalls;
 320                     $cpercall = ($c_rsecs)/$ncalls;
 321                         if($rtotal) {
 322                     $pcnt = 100*$rtimes[$j]/$rtotal;
 323                         }
 324                         else {
 325                             $pcnt = 100;
 326                         }
 327             }
 328             if(array_key_exists('R', $opt)) {
 329                     $percall = ($rsecs)/$ncalls;
 330                     $cpercall = ($c_rsecs)/$ncalls;
 331                         if($rtotal) {
 332                     $pcnt = 100*$c_rtimes[$j]/$rtotal;
 333                         }
 334                         else {
 335                             $pcnt = 100;
 336                         }
 337             }
 338             if(array_key_exists('u', $opt)) {
 339                     $percall = ($usecs)/$ncalls;
 340                     $cpercall = ($c_usecs)/$ncalls;
 341                         if($utotal) {
 342                     $pcnt = 100*$this->utimes[$j]/$utotal;
 343                         }
 344                         else {
 345                             $pcnt = 100;
 346                         }
 347             }
 348             if(array_key_exists('U', $opt)) {
 349                     $percall = ($usecs)/$ncalls;
 350                     $cpercall = ($c_usecs)/$ncalls;
 351                         if($utotal) {
 352                     $pcnt = 100*$this->c_utimes[$j]/$utotal;
 353                         }
 354                         else {
 355                             $pcnt = 100;
 356                         }
 357             }
 358             if(array_key_exists('s', $opt)) {
 359                     $percall = ($ssecs)/$ncalls;
 360                     $cpercall = ($c_ssecs)/$ncalls;
 361                         if($stotal) {
 362                     $pcnt = 100*$this->stimes[$j]/$stotal;
 363                         }
 364                         else {
 365                             $pcnt = 100;
 366                         }
 367             }
 368             if(array_key_exists('S', $opt)) {
 369                     $percall = ($ssecs)/$ncalls;
 370                     $cpercall = ($c_ssecs)/$ncalls;
 371                         if($stotal) {
 372                     $pcnt = 100*$this->c_stimes[$j]/$stotal;
 373                         }
 374                         else {
 375                             $pcnt = 100;
 376                         }
 377             }
 378         //        $cpercall = ($c_usecs + $c_ssecs)/$ncalls;
 379                 $mem_usage = $this->mem[$j];
 380                 $name = $symbol_hash[$j];
 381                 $retstring .=  sprintf("%3.01f %2.02f %2.02f  %2.02f %2.02f  %2.02f %2.02f  %4d  %2.04f   %2.04f %12d %s\n",
 382                                 $pcnt, $rsecs, $c_rsecs, $usecs, $c_usecs, $ssecs, $c_ssecs, $ncalls, $percall, $cpercall, $mem_usage, $name);
 383                 return $retstring;
 384             }
 385         }
 386         return $retstring;
 387     }
 388
 389     function usage() {
 390     return <<<EOD
 391     Profiler::get_profiling(\$args)
 392         Sort options
 393         -a          Sort by alphabetic names of subroutines.
 394         -l          Sort by number of calls to subroutines
 395         -m          Sort by memory used in a function call.
 396         -r          Sort by real time spent in subroutines.
 397         -R          Sort by real time spent in subroutines (inclusive of child calls).
 398         -s          Sort by system time spent in subroutines.
 399         -S          Sort by system time spent in subroutines (inclusive of child calls).
 400         -u          Sort by user time spent in subroutines.
 401         -U          Sort by user time spent in subroutines (inclusive of child calls).
 402         -v          Sort by average amount of time spent in subroutines.
 403         -z          Sort by user+system time spent in subroutines. (default)
 404
 405         Display options
 406         -c          Display Real time elapsed alongside call tree.
 407         -i          Suppress reporting for php builtin functions
 408         -O <cnt>    Specifies maximum number of subroutines to display. (default 15)
 409         -t          Display compressed call tree.
 410         -T          Display uncompressed call tree.
 411
 412 EOD;
 413         exit(1);
 414     }
 415
 416     function parse_info($tag, $datasource, &$cfg) {
 417         while($line = fgets($datasource)) {
 418             $line = rtrim($line);
 419             if(preg_match("/^END_$tag$/", $line)) {
 420                 break;
 421             }
 422             if(preg_match("/(\w+)=(.*)/", $line, $matches)) {
 423                 $cfg[$matches[1]] = $matches[2];
 424             }
 425         }
 426     }
 427
 428     function num_cmp($a, $b) {
 429         if (intval($a) > intval($b)) { return 1;}
 430         elseif(intval($a) < intval($b)) { return -1;}
 431         else {return 0;}
 432     }
 433
 434     function by_time($a,$b) {
 435         return $this->num_cmp(($this->stimes[$b] + $this->utimes[$b]),($this->stimes[$a] + $this->utimes[$a]));
 436     }
 437
 438     function by_c_time($a,$b) {
 439         return $this->num_cmp(($this->c_stimes[$b] + $this->c_utimes[$b]),($this->c_stimes[$a] + $this->c_utimes[$a]));
 440     }
 441
 442     function by_avgcpu($a,$b) {
 443         return $this->num_cmp(($this->stimes[$b] + $this->utimes[$b])/$this->calls[$b],($this->stimes[$a] + $this->utimes[$a])/$this->calls[$a]);
 444     }
 445
 446     function by_calls($a, $b) {
 447         return $this->num_cmp($this->calls[$b], $this->calls[$a]);
 448     }
 449
 450     function by_rtime($a,$b) {
 451         return $this->num_cmp($this->rtimes[$b], $this->rtimes[$a]);
 452     }
 453
 454     function by_c_rtime($a,$b) {
 455         return $this->num_cmp($this->c_rtimes[$b], $this->c_rtimes[$a]);
 456     }
 457
 458     function by_stime($a,$b) {
 459         return $this->num_cmp($this->stimes[$b], $this->stimes[$a]);
 460     }
 461
 462     function by_c_stime($a,$b) {
 463         return $this->num_cmp($this->c_stimes[$b], $this->c_stimes[$a]);
 464     }
 465
 466     function by_utime($a,$b) {
 467         return $this->num_cmp($this->utimes[$b], $this->utimes[$a]);
 468     }
 469
 470     function by_c_utime($a,$b) {
 471         return $this->num_cmp($this->c_utimes[$b], $this->c_utimes[$a]);
 472     }
 473
 474     function by_mem($a, $b) {
 475         return $this->num_cmp($this->mem[$b], $this->mem[$a]);
 476     }
 477 }