fixed invalid return
[moodle.git] / lib / profilerlib.php
CommitLineData
b65567f4 1<?php
6fc4ad72 2
50fcb1d8 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 */
0c449272 25require_once('Console/Getopt.php');
6fc4ad72 26
b65567f4 27/**
50fcb1d8 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 */
b65567f4 38class Profiler
39{
40 var $stimes;
41 var $utimes;
42 var $calls;
43 var $c_stimes;
44 var $c_utimes;
45 var $mem;
117bd748 46
6fc4ad72 47 /**
48 * Concatenates all the pprof files generated by apd_set_pprof_trace()
117bd748 49 * and returns the resulting string, which can then be processed by
6fc4ad72 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.
117bd748 54 *
6fc4ad72 55 * WARNING: If you switch cleanup off, profiling data will
56 * accumulate from one pageload to the next.
57 *
50fcb1d8 58 * @global object
59 * @global object
6fc4ad72 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
117bd748 67 $tempdir = $CFG->dataroot . '/temp/profile/' . $USER->id;
6fc4ad72 68 if ($files = scandir($tempdir)) {
69 // Concatenate the files
117bd748 70 print_r($files);
6fc4ad72 71 } else {
72 print "Error: Profiler could not read the directory $tempdir.";
73 return false;
74 }
117bd748 75
6fc4ad72 76
77 // Return a handle to the resulting file
117bd748
PS
78
79
6fc4ad72 80 if(($DATA = fopen($dataFile, "r")) == FALSE) {
81 return "Failed to open $dataFile for reading\n";
82 }
83 return $handle;
84 }
85
b65567f4 86
6fc4ad72 87 /**
88 * Returns profiling information gathered using APD functions.
89 * Accepts a numerical array of command-line arguments.
117bd748 90 *
50fcb1d8 91 * Profiler::get_profiling($args)
6fc4ad72 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');
117bd748 113 *
6fc4ad72 114 * @param Array $args
115 * @return String Profiling info
116 */
117 function get_profiling($args)
117bd748 118 {
6fc4ad72 119 $con = new Console_Getopt;
120 array_shift($args);
117bd748 121
6fc4ad72 122 $shortoptions = 'acg:hiIlmMrRsStTuUO:vzZ';
123 $retval = $con->getopt( $args, $shortoptions);
124 if(is_object($retval)) {
125 usage();
b65567f4 126 }
117bd748 127
6fc4ad72 128 $opt['O'] = 20;
129 foreach ($retval[0] as $kv_array) {
130 $opt[$kv_array[0]] = $kv_array[1];
b65567f4 131 }
117bd748 132
6fc4ad72 133 $DATA = Profiler::_get_pprofp();
b65567f4 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;
b8468965 181 }
b65567f4 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)) {
b8468965 264 return NULL;
b65567f4 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);
117bd748 273
b65567f4 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;
117bd748 343 }
b65567f4 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];
117bd748 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",
b65567f4 382 $pcnt, $rsecs, $c_rsecs, $usecs, $c_usecs, $ssecs, $c_ssecs, $ncalls, $percall, $cpercall, $mem_usage, $name);
383 return $retstring;
384 }
385 }
6fc4ad72 386 return $retstring;
b65567f4 387 }
388
389 function usage() {
390 return <<<EOD
6fc4ad72 391 Profiler::get_profiling(\$args)
b65567f4 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
412EOD;
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 }
117bd748
PS
449
450 function by_rtime($a,$b) {
b65567f4 451 return $this->num_cmp($this->rtimes[$b], $this->rtimes[$a]);
452 }
117bd748
PS
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]);
b65567f4 460 }
117bd748
PS
461
462 function by_c_stime($a,$b) {
463 return $this->num_cmp($this->c_stimes[$b], $this->c_stimes[$a]);
b65567f4 464 }
117bd748
PS
465
466 function by_utime($a,$b) {
467 return $this->num_cmp($this->utimes[$b], $this->utimes[$a]);
b65567f4 468 }
117bd748
PS
469
470 function by_c_utime($a,$b) {
471 return $this->num_cmp($this->c_utimes[$b], $this->c_utimes[$a]);
b65567f4 472 }
117bd748
PS
473
474 function by_mem($a, $b) {
475 return $this->num_cmp($this->mem[$b], $this->mem[$a]);
b65567f4 476 }
b65567f4 477}