1 ;;; elp.el --- Emacs Lisp Profiler
3 ;; Copyright (C) 1994 Free Software Foundation, Inc.
5 ;; Author: 1994 Barry A. Warsaw <bwarsaw@cnri.reston.va.us>
6 ;; Maintainer: tools-help@anthem.nlm.nih.gov
7 ;; Created: 26-Feb-1994
9 ;; Last Modified: 1994/12/28 22:39:31
10 ;; Keywords: Emacs Lisp Profile Timing
12 ;; This file is part of GNU Emacs.
14 ;; GNU Emacs is free software; you can redistribute it and/or modify
15 ;; it under the terms of the GNU General Public License as published by
16 ;; the Free Software Foundation; either version 2, or (at your option)
19 ;; GNU Emacs is distributed in the hope that it will be useful,
20 ;; but WITHOUT ANY WARRANTY; without even the implied warranty of
21 ;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
22 ;; GNU General Public License for more details.
24 ;; You should have received a copy of the GNU General Public License
25 ;; along with GNU Emacs; see the file COPYING. If not, write to the
26 ;; Free Software Foundation, Inc., 59 Temple Place - Suite 330,
27 ;; Boston, MA 02111-1307, USA.
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. With elp-reset-after-results set to non-nil,
36 ;; profiling information will be reset whenever the results are
37 ;; displayed. You can also reset all profiling info at any time with
40 ;; You can also instrument all functions in a package, provided that
41 ;; the package follows the GNU coding standard of a common textural
42 ;; prefix. Use M-x elp-instrument-package for this.
44 ;; If you want to sort the results, set elp-sort-by-function to some
45 ;; predicate function. The three most obvious choices are predefined:
46 ;; elp-sort-by-call-count, elp-sort-by-average-time, and
47 ;; elp-sort-by-total-time. Also, you can prune from the output, all
48 ;; functions that have been called fewer than a given number of times
49 ;; by setting elp-report-limit.
51 ;; Elp can instrument byte-compiled functions just as easily as
52 ;; interpreted functions, but it cannot instrument macros. However,
53 ;; when you redefine a function (e.g. with eval-defun), you'll need to
54 ;; re-instrument it with M-x elp-instrument-function. This will also
55 ;; reset profiling information for that function. Elp can handle
56 ;; interactive functions (i.e. commands), but of course any time spent
57 ;; idling for user prompts will show up in the timing results.
59 ;; You can also designate a `master' function. Profiling times will
60 ;; be gathered for instrumented functions only during execution of
61 ;; this master function. Thus, if you have some defuns like:
63 ;; (defun foo () (do-something-time-intensive))
64 ;; (defun bar () (foo))
65 ;; (defun baz () (bar) (foo))
67 ;; and you want to find out the amount of time spent in bar and foo,
68 ;; but only during execution of bar, make bar the master. The call of
69 ;; foo from baz will not add to foo's total timing sums. Use M-x
70 ;; elp-set-master and M-x elp-unset-master to utilize this feature.
71 ;; Only one master function can be set at a time.
73 ;; You can restore any function's original function definition with
74 ;; elp-restore-function. The other instrument, restore, and reset
75 ;; functions are provided for symmetry.
77 ;; Note that there are plenty of factors that could make the times
78 ;; reported unreliable, including the accuracy and granularity of your
79 ;; system clock, and the overhead spent in lisp calculating and
80 ;; recording the intervals. The latter I figure is pretty constant
81 ;; so, while the times may not be entirely accurate, I think they'll
82 ;; give you a good feel for the relative amount of work spent in the
83 ;; various lisp routines you are profiling. Note further that times
84 ;; are calculated using wall-clock time, so other system load will
85 ;; affect accuracy too.
87 ;; Here is a list of variable you can use to customize elp:
89 ;; elp-reset-after-results
90 ;; elp-sort-by-function
93 ;; Here is a list of the interactive commands you can use:
94 ;; elp-instrument-function
95 ;; elp-restore-function
96 ;; elp-instrument-list
98 ;; elp-instrument-package
100 ;; elp-reset-function
106 ;; elp-submit-bug-report
108 ;; Note that there are plenty of factors that could make the times
109 ;; reported unreliable, including the accuracy and granularity of your
110 ;; system clock, and the overhead spent in lisp calculating and
111 ;; recording the intervals. I figure the latter is pretty constant,
112 ;; so while the times may not be entirely accurate, I think they'll
113 ;; give you a good feel for the relative amount of work spent in the
114 ;; various lisp routines you are profiling. Note further that times
115 ;; are calculated using wall-clock time, so other system load will
116 ;; affect accuracy too. You cannot profile anything longer than ~18
117 ;; hours since I throw away the most significant 16 bits of seconds
118 ;; returned by current-time: 2^16 == 65536 seconds == ~1092 minutes ==
119 ;; ~18 hours. I doubt you will ever want to profile stuff on the
120 ;; order of 18 hours anyway.
124 ;; This program is based on the only two existing Emacs Lisp profilers
125 ;; that I'm aware of, Boaz Ben-Zvi's profile.el, and Root Boy Jim's
126 ;; profiler.el. Both were written for Emacs 18 and both were pretty
127 ;; good first shots at profiling, but I found that they didn't provide
128 ;; the functionality or interface that I wanted. So I wrote this.
129 ;; I've tested elp in GNU Emacs 19 and in GNU XEmacs. There's no
130 ;; point in even trying to make this work with Emacs 18.
132 ;; Unlike previous profilers, elp uses Emacs 19's built-in function
133 ;; current-time to return interval times. This obviates the need for
134 ;; both an external C program and Emacs processes to communicate with
135 ;; such a program, and thus simplifies the package as a whole.
140 ;; start user configuration variables
141 ;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
143 (defvar elp-function-list nil
144 "*List of function to profile.")
146 (defvar elp-reset-after-results t
147 "*Non-nil means reset all profiling info after results are displayed.
148 Results are displayed with the `elp-results' command.")
150 (defvar elp-sort-by-function nil
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.")
165 (defvar elp-report-limit nil
166 "*Prevents some functions from being displayed in the results buffer.
167 If a number, no function that has been called fewer than that number
168 of times will be displayed in the output buffer. If nil, all
169 functions will be displayed.")
172 ;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
173 ;; end user configuration variables
176 (defconst elp-version
"2.23"
177 "ELP version number.")
179 (defconst elp-help-address
"tools-help@anthem.nlm.nih.gov"
180 "Address accepting submissions of bug reports and questions.")
182 (defvar elp-results-buffer
"*ELP Profiling Results*"
183 "Buffer name for outputting profiling results.")
185 (defconst elp-timer-info-property
'elp-info
186 "ELP information property name.")
188 (defvar elp-all-instrumented-list nil
189 "List of all functions currently being instrumented.")
191 (defvar elp-record-p t
192 "Controls whether functions should record times or not.
193 This variable is set by the master function.")
195 (defvar elp-master nil
196 "Master function symbol.")
200 (defun elp-instrument-function (funsym)
201 "Instrument FUNSYM for profiling.
202 FUNSYM must be a symbol of a defined function."
203 (interactive "aFunction to instrument: ")
204 ;; TBD what should we do if the function is already instrumented???
205 (let* ((funguts (symbol-function funsym
))
206 (infovec (vector 0 0 funguts
))
207 (newguts '(lambda (&rest args
))))
208 ;; we cannot profile macros
209 (and (eq (car-safe funguts
) 'macro
)
210 (error "ELP cannot profile macro %s" funsym
))
211 ;; put rest of newguts together
212 (if (commandp funsym
)
213 (setq newguts
(append newguts
'((interactive)))))
214 (setq newguts
(append newguts
(list
219 (not (not (commandp funsym
))))
221 ;; to record profiling times, we set the symbol's function
222 ;; definition so that it runs the elp-wrapper function with the
223 ;; function symbol as an argument. We place the old function
224 ;; definition on the info vector.
226 ;; The info vector data structure is a 3 element vector. The 0th
227 ;; element is the call-count, i.e. the total number of times this
228 ;; function has been entered. This value is bumped up on entry to
229 ;; the function so that non-local exists are still recorded. TBD:
230 ;; I haven't tested non-local exits at all, so no guarantees.
232 ;; The 1st element is the total amount of time in usecs that have
233 ;; been spent inside this function. This number is added to on
236 ;; The 2nd element is the old function definition list. This gets
237 ;; funcall'd in between start/end time retrievals. I believe that
238 ;; this lets us profile even byte-compiled functions.
240 ;; put the info vector on the property list
241 (put funsym elp-timer-info-property infovec
)
243 ;; set the symbol's new profiling function definition to run
245 (fset funsym newguts
)
247 ;; add this function to the instrumentation list
248 (or (memq funsym elp-all-instrumented-list
)
249 (setq elp-all-instrumented-list
250 (cons funsym elp-all-instrumented-list
)))
254 (defun elp-restore-function (funsym)
255 "Restore an instrumented function to its original definition.
256 Argument FUNSYM is the symbol of a defined function."
257 (interactive "aFunction to restore: ")
258 (let ((info (get funsym elp-timer-info-property
)))
259 ;; delete the function from the all instrumented list
260 (setq elp-all-instrumented-list
261 (delq funsym elp-all-instrumented-list
))
263 ;; if the function was the master, reset the master
264 (if (eq funsym elp-master
)
268 ;; zap the properties
269 (put funsym elp-timer-info-property nil
)
271 ;; restore the original function definition, but if the function
272 ;; wasn't instrumented do nothing. we do this after the above
273 ;; because its possible the function got un-instrumented due to
274 ;; circumstances beyond our control. Also, check to make sure
275 ;; that the current function symbol points to elp-wrapper. If
276 ;; not, then the user probably did an eval-defun while the
277 ;; function was instrumented and we don't want to destroy the new
280 (assq 'elp-wrapper
(symbol-function funsym
))
281 (fset funsym
(aref info
2)))))
284 (defun elp-instrument-list (&optional list
)
285 "Instrument for profiling, all functions in `elp-function-list'.
286 Use optional LIST if provided instead."
287 (interactive "PList of functions to instrument: ")
288 (let ((list (or list elp-function-list
)))
289 (mapcar 'elp-instrument-function list
)))
292 (defun elp-instrument-package (prefix)
293 "Instrument for profiling, all functions which start with PREFIX.
294 For example, to instrument all ELP functions, do the following:
296 \\[elp-instrument-package] RET elp- RET"
297 (interactive "sPrefix of package to instrument: ")
299 (mapcar 'intern
(all-completions prefix obarray
304 (symbol-function sym
))
307 (defun elp-restore-list (&optional list
)
308 "Restore the original definitions for all functions in `elp-function-list'.
309 Use optional LIST if provided instead."
310 (interactive "PList of functions to restore: ")
311 (let ((list (or list elp-function-list
)))
312 (mapcar 'elp-restore-function list
)))
314 (defun elp-restore-all ()
315 "Restores the original definitions of all functions being profiled."
317 (elp-restore-list elp-all-instrumented-list
))
320 (defun elp-reset-function (funsym)
321 "Reset the profiling information for FUNSYM."
322 (interactive "aFunction to reset: ")
323 (let ((info (get funsym elp-timer-info-property
)))
325 (error "%s is not instrumented for profiling." funsym
))
326 (aset info
0 0) ;reset call counter
327 (aset info
1 0.0) ;reset total time
328 ;; don't muck with aref 2 as that is the old symbol definition
331 (defun elp-reset-list (&optional list
)
332 "Reset the profiling information for all functions in `elp-function-list'.
333 Use optional LIST if provided instead."
334 (interactive "PList of functions to reset: ")
335 (let ((list (or list elp-function-list
)))
336 (mapcar 'elp-reset-function list
)))
338 (defun elp-reset-all ()
339 "Reset the profiling information for all functions being profiled."
341 (elp-reset-list elp-all-instrumented-list
))
343 (defun elp-set-master (funsym)
344 "Set the master function for profiling."
345 (interactive "aMaster function: ")
346 ;; when there's a master function, recording is turned off by
348 (setq elp-master funsym
350 ;; make sure master function is instrumented
351 (or (memq funsym elp-all-instrumented-list
)
352 (elp-instrument-function funsym
)))
354 (defun elp-unset-master ()
355 "Unsets the master function."
357 ;; when there's no master function, recording is turned on by default.
362 (defsubst elp-get-time
()
363 ;; get current time in seconds and microseconds. I throw away the
364 ;; most significant 16 bits of seconds since I doubt we'll ever want
365 ;; to profile lisp on the order of 18 hours. See notes at top of file.
366 (let ((now (current-time)))
367 (+ (float (nth 1 now
)) (/ (float (nth 2 now
)) 1000000.0))))
369 (defun elp-wrapper (funsym interactive-p args
)
370 "This function has been instrumented for profiling by the ELP.
371 ELP is the Emacs Lisp Profiler. To restore the function to its
372 original definition, use \\[elp-restore-function] or \\[elp-restore-all]."
373 ;; turn on recording if this is the master function
375 (eq funsym elp-master
))
376 (setq elp-record-p t
))
377 ;; get info vector and original function symbol
378 (let* ((info (get funsym elp-timer-info-property
))
382 (error "%s is not instrumented for profiling." funsym
))
383 (if (not elp-record-p
)
384 ;; when not recording, just call the original function symbol
385 ;; and return the results.
388 (call-interactively func
)
390 ;; we are recording times
391 (let ((enter-time (elp-get-time)))
392 ;; increment the call-counter
393 (aset info
0 (1+ (aref info
0)))
394 ;; now call the old symbol function, checking to see if it
395 ;; should be called interactively. make sure we return the
399 (call-interactively func
)
401 ;; calculate total time in function
402 (aset info
1 (+ (aref info
1) (- (elp-get-time) enter-time
)))
404 ;; turn off recording if this is the master function
406 (eq funsym elp-master
))
407 (setq elp-record-p nil
))
411 ;; shut the byte-compiler up
412 (defvar elp-field-len nil
)
413 (defvar elp-cc-len nil
)
414 (defvar elp-at-len nil
)
415 (defvar elp-et-len nil
)
417 (defun elp-sort-by-call-count (vec1 vec2
)
418 ;; sort by highest call count. See `sort'.
419 (>= (aref vec1
0) (aref vec2
0)))
421 (defun elp-sort-by-total-time (vec1 vec2
)
422 ;; sort by highest total time spent in function. See `sort'.
423 (>= (aref vec1
1) (aref vec2
1)))
425 (defun elp-sort-by-average-time (vec1 vec2
)
426 ;; sort by highest average time spent in function. See `sort'.
427 (>= (aref vec1
2) (aref vec2
2)))
429 (defsubst elp-pack-number
(number width
)
430 ;; pack the NUMBER string into WIDTH characters, watching out for
431 ;; very small or large numbers
432 (if (<= (length number
) width
)
434 ;; check for very large or small numbers
435 (if (string-match "^\\(.*\\)\\(e[+-].*\\)$" number
)
437 (substring number
(match-beginning 1) (match-end 1))
439 (- width
(match-end 2) (- (match-beginning 2)) 3))
441 (substring number
(match-beginning 2) (match-end 2)))
442 (concat (substring number
0 width
)))))
444 (defun elp-output-result (resultvec)
445 ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or
446 ;; more element vector where aref 0 is the call count, aref 1 is the
447 ;; total time spent in the function, aref 2 is the average time
448 ;; spent in the function, and aref 3 is the symbol's string
449 ;; name. All other elements in the vector are ignored.
450 (let* ((cc (aref resultvec
0))
451 (tt (aref resultvec
1))
452 (at (aref resultvec
2))
453 (symname (aref resultvec
3))
454 callcnt totaltime avetime
)
455 (setq callcnt
(number-to-string cc
)
456 totaltime
(number-to-string tt
)
457 avetime
(number-to-string at
))
458 ;; possibly prune the results
459 (if (and elp-report-limit
460 (numberp elp-report-limit
)
461 (< cc elp-report-limit
))
464 (insert-char 32 (+ elp-field-len
(- (length symname
)) 2))
465 ;; print stuff out, formatting it nicely
467 (insert-char 32 (+ elp-cc-len
(- (length callcnt
)) 2))
468 (let ((ttstr (elp-pack-number totaltime elp-et-len
))
469 (atstr (elp-pack-number avetime elp-at-len
)))
471 (insert-char 32 (+ elp-et-len
(- (length ttstr
)) 2))
476 (defun elp-results ()
477 "Display current profiling results.
478 If `elp-reset-after-results' is non-nil, then current profiling
479 information for all instrumented functions are reset after results are
482 (let ((curbuf (current-buffer))
483 (resultsbuf (get-buffer-create elp-results-buffer
)))
484 (set-buffer resultsbuf
)
486 (beginning-of-buffer)
487 ;; get the length of the longest function name being profiled
489 (title "Function Name")
490 (titlelen (length title
))
491 (elp-field-len titlelen
)
492 (cc-header "Call Count")
493 (elp-cc-len (length cc-header
))
494 (et-header "Elapsed Time")
495 (elp-et-len (length et-header
))
496 (at-header "Average Time")
497 (elp-at-len (length at-header
))
502 (let* ((info (get funsym elp-timer-info-property
))
503 (symname (format "%s" funsym
))
507 (insert "No profiling information found for: "
509 (setq longest
(max longest
(length symname
)))
510 (vector cc tt
(if (zerop cc
)
511 0.0 ;avoid arithmetic div-by-zero errors
512 (/ (float tt
) (float cc
)))
514 elp-all-instrumented-list
))
517 (if (> longest titlelen
)
519 (insert-char 32 (- longest titlelen
))
520 (setq elp-field-len longest
)))
521 (insert " " cc-header
" " et-header
" " at-header
"\n")
522 (insert-char ?
= elp-field-len
)
524 (insert-char ?
= elp-cc-len
)
526 (insert-char ?
= elp-et-len
)
528 (insert-char ?
= elp-at-len
)
530 ;; if sorting is enabled, then sort the results list. in either
531 ;; case, call elp-output-result to output the result in the
533 (if elp-sort-by-function
534 (setq resvec
(sort resvec elp-sort-by-function
)))
535 (mapcar 'elp-output-result resvec
))
536 ;; now pop up results buffer
538 (pop-to-buffer resultsbuf
)
539 ;; reset profiling info if desired
540 (and elp-reset-after-results
548 (defun elp-submit-bug-report ()
549 "Submit via mail, a bug report on elp."
552 (y-or-n-p "Do you want to submit a report on elp? ")
554 (reporter-submit-bug-report
555 elp-help-address
(concat "elp " elp-version
)
557 elp-reset-after-results
558 elp-sort-by-function
))))