fixed invalid return
[moodle.git] / lib / profilerlib.php
1 <?php
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/>.
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  */
24 /** Includes */
25 require_once('Console/Getopt.php');
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;
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         }
77         // Return a handle to the resulting file
80         if(($DATA = fopen($dataFile, "r")) == FALSE) {
81             return "Failed to open $dataFile for reading\n";
82         }
83         return $handle;
84     }
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);
122         $shortoptions = 'acg:hiIlmMrRsStTuUO:vzZ';
123         $retval = $con->getopt( $args, $shortoptions);
124         if(is_object($retval)) {
125             usage();
126         }
128         $opt['O'] = 20;
129         foreach ($retval[0] as $kv_array) {
130             $opt[$kv_array[0]] = $kv_array[1];
131         }
133         $DATA = Profiler::_get_pprofp();
135         $cfg = array();
136         $this->parse_info('HEADER', $DATA, $cfg);
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;
157         $symbol_hash = array();
158         $symbol_type = array();
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         }
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);
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;
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     }
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)
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.
412 EOD;
413         exit(1);
414     }
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     }
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     }
434     function by_time($a,$b) {
435         return $this->num_cmp(($this->stimes[$b] + $this->utimes[$b]),($this->stimes[$a] + $this->utimes[$a]));
436     }
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     }
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     }
446     function by_calls($a, $b) {
447         return $this->num_cmp($this->calls[$b], $this->calls[$a]);
448     }
450     function by_rtime($a,$b) {
451         return $this->num_cmp($this->rtimes[$b], $this->rtimes[$a]);
452     }
454     function by_c_rtime($a,$b) {
455         return $this->num_cmp($this->c_rtimes[$b], $this->c_rtimes[$a]);
456     }
458     function by_stime($a,$b) {
459         return $this->num_cmp($this->stimes[$b], $this->stimes[$a]);
460     }
462     function by_c_stime($a,$b) {
463         return $this->num_cmp($this->c_stimes[$b], $this->c_stimes[$a]);
464     }
466     function by_utime($a,$b) {
467         return $this->num_cmp($this->utimes[$b], $this->utimes[$a]);
468     }
470     function by_c_utime($a,$b) {
471         return $this->num_cmp($this->c_utimes[$b], $this->c_utimes[$a]);
472     }
474     function by_mem($a, $b) {
475         return $this->num_cmp($this->mem[$b], $this->mem[$a]);
476     }