1 ;;; elp.el --- Emacs Lisp Profiler
3 ;; Copyright (C) 1994, 1995, 1997, 1998, 2001, 2002, 2003, 2004,
4 ;; 2005 Free Software Foundation, Inc.
6 ;; Author: Barry A. Warsaw
8 ;; Created: 26-Feb-1994
9 ;; Keywords: debugging lisp tools
11 ;; This file is part of GNU Emacs.
13 ;; GNU Emacs is free software; you can redistribute it and/or modify
14 ;; it under the terms of the GNU General Public License as published by
15 ;; the Free Software Foundation; either version 2, or (at your option)
18 ;; GNU Emacs is distributed in the hope that it will be useful,
19 ;; but WITHOUT ANY WARRANTY; without even the implied warranty of
20 ;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
21 ;; GNU General Public License for more details.
23 ;; You should have received a copy of the GNU General Public License
24 ;; along with GNU Emacs; see the file COPYING. If not, write to the
25 ;; Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor,
26 ;; Boston, MA 02110-1301, USA.
30 ;; If you want to profile a bunch of functions, set elp-function-list
31 ;; to the list of symbols, then do a M-x elp-instrument-list. This
32 ;; hacks those functions so that profiling information is recorded
33 ;; whenever they are called. To print out the current results, use
34 ;; M-x elp-results. If you want output to go to standard-output
35 ;; instead of a separate buffer, setq elp-use-standard-output to
36 ;; non-nil. With elp-reset-after-results set to non-nil, profiling
37 ;; information will be reset whenever the results are displayed. You
38 ;; can also reset all profiling info at any time with M-x
41 ;; You can also instrument all functions in a package, provided that
42 ;; the package follows the GNU coding standard of a common textual
43 ;; prefix. Use M-x elp-instrument-package for this.
45 ;; If you want to sort the results, set elp-sort-by-function to some
46 ;; predicate function. The three most obvious choices are predefined:
47 ;; elp-sort-by-call-count, elp-sort-by-average-time, and
48 ;; elp-sort-by-total-time. Also, you can prune from the output, all
49 ;; functions that have been called fewer than a given number of times
50 ;; by setting elp-report-limit.
52 ;; Elp can instrument byte-compiled functions just as easily as
53 ;; interpreted functions, but it cannot instrument macros. However,
54 ;; when you redefine a function (e.g. with eval-defun), you'll need to
55 ;; re-instrument it with M-x elp-instrument-function. This will also
56 ;; reset profiling information for that function. Elp can handle
57 ;; interactive functions (i.e. commands), but of course any time spent
58 ;; idling for user prompts will show up in the timing results.
60 ;; You can also designate a `master' function. Profiling times will
61 ;; be gathered for instrumented functions only during execution of
62 ;; this master function. Thus, if you have some defuns like:
64 ;; (defun foo () (do-something-time-intensive))
65 ;; (defun bar () (foo))
66 ;; (defun baz () (bar) (foo))
68 ;; and you want to find out the amount of time spent in bar and foo,
69 ;; but only during execution of bar, make bar the master. The call of
70 ;; foo from baz will not add to foo's total timing sums. Use M-x
71 ;; elp-set-master and M-x elp-unset-master to utilize this feature.
72 ;; Only one master function can be set at a time.
74 ;; You can restore any function's original function definition with
75 ;; elp-restore-function. The other instrument, restore, and reset
76 ;; functions are provided for symmetry.
78 ;; Here is a list of variable you can use to customize elp:
80 ;; elp-reset-after-results
81 ;; elp-sort-by-function
84 ;; Here is a list of the interactive commands you can use:
85 ;; elp-instrument-function
86 ;; elp-restore-function
87 ;; elp-instrument-list
89 ;; elp-instrument-package
98 ;; Note that there are plenty of factors that could make the times
99 ;; reported unreliable, including the accuracy and granularity of your
100 ;; system clock, and the overhead spent in lisp calculating and
101 ;; recording the intervals. I figure the latter is pretty constant,
102 ;; so while the times may not be entirely accurate, I think they'll
103 ;; give you a good feel for the relative amount of work spent in the
104 ;; various lisp routines you are profiling. Note further that times
105 ;; are calculated using wall-clock time, so other system load will
106 ;; affect accuracy too.
110 ;; This program was inspired by the only two existing Emacs Lisp
111 ;; profilers that I'm aware of, Boaz Ben-Zvi's profile.el, and Root
112 ;; Boy Jim's profiler.el. Both were written for Emacs 18 and both were
113 ;; pretty good first shots at profiling, but I found that they didn't
114 ;; provide the functionality or interface that I wanted, so I wrote
115 ;; this. I've tested elp in XEmacs 19 and Emacs 19. There's no point
116 ;; in even trying to make this work with Emacs 18.
118 ;; Unlike previous profilers, elp uses Emacs 19's built-in function
119 ;; current-time to return interval times. This obviates the need for
120 ;; both an external C program and Emacs processes to communicate with
121 ;; such a program, and thus simplifies the package as a whole.
124 ;; Make this act like a real profiler, so that it records time spent
125 ;; in all branches of execution.
130 ;; start of user configuration variables
131 ;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
134 "Emacs Lisp Profiler."
137 (defcustom elp-function-list nil
138 "*List of functions to profile.
139 Used by the command `elp-instrument-list'."
140 :type '(repeat function)
143 (defcustom elp-reset-after-results t
144 "*Non-nil means reset all profiling info after results are displayed.
145 Results are displayed with the `elp-results' command."
149 (defcustom elp-sort-by-function 'elp-sort-by-total-time
150 "*Non-nil specifies elp results sorting function.
151 These functions are currently available:
153 elp-sort-by-call-count -- sort by the highest call count
154 elp-sort-by-total-time -- sort by the highest total time
155 elp-sort-by-average-time -- sort by the highest average times
157 You can write you're own sort function. It should adhere to the
158 interface specified by the PRED argument for the `sort' defun. Each
159 \"element of LIST\" is really a 4 element vector where element 0 is
160 the call count, element 1 is the total time spent in the function,
161 element 2 is the average time spent in the function, and element 3 is
162 the symbol's name string."
166 (defcustom elp-report-limit 1
167 "*Prevents some functions from being displayed in the results buffer.
168 If a number, no function that has been called fewer than that number
169 of times will be displayed in the output buffer. If nil, all
170 functions will be displayed."
171 :type '(choice integer
172 (const :tag "Show All" nil))
175 (defcustom elp-use-standard-output nil
176 "*Non-nil says to output to `standard-output' instead of a buffer."
180 (defcustom elp-recycle-buffers-p t
181 "*nil says to not recycle the `elp-results-buffer'.
182 In other words, a new unique buffer is create every time you run
188 ;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
189 ;; end of user configuration variables
192 (defvar elp-results-buffer "*ELP Profiling Results*"
193 "Buffer name for outputting profiling results.")
195 (defconst elp-timer-info-property 'elp-info
196 "ELP information property name.")
198 (defvar elp-all-instrumented-list nil
199 "List of all functions currently being instrumented.")
201 (defvar elp-record-p t
202 "Controls whether functions should record times or not.
203 This variable is set by the master function.")
205 (defvar elp-master nil
206 "Master function symbol.")
208 (defvar elp-not-profilable
209 '(elp-wrapper elp-elapsed-time error call-interactively apply current-time interactive-p)
210 "List of functions that cannot be profiled.
211 Those functions are used internally by the profiling code and profiling
212 them would thus lead to infinite recursion.")
214 (defun elp-not-profilable-p (fun)
215 (or (memq fun elp-not-profilable)
218 (when (subrp (symbol-function fun))
219 (eq 'unevalled (cdr (subr-arity (symbol-function fun)))))
224 (defun elp-instrument-function (funsym)
225 "Instrument FUNSYM for profiling.
226 FUNSYM must be a symbol of a defined function."
227 (interactive "aFunction to instrument: ")
228 ;; restore the function. this is necessary to avoid infinite
229 ;; recursion of already instrumented functions (i.e. elp-wrapper
230 ;; calling elp-wrapper ad infinitum). it is better to simply
231 ;; restore the function than to throw an error. this will work
232 ;; properly in the face of eval-defun because if the function was
233 ;; redefined, only the timer info will be nil'd out since
234 ;; elp-restore-function is smart enough not to trash the new
236 (elp-restore-function funsym)
237 (let* ((funguts (symbol-function funsym))
238 (infovec (vector 0 0 funguts))
239 (newguts '(lambda (&rest args))))
240 ;; We cannot profile functions used internally during profiling.
241 (when (elp-not-profilable-p funsym)
242 (error "ELP cannot profile the function: %s" funsym))
243 ;; we cannot profile macros
244 (and (eq (car-safe funguts) 'macro)
245 (error "ELP cannot profile macro: %s" funsym))
246 ;; TBD: at some point it might be better to load the autoloaded
247 ;; function instead of throwing an error. if we do this, then we
248 ;; probably want elp-instrument-package to be updated with the
249 ;; newly loaded list of functions. i'm not sure it's smart to do
250 ;; the autoload here, since that could have side effects, and
251 ;; elp-instrument-function is similar (in my mind) to defun-ish
252 ;; type functionality (i.e. it shouldn't execute the function).
253 (and (eq (car-safe funguts) 'autoload)
254 (error "ELP cannot profile autoloaded function: %s" funsym))
255 ;; put rest of newguts together
256 (if (commandp funsym)
257 (setq newguts (append newguts '((interactive)))))
258 (setq newguts (append newguts `((elp-wrapper
260 ,(when (commandp funsym)
261 '(called-interactively-p))
263 ;; to record profiling times, we set the symbol's function
264 ;; definition so that it runs the elp-wrapper function with the
265 ;; function symbol as an argument. We place the old function
266 ;; definition on the info vector.
268 ;; The info vector data structure is a 3 element vector. The 0th
269 ;; element is the call-count, i.e. the total number of times this
270 ;; function has been entered. This value is bumped up on entry to
271 ;; the function so that non-local exists are still recorded. TBD:
272 ;; I haven't tested non-local exits at all, so no guarantees.
274 ;; The 1st element is the total amount of time in usecs that have
275 ;; been spent inside this function. This number is added to on
278 ;; The 2nd element is the old function definition list. This gets
279 ;; funcall'd in between start/end time retrievals. I believe that
280 ;; this lets us profile even byte-compiled functions.
282 ;; put the info vector on the property list
283 (put funsym elp-timer-info-property infovec)
285 ;; Set the symbol's new profiling function definition to run
287 (let ((advice-info (get funsym 'ad-advice-info)))
290 ;; If function is advised, don't let Advice change
291 ;; its definition from under us during the `fset'.
292 (put funsym 'ad-advice-info nil)
293 (fset funsym newguts)
294 (put funsym 'ad-advice-info advice-info))
295 (fset funsym newguts)))
297 ;; add this function to the instrumentation list
298 (unless (memq funsym elp-all-instrumented-list)
299 (push funsym elp-all-instrumented-list))))
301 (defun elp-restore-function (funsym)
302 "Restore an instrumented function to its original definition.
303 Argument FUNSYM is the symbol of a defined function."
304 (interactive "aFunction to restore: ")
305 (let ((info (get funsym elp-timer-info-property)))
306 ;; delete the function from the all instrumented list
307 (setq elp-all-instrumented-list
308 (delq funsym elp-all-instrumented-list))
310 ;; if the function was the master, reset the master
311 (if (eq funsym elp-master)
315 ;; zap the properties
316 (put funsym elp-timer-info-property nil)
318 ;; restore the original function definition, but if the function
319 ;; wasn't instrumented do nothing. we do this after the above
320 ;; because its possible the function got un-instrumented due to
321 ;; circumstances beyond our control. Also, check to make sure
322 ;; that the current function symbol points to elp-wrapper. If
323 ;; not, then the user probably did an eval-defun, or loaded a
324 ;; byte-compiled version, while the function was instrumented and
325 ;; we don't want to destroy the new definition. can it ever be
326 ;; the case that a lisp function can be compiled instrumented?
329 (not (byte-code-function-p (symbol-function funsym)))
330 (assq 'elp-wrapper (symbol-function funsym))
331 (fset funsym (aref info 2)))))
334 (defun elp-instrument-list (&optional list)
335 "Instrument for profiling, all functions in `elp-function-list'.
336 Use optional LIST if provided instead."
337 (interactive "PList of functions to instrument: ")
338 (let ((list (or list elp-function-list)))
339 (mapcar 'elp-instrument-function list)))
342 (defun elp-instrument-package (prefix)
343 "Instrument for profiling, all functions which start with PREFIX.
344 For example, to instrument all ELP functions, do the following:
346 \\[elp-instrument-package] RET elp- RET"
347 (interactive "sPrefix of package to instrument: ")
348 (if (zerop (length prefix))
349 (error "Instrumenting all Emacs functions would render Emacs unusable"))
357 (not (or (memq (car-safe (symbol-function sym)) '(autoload macro))
358 (elp-not-profilable-p sym)))))))))
360 (defun elp-restore-list (&optional list)
361 "Restore the original definitions for all functions in `elp-function-list'.
362 Use optional LIST if provided instead."
363 (interactive "PList of functions to restore: ")
364 (let ((list (or list elp-function-list)))
365 (mapcar 'elp-restore-function list)))
367 (defun elp-restore-all ()
368 "Restores the original definitions of all functions being profiled."
370 (elp-restore-list elp-all-instrumented-list))
373 (defun elp-reset-function (funsym)
374 "Reset the profiling information for FUNSYM."
375 (interactive "aFunction to reset: ")
376 (let ((info (get funsym elp-timer-info-property)))
378 (error "%s is not instrumented for profiling" funsym))
379 (aset info 0 0) ;reset call counter
380 (aset info 1 0.0) ;reset total time
381 ;; don't muck with aref 2 as that is the old symbol definition
384 (defun elp-reset-list (&optional list)
385 "Reset the profiling information for all functions in `elp-function-list'.
386 Use optional LIST if provided instead."
387 (interactive "PList of functions to reset: ")
388 (let ((list (or list elp-function-list)))
389 (mapcar 'elp-reset-function list)))
391 (defun elp-reset-all ()
392 "Reset the profiling information for all functions being profiled."
394 (elp-reset-list elp-all-instrumented-list))
396 (defun elp-set-master (funsym)
397 "Set the master function for profiling."
398 (interactive "aMaster function: ")
399 ;; when there's a master function, recording is turned off by
401 (setq elp-master funsym
403 ;; make sure master function is instrumented
404 (or (memq funsym elp-all-instrumented-list)
405 (elp-instrument-function funsym)))
407 (defun elp-unset-master ()
408 "Unsets the master function."
410 ;; when there's no master function, recording is turned on by default.
415 (defsubst elp-elapsed-time (start end)
416 (+ (* (- (car end) (car start)) 65536.0)
417 (- (car (cdr end)) (car (cdr start)))
418 (/ (- (car (cdr (cdr end))) (car (cdr (cdr start)))) 1000000.0)))
420 (defun elp-wrapper (funsym interactive-p args)
421 "This function has been instrumented for profiling by the ELP.
422 ELP is the Emacs Lisp Profiler. To restore the function to its
423 original definition, use \\[elp-restore-function] or \\[elp-restore-all]."
424 ;; turn on recording if this is the master function
426 (eq funsym elp-master))
427 (setq elp-record-p t))
428 ;; get info vector and original function symbol
429 (let* ((info (get funsym elp-timer-info-property))
433 (error "%s is not instrumented for profiling" funsym))
434 (if (not elp-record-p)
435 ;; when not recording, just call the original function symbol
436 ;; and return the results.
439 (call-interactively func)
441 ;; we are recording times
442 (let (enter-time exit-time)
443 ;; increment the call-counter
444 (aset info 0 (1+ (aref info 0)))
445 ;; now call the old symbol function, checking to see if it
446 ;; should be called interactively. make sure we return the
449 (setq enter-time (current-time)
450 result (call-interactively func)
451 exit-time (current-time))
452 (setq enter-time (current-time)
453 result (apply func args)
454 exit-time (current-time)))
455 ;; calculate total time in function
456 (aset info 1 (+ (aref info 1) (elp-elapsed-time enter-time exit-time)))
458 ;; turn off recording if this is the master function
460 (eq funsym elp-master))
461 (setq elp-record-p nil))
465 ;; shut the byte-compiler up
466 (defvar elp-field-len nil)
467 (defvar elp-cc-len nil)
468 (defvar elp-at-len nil)
469 (defvar elp-et-len nil)
471 (defun elp-sort-by-call-count (vec1 vec2)
472 ;; sort by highest call count. See `sort'.
473 (>= (aref vec1 0) (aref vec2 0)))
475 (defun elp-sort-by-total-time (vec1 vec2)
476 ;; sort by highest total time spent in function. See `sort'.
477 (>= (aref vec1 1) (aref vec2 1)))
479 (defun elp-sort-by-average-time (vec1 vec2)
480 ;; sort by highest average time spent in function. See `sort'.
481 (>= (aref vec1 2) (aref vec2 2)))
483 (defsubst elp-pack-number (number width)
484 ;; pack the NUMBER string into WIDTH characters, watching out for
485 ;; very small or large numbers
486 (if (<= (length number) width)
488 ;; check for very large or small numbers
489 (if (string-match "^\\(.*\\)\\(e[+-].*\\)$" number)
491 (substring number (match-beginning 1) (match-end 1))
493 (- width (match-end 2) (- (match-beginning 2)) 3))
495 (substring number (match-beginning 2) (match-end 2)))
496 (concat (substring number 0 width)))))
498 (defun elp-output-result (resultvec)
499 ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or
500 ;; more element vector where aref 0 is the call count, aref 1 is the
501 ;; total time spent in the function, aref 2 is the average time
502 ;; spent in the function, and aref 3 is the symbol's string
503 ;; name. All other elements in the vector are ignored.
504 (let* ((cc (aref resultvec 0))
505 (tt (aref resultvec 1))
506 (at (aref resultvec 2))
507 (symname (aref resultvec 3))
508 callcnt totaltime avetime)
509 (setq callcnt (number-to-string cc)
510 totaltime (number-to-string tt)
511 avetime (number-to-string at))
512 ;; possibly prune the results
513 (if (and elp-report-limit
514 (numberp elp-report-limit)
515 (< cc elp-report-limit))
517 (elp-output-insert-symname symname)
518 (insert-char 32 (+ elp-field-len (- (length symname)) 2))
519 ;; print stuff out, formatting it nicely
521 (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2))
522 (let ((ttstr (elp-pack-number totaltime elp-et-len))
523 (atstr (elp-pack-number avetime elp-at-len)))
525 (insert-char 32 (+ elp-et-len (- (length ttstr)) 2))
529 (defvar elp-results-symname-map
530 (let ((map (make-sparse-keymap)))
531 (define-key map [mouse-2] 'elp-results-jump-to-definition-by-mouse)
532 (define-key map "\C-m" 'elp-results-jump-to-definition)
534 "Keymap used on the function name column." )
536 (defun elp-results-jump-to-definition-by-mouse (event)
537 "Jump to the definition of the function under the place specified by EVENT."
539 (posn-set-point (event-end event))
540 (elp-results-jump-to-definition))
542 (defun elp-results-jump-to-definition ()
543 "Jump to the definition of the function under the point."
545 (find-function (get-text-property (point) 'elp-symname)))
547 (defun elp-output-insert-symname (symname)
548 ;; Insert SYMNAME with text properties.
549 (insert (propertize symname
550 'elp-symname (intern symname)
551 'keymap elp-results-symname-map
552 'mouse-face 'highlight
553 'help-echo (substitute-command-keys "\\{elp-results-symname-map}"))))
556 (defun elp-results ()
557 "Display current profiling results.
558 If `elp-reset-after-results' is non-nil, then current profiling
559 information for all instrumented functions are reset after results are
562 (let ((curbuf (current-buffer))
563 (resultsbuf (if elp-recycle-buffers-p
564 (get-buffer-create elp-results-buffer)
565 (generate-new-buffer elp-results-buffer))))
566 (set-buffer resultsbuf)
568 ;; get the length of the longest function name being profiled
570 (title "Function Name")
571 (titlelen (length title))
572 (elp-field-len titlelen)
573 (cc-header "Call Count")
574 (elp-cc-len (length cc-header))
575 (et-header "Elapsed Time")
576 (elp-et-len (length et-header))
577 (at-header "Average Time")
578 (elp-at-len (length at-header))
583 (let* ((info (get funsym elp-timer-info-property))
584 (symname (format "%s" funsym))
588 (insert "No profiling information found for: "
590 (setq longest (max longest (length symname)))
591 (vector cc tt (if (zerop cc)
592 0.0 ;avoid arithmetic div-by-zero errors
593 (/ (float tt) (float cc)))
595 elp-all-instrumented-list))
598 (if (> longest titlelen)
600 (insert-char 32 (- longest titlelen))
601 (setq elp-field-len longest)))
602 (insert " " cc-header " " et-header " " at-header "\n")
603 (insert-char ?= elp-field-len)
605 (insert-char ?= elp-cc-len)
607 (insert-char ?= elp-et-len)
609 (insert-char ?= elp-at-len)
611 ;; if sorting is enabled, then sort the results list. in either
612 ;; case, call elp-output-result to output the result in the
614 (if elp-sort-by-function
615 (setq resvec (sort resvec elp-sort-by-function)))
616 (mapcar 'elp-output-result resvec))
617 ;; now pop up results buffer
619 (pop-to-buffer resultsbuf)
620 ;; copy results to standard-output?
621 (if (or elp-use-standard-output noninteractive)
622 (princ (buffer-substring (point-min) (point-max))))
623 ;; reset profiling info if desired
624 (and elp-reset-after-results
627 (defun elp-unload-hook ()
629 (add-hook 'elp-unload-hook 'elp-unload-hook)
633 ;;; arch-tag: c4eef311-9b3e-4bb2-8a54-3485d41b4eb1