1 ;;; elp.el --- Emacs Lisp Profiler
3 ;; Copyright (C) 1994,1995,1997,1998, 2001 Free Software Foundation, Inc.
5 ;; Author: Barry A. Warsaw
6 ;; Maintainer: XEmacs Development Team <xemacs-beta@xemacs.org>
7 ;; Created: 26-Feb-1994
8 ;; Keywords: debugging lisp tools
10 ;; This file is part of XEmacs.
12 ;; XEmacs is free software; you can redistribute it and/or modify
13 ;; it under the terms of the GNU General Public License as published by
14 ;; the Free Software Foundation; either version 2, or (at your option)
17 ;; XEmacs is distributed in the hope that it will be useful,
18 ;; but WITHOUT ANY WARRANTY; without even the implied warranty of
19 ;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
20 ;; GNU General Public License for more details.
22 ;; You should have received a copy of the GNU General Public License
23 ;; along with XEmacs; see the file COPYING. If not, write to the
24 ;; Free Software Foundation, Inc., 59 Temple Place - Suite 330,
25 ;; Boston, MA 02111-1307, USA.
27 ;;; Synched with GNU Emacs 21.1 2001-12-25 Simon Josefsson <jas@extundo.com>
31 ;; If you want to profile a bunch of functions, set elp-function-list
32 ;; to the list of symbols, then do a M-x elp-instrument-list. This
33 ;; hacks those functions so that profiling information is recorded
34 ;; whenever they are called. To print out the current results, use
35 ;; M-x elp-results. If you want output to go to standard-output
36 ;; instead of a separate buffer, setq elp-use-standard-output to
37 ;; non-nil. With elp-reset-after-results set to non-nil, profiling
38 ;; information will be reset whenever the results are displayed. You
39 ;; can also reset all profiling info at any time with M-x
42 ;; You can also instrument all functions in a package, provided that
43 ;; the package follows the GNU coding standard of a common textual
44 ;; prefix. Use M-x elp-instrument-package for this.
46 ;; If you want to sort the results, set elp-sort-by-function to some
47 ;; predicate function. The three most obvious choices are predefined:
48 ;; elp-sort-by-call-count, elp-sort-by-average-time, and
49 ;; elp-sort-by-total-time. Also, you can prune from the output, all
50 ;; functions that have been called fewer than a given number of times
51 ;; by setting elp-report-limit.
53 ;; Elp can instrument byte-compiled functions just as easily as
54 ;; interpreted functions, but it cannot instrument macros. However,
55 ;; when you redefine a function (e.g. with eval-defun), you'll need to
56 ;; re-instrument it with M-x elp-instrument-function. This will also
57 ;; reset profiling information for that function. Elp can handle
58 ;; interactive functions (i.e. commands), but of course any time spent
59 ;; idling for user prompts will show up in the timing results.
61 ;; You can also designate a `master' function. Profiling times will
62 ;; be gathered for instrumented functions only during execution of
63 ;; this master function. Thus, if you have some defuns like:
65 ;; (defun foo () (do-something-time-intensive))
66 ;; (defun bar () (foo))
67 ;; (defun baz () (bar) (foo))
69 ;; and you want to find out the amount of time spent in bar and foo,
70 ;; but only during execution of bar, make bar the master. The call of
71 ;; foo from baz will not add to foo's total timing sums. Use M-x
72 ;; elp-set-master and M-x elp-unset-master to utilize this feature.
73 ;; Only one master function can be set at a time.
75 ;; You can restore any function's original function definition with
76 ;; elp-restore-function. The other instrument, restore, and reset
77 ;; functions are provided for symmetry.
79 ;; Here is a list of variable you can use to customize elp:
81 ;; elp-reset-after-results
82 ;; elp-sort-by-function
85 ;; Here is a list of the interactive commands you can use:
86 ;; elp-instrument-function
87 ;; elp-restore-function
88 ;; elp-instrument-list
90 ;; elp-instrument-package
99 ;; Note that there are plenty of factors that could make the times
100 ;; reported unreliable, including the accuracy and granularity of your
101 ;; system clock, and the overhead spent in lisp calculating and
102 ;; recording the intervals. I figure the latter is pretty constant,
103 ;; so while the times may not be entirely accurate, I think they'll
104 ;; give you a good feel for the relative amount of work spent in the
105 ;; various lisp routines you are profiling. Note further that times
106 ;; are calculated using wall-clock time, so other system load will
107 ;; affect accuracy too.
111 ;; This program was inspired by the only two existing Emacs Lisp
112 ;; profilers that I'm aware of, Boaz Ben-Zvi's profile.el, and Root
113 ;; Boy Jim's profiler.el. Both were written for Emacs 18 and both were
114 ;; pretty good first shots at profiling, but I found that they didn't
115 ;; provide the functionality or interface that I wanted, so I wrote
116 ;; this. I've tested elp in XEmacs 19 and Emacs 19. There's no point
117 ;; in even trying to make this work with Emacs 18.
119 ;; Unlike previous profilers, elp uses Emacs 19's built-in function
120 ;; current-time to return interval times. This obviates the need for
121 ;; both an external C program and Emacs processes to communicate with
122 ;; such a program, and thus simplifies the package as a whole.
125 ;; Make this act like a real profiler, so that it records time spent
126 ;; in all branches of execution.
131 ;; start of user configuration variables
132 ;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
135 "Emacs Lisp Profiler"
138 (defcustom elp-function-list nil
139 "*List of functions to profile.
140 Used by the command `elp-instrument-list'."
141 :type '(repeat function)
144 (defcustom elp-reset-after-results t
145 "*Non-nil means reset all profiling info after results are displayed.
146 Results are displayed with the `elp-results' command."
150 (defcustom elp-sort-by-function 'elp-sort-by-total-time
151 "*Non-nil specifies elp results sorting function.
152 These functions are currently available:
154 elp-sort-by-call-count -- sort by the highest call count
155 elp-sort-by-total-time -- sort by the highest total time
156 elp-sort-by-average-time -- sort by the highest average times
158 You can write you're own sort function. It should adhere to the
159 interface specified by the PRED argument for the `sort' defun. Each
160 \"element of LIST\" is really a 4 element vector where element 0 is
161 the call count, element 1 is the total time spent in the function,
162 element 2 is the average time spent in the function, and element 3 is
163 the symbol's name string."
167 (defcustom elp-report-limit 1
168 "*Prevents some functions from being displayed in the results buffer.
169 If a number, no function that has been called fewer than that number
170 of times will be displayed in the output buffer. If nil, all
171 functions will be displayed."
172 :type '(choice integer
173 (const :tag "Show All" nil))
176 (defcustom elp-use-standard-output nil
177 "*Non-nil says to output to `standard-output' instead of a buffer."
181 (defcustom elp-recycle-buffers-p t
182 "*nil says to not recycle the `elp-results-buffer'.
183 In other words, a new unique buffer is create every time you run
189 ;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
190 ;; end of user configuration variables
193 (defvar elp-results-buffer "*ELP Profiling Results*"
194 "Buffer name for outputting profiling results.")
196 (defconst elp-timer-info-property 'elp-info
197 "ELP information property name.")
199 (defvar elp-all-instrumented-list nil
200 "List of all functions currently being instrumented.")
202 (defvar elp-record-p t
203 "Controls whether functions should record times or not.
204 This variable is set by the master function.")
206 (defvar elp-master nil
207 "Master function symbol.")
209 (defvar elp-not-profilable
210 '(elp-wrapper elp-elapsed-time error call-interactively apply current-time interactive-p)
211 "List of functions that cannot be profiled.
212 Those functions are used internally by the profiling code and profiling
213 them would thus lead to infinite recursion.")
215 (defun elp-not-profilable-p (fun)
216 (or (memq fun elp-not-profilable)
219 (when (subrp (symbol-function fun))
220 (eq 'unevalled (cdr (subr-arity (symbol-function fun)))))
225 (defun elp-instrument-function (funsym)
226 "Instrument FUNSYM for profiling.
227 FUNSYM must be a symbol of a defined function."
228 (interactive "aFunction to instrument: ")
229 ;; restore the function. this is necessary to avoid infinite
230 ;; recursion of already instrumented functions (i.e. elp-wrapper
231 ;; calling elp-wrapper ad infinitum). it is better to simply
232 ;; restore the function than to throw an error. this will work
233 ;; properly in the face of eval-defun because if the function was
234 ;; redefined, only the timer info will be nil'd out since
235 ;; elp-restore-function is smart enough not to trash the new
237 (elp-restore-function funsym)
238 (let* ((funguts (symbol-function funsym))
239 (infovec (vector 0 0 funguts))
240 (newguts '(lambda (&rest args))))
241 ;; We cannot profile functions used internally during profiling.
242 (when (elp-not-profilable-p funsym)
243 (error "ELP cannot profile the function: %s" funsym))
244 ;; we cannot profile macros
245 (and (eq (car-safe funguts) 'macro)
246 (error "ELP cannot profile macro: %s" funsym))
247 ;; TBD: at some point it might be better to load the autoloaded
248 ;; function instead of throwing an error. if we do this, then we
249 ;; probably want elp-instrument-package to be updated with the
250 ;; newly loaded list of functions. i'm not sure it's smart to do
251 ;; the autoload here, since that could have side effects, and
252 ;; elp-instrument-function is similar (in my mind) to defun-ish
253 ;; type functionality (i.e. it shouldn't execute the function).
254 (and (eq (car-safe funguts) 'autoload)
255 (error "ELP cannot profile autoloaded function: %s" funsym))
256 ;; put rest of newguts together
257 (if (commandp funsym)
258 (setq newguts (append newguts '((interactive)))))
259 (setq newguts (append newguts `((elp-wrapper
261 ,(when (commandp funsym)
264 ;; to record profiling times, we set the symbol's function
265 ;; definition so that it runs the elp-wrapper function with the
266 ;; function symbol as an argument. We place the old function
267 ;; definition on the info vector.
269 ;; The info vector data structure is a 3 element vector. The 0th
270 ;; element is the call-count, i.e. the total number of times this
271 ;; function has been entered. This value is bumped up on entry to
272 ;; the function so that non-local exists are still recorded. TBD:
273 ;; I haven't tested non-local exits at all, so no guarantees.
275 ;; The 1st element is the total amount of time in usecs that have
276 ;; been spent inside this function. This number is added to on
279 ;; The 2nd element is the old function definition list. This gets
280 ;; funcall'd in between start/end time retrievals. I believe that
281 ;; this lets us profile even byte-compiled functions.
283 ;; put the info vector on the property list
284 (put funsym elp-timer-info-property infovec)
286 ;; Set the symbol's new profiling function definition to run
288 (let ((advice-info (get funsym 'ad-advice-info)))
291 ;; If function is advised, don't let Advice change
292 ;; its definition from under us during the `fset'.
293 (put funsym 'ad-advice-info nil)
294 (fset funsym newguts)
295 (put funsym 'ad-advice-info advice-info))
296 (fset funsym newguts)))
298 ;; add this function to the instrumentation list
299 (unless (memq funsym elp-all-instrumented-list)
300 (push funsym elp-all-instrumented-list))))
302 (defun elp-restore-function (funsym)
303 "Restore an instrumented function to its original definition.
304 Argument FUNSYM is the symbol of a defined function."
305 (interactive "aFunction to restore: ")
306 (let ((info (get funsym elp-timer-info-property)))
307 ;; delete the function from the all instrumented list
308 (setq elp-all-instrumented-list
309 (delq funsym elp-all-instrumented-list))
311 ;; if the function was the master, reset the master
312 (if (eq funsym elp-master)
316 ;; zap the properties
317 (put funsym elp-timer-info-property nil)
319 ;; restore the original function definition, but if the function
320 ;; wasn't instrumented do nothing. we do this after the above
321 ;; because its possible the function got un-instrumented due to
322 ;; circumstances beyond our control. Also, check to make sure
323 ;; that the current function symbol points to elp-wrapper. If
324 ;; not, then the user probably did an eval-defun, or loaded a
325 ;; byte-compiled version, while the function was instrumented and
326 ;; we don't want to destroy the new definition. can it ever be
327 ;; the case that a lisp function can be compiled instrumented?
330 (not (byte-code-function-p (symbol-function funsym)))
331 (assq 'elp-wrapper (symbol-function funsym))
332 (fset funsym (aref info 2)))))
335 (defun elp-instrument-list (&optional list)
336 "Instrument for profiling, all functions in `elp-function-list'.
337 Use optional LIST if provided instead."
338 (interactive "PList of functions to instrument: ")
339 (let ((list (or list elp-function-list)))
340 (mapcar 'elp-instrument-function list)))
343 (defun elp-instrument-package (prefix)
344 "Instrument for profiling, all functions which start with PREFIX.
345 For example, to instrument all ELP functions, do the following:
347 \\[elp-instrument-package] RET elp- RET"
348 (interactive "sPrefix of package to instrument: ")
349 (if (zerop (length prefix))
350 (error "Instrumenting all Emacs functions would render Emacs unusable"))
358 (not (or (memq (car-safe (symbol-function sym)) '(autoload macro))
359 (elp-not-profilable-p sym)))))))))
361 (defun elp-restore-list (&optional list)
362 "Restore the original definitions for all functions in `elp-function-list'.
363 Use optional LIST if provided instead."
364 (interactive "PList of functions to restore: ")
365 (let ((list (or list elp-function-list)))
366 (mapcar 'elp-restore-function list)))
368 (defun elp-restore-all ()
369 "Restores the original definitions of all functions being profiled."
371 (elp-restore-list elp-all-instrumented-list))
374 (defun elp-reset-function (funsym)
375 "Reset the profiling information for FUNSYM."
376 (interactive "aFunction to reset: ")
377 (let ((info (get funsym elp-timer-info-property)))
379 (error "%s is not instrumented for profiling" funsym))
380 (aset info 0 0) ;reset call counter
381 (aset info 1 0.0) ;reset total time
382 ;; don't muck with aref 2 as that is the old symbol definition
385 (defun elp-reset-list (&optional list)
386 "Reset the profiling information for all functions in `elp-function-list'.
387 Use optional LIST if provided instead."
388 (interactive "PList of functions to reset: ")
389 (let ((list (or list elp-function-list)))
390 (mapcar 'elp-reset-function list)))
392 (defun elp-reset-all ()
393 "Reset the profiling information for all functions being profiled."
395 (elp-reset-list elp-all-instrumented-list))
397 (defun elp-set-master (funsym)
398 "Set the master function for profiling."
399 (interactive "aMaster function: ")
400 ;; when there's a master function, recording is turned off by
402 (setq elp-master funsym
404 ;; make sure master function is instrumented
405 (or (memq funsym elp-all-instrumented-list)
406 (elp-instrument-function funsym)))
408 (defun elp-unset-master ()
409 "Unsets the master function."
411 ;; when there's no master function, recording is turned on by default.
416 (defsubst elp-elapsed-time (start end)
417 (+ (* (- (car end) (car start)) 65536.0)
418 (- (car (cdr end)) (car (cdr start)))
419 (/ (- (car (cdr (cdr end))) (car (cdr (cdr start)))) 1000000.0)))
421 (defun elp-wrapper (funsym interactive-p args)
422 "This function has been instrumented for profiling by the ELP.
423 ELP is the Emacs Lisp Profiler. To restore the function to its
424 original definition, use \\[elp-restore-function] or \\[elp-restore-all]."
425 ;; turn on recording if this is the master function
427 (eq funsym elp-master))
428 (setq elp-record-p t))
429 ;; get info vector and original function symbol
430 (let* ((info (get funsym elp-timer-info-property))
434 (error "%s is not instrumented for profiling" funsym))
435 (if (not elp-record-p)
436 ;; when not recording, just call the original function symbol
437 ;; and return the results.
440 (call-interactively func)
442 ;; we are recording times
443 (let (enter-time exit-time)
444 ;; increment the call-counter
445 (aset info 0 (1+ (aref info 0)))
446 ;; now call the old symbol function, checking to see if it
447 ;; should be called interactively. make sure we return the
450 (setq enter-time (current-time)
451 result (call-interactively func)
452 exit-time (current-time))
453 (setq enter-time (current-time)
454 result (apply func args)
455 exit-time (current-time)))
456 ;; calculate total time in function
457 (aset info 1 (+ (aref info 1) (elp-elapsed-time enter-time exit-time)))
459 ;; turn off recording if this is the master function
461 (eq funsym elp-master))
462 (setq elp-record-p nil))
466 ;; shut the byte-compiler up
467 (defvar elp-field-len nil)
468 (defvar elp-cc-len nil)
469 (defvar elp-at-len nil)
470 (defvar elp-et-len nil)
472 (defun elp-sort-by-call-count (vec1 vec2)
473 ;; sort by highest call count. See `sort'.
474 (>= (aref vec1 0) (aref vec2 0)))
476 (defun elp-sort-by-total-time (vec1 vec2)
477 ;; sort by highest total time spent in function. See `sort'.
478 (>= (aref vec1 1) (aref vec2 1)))
480 (defun elp-sort-by-average-time (vec1 vec2)
481 ;; sort by highest average time spent in function. See `sort'.
482 (>= (aref vec1 2) (aref vec2 2)))
484 (defsubst elp-pack-number (number width)
485 ;; pack the NUMBER string into WIDTH characters, watching out for
486 ;; very small or large numbers
487 (if (<= (length number) width)
489 ;; check for very large or small numbers
490 (if (string-match "^\\(.*\\)\\(e[+-].*\\)$" number)
492 (substring number (match-beginning 1) (match-end 1))
494 (- width (match-end 2) (- (match-beginning 2)) 3))
496 (substring number (match-beginning 2) (match-end 2)))
497 (concat (substring number 0 width)))))
499 (defun elp-output-result (resultvec)
500 ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or
501 ;; more element vector where aref 0 is the call count, aref 1 is the
502 ;; total time spent in the function, aref 2 is the average time
503 ;; spent in the function, and aref 3 is the symbol's string
504 ;; name. All other elements in the vector are ignored.
505 (let* ((cc (aref resultvec 0))
506 (tt (aref resultvec 1))
507 (at (aref resultvec 2))
508 (symname (aref resultvec 3))
509 callcnt totaltime avetime)
510 (setq callcnt (number-to-string cc)
511 totaltime (number-to-string tt)
512 avetime (number-to-string at))
513 ;; possibly prune the results
514 (if (and elp-report-limit
515 (numberp elp-report-limit)
516 (< cc elp-report-limit))
519 (insert-char 32 (+ elp-field-len (- (length symname)) 2))
520 ;; print stuff out, formatting it nicely
522 (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2))
523 (let ((ttstr (elp-pack-number totaltime elp-et-len))
524 (atstr (elp-pack-number avetime elp-at-len)))
526 (insert-char 32 (+ elp-et-len (- (length ttstr)) 2))
531 (defun elp-results ()
532 "Display current profiling results.
533 If `elp-reset-after-results' is non-nil, then current profiling
534 information for all instrumented functions are reset after results are
537 (let ((curbuf (current-buffer))
538 (resultsbuf (if elp-recycle-buffers-p
539 (get-buffer-create elp-results-buffer)
540 (generate-new-buffer elp-results-buffer))))
541 (set-buffer resultsbuf)
543 (beginning-of-buffer)
544 ;; get the length of the longest function name being profiled
546 (title "Function Name")
547 (titlelen (length title))
548 (elp-field-len titlelen)
549 (cc-header "Call Count")
550 (elp-cc-len (length cc-header))
551 (et-header "Elapsed Time")
552 (elp-et-len (length et-header))
553 (at-header "Average Time")
554 (elp-at-len (length at-header))
559 (let* ((info (get funsym elp-timer-info-property))
560 (symname (format "%s" funsym))
564 (insert "No profiling information found for: "
566 (setq longest (max longest (length symname)))
567 (vector cc tt (if (zerop cc)
568 0.0 ;avoid arithmetic div-by-zero errors
569 (/ (float tt) (float cc)))
571 elp-all-instrumented-list))
574 (if (> longest titlelen)
576 (insert-char 32 (- longest titlelen))
577 (setq elp-field-len longest)))
578 (insert " " cc-header " " et-header " " at-header "\n")
579 (insert-char ?= elp-field-len)
581 (insert-char ?= elp-cc-len)
583 (insert-char ?= elp-et-len)
585 (insert-char ?= elp-at-len)
587 ;; if sorting is enabled, then sort the results list. in either
588 ;; case, call elp-output-result to output the result in the
590 (if elp-sort-by-function
591 (setq resvec (sort resvec elp-sort-by-function)))
592 (mapcar 'elp-output-result resvec))
593 ;; now pop up results buffer
595 (pop-to-buffer resultsbuf)
596 ;; copy results to standard-output?
597 (if (or elp-use-standard-output noninteractive)
598 (princ (buffer-substring (point-min) (point-max))))
599 ;; reset profiling info if desired
600 (and elp-reset-after-results
603 (defun elp-unload-hook ()