Mercurial > emacs
comparison lisp/emacs-lisp/elp.el @ 8735:d1f0811de024
Initial revision
author | Richard M. Stallman <rms@gnu.org> |
---|---|
date | Wed, 14 Sep 1994 09:03:27 +0000 |
parents | |
children | e1b824af0849 |
comparison
equal
deleted
inserted
replaced
8734:bd55f44d82f1 | 8735:d1f0811de024 |
---|---|
1 ;;; elp.el --- Emacs Lisp Profiler | |
2 | |
3 ;; Author: 1994 Barry A. Warsaw, Century Computing, Inc. <bwarsaw@cen.com> | |
4 ;; Maintainer: bwarsaw@cen.com | |
5 ;; Created: 26-Feb-1994 | |
6 ;; Version: 2.11 | |
7 ;; Last Modified: 1994/06/06 22:38:07 | |
8 ;; Keywords: Emacs Lisp Profile Timing | |
9 | |
10 ;; Copyright (C) 1994 Barry A. Warsaw | |
11 | |
12 ;; This file is not yet part of GNU Emacs. | |
13 ;; | |
14 ;; This program 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 of the License, or | |
17 ;; (at your option) any later version. | |
18 ;; | |
19 ;; This program 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. | |
23 ;; | |
24 ;; You should have received a copy of the GNU General Public License | |
25 ;; along with this program; if not, write to the Free Software | |
26 ;; Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. | |
27 | |
28 ;; LCD Archive Entry: | |
29 ;; elp|Barry A. Warsaw|tools-help@anthem.nlm.nih.gov| | |
30 ;; Emacs Lisp Profiler| | |
31 ;; 1994/06/06 22:38:07|2.11|~/misc/elp.el.Z| | |
32 | |
33 ;;; Commentary: | |
34 ;; | |
35 ;; This program is based on the only two existing Emacs Lisp profilers | |
36 ;; that I'm aware of, Boaz Ben-Zvi's profile.el, and Root Boy Jim's | |
37 ;; profiler.el. Both were written for Emacs 18 and both were pretty | |
38 ;; good first shots at profiling, but I found that they didn't provide | |
39 ;; the functionality or interface that I wanted. So I wrote this. | |
40 ;; I've tested elp in Lucid Emacs 19.9 and in Emacs 19.22. There's no | |
41 ;; point in even trying to make this work with Emacs 18. | |
42 | |
43 ;; Unlike previous profilers, elp uses Emacs 19's built-in function | |
44 ;; current-time to return interval times. This obviates the need for | |
45 ;; both an external C program and Emacs processes to communicate with | |
46 ;; such a program, and thus simplifies the package as a whole. One | |
47 ;; small shortcut: I throw away the most significant 16 bits of | |
48 ;; seconds returned by current-time since I doubt anyone will ever | |
49 ;; want to profile stuff on the order of 18 hours. 2^16 == 65536 | |
50 ;; seconds == ~1092 minutes == ~18 hours. | |
51 | |
52 ;; Note that there are plenty of factors that could make the times | |
53 ;; reported unreliable, including the accuracy and granularity of your | |
54 ;; system clock, and the overhead spent in lisp calculating and | |
55 ;; recording the intervals. The latter I figure is pretty constant | |
56 ;; so, while the times may not be entirely accurate, I think they'll | |
57 ;; give you a good feel for the relative amount of work spent in the | |
58 ;; various lisp routines you are profiling. Note further that times | |
59 ;; are calculated using wall-clock time, so other system load will | |
60 ;; affect accuracy too. | |
61 | |
62 ;; There are only 3 variables you can change to customize behavior of | |
63 ;; elp. See below for their description. | |
64 ;; | |
65 ;; Here is a list of the interactive commands you can use: | |
66 ;; elp-instrument-function | |
67 ;; elp-restore-function | |
68 ;; elp-instrument-list | |
69 ;; elp-restore-list | |
70 ;; elp-restore-all | |
71 ;; elp-reset-function | |
72 ;; elp-reset-list | |
73 ;; elp-reset-all | |
74 ;; elp-results | |
75 ;; elp-submit-bug-report | |
76 ;; | |
77 ;; Here are some brief usage notes. If you want to profile a bunch of | |
78 ;; functions, set elp-function-list to the list of symbols, then call | |
79 ;; elp-instrument-list. This hacks the functions so that profiling | |
80 ;; information is recorded whenever they are called. To print out the | |
81 ;; current results, use elp-results. With elp-reset-after-results set | |
82 ;; to non-nil, profiling information will be reset whenever the | |
83 ;; results are displayed, but you can reset all profiling info with | |
84 ;; elp-reset-all. | |
85 ;; | |
86 ;; If you want to sort the results, set elp-sort-by-function to some | |
87 ;; predicate function. The three most obvious choices are predefined: | |
88 ;; elp-sort-by-call-count, elp-sort-by-average-time, and | |
89 ;; elp-sort-by-total-time. | |
90 ;; | |
91 ;; Elp can instrument byte-compiled functions just as easily as | |
92 ;; interpreted functions. However, when you redefine a function (e.g. | |
93 ;; with eval-defun), you'll need to re-instrument it with | |
94 ;; elp-instrument-function. Re-instrumenting resets profiling | |
95 ;; information for that function. Elp can also handle interactive | |
96 ;; functions (i.e. commands), but of course any time spent idling for | |
97 ;; user prompts will show up in the timing results. | |
98 ;; | |
99 ;; You can also designate a `master' function. Profiling times will | |
100 ;; be gathered for instrumented functions only during execution of | |
101 ;; this master function. Thus, if you have some defuns like: | |
102 ;; | |
103 ;; (defun foo () (do-something-time-intensive)) | |
104 ;; (defun bar () (foo)) | |
105 ;; (defun baz () (bar) (foo)) | |
106 ;; | |
107 ;; and you want to find out the amount of time spent in bar and foo, | |
108 ;; but only during execution of bar, make bar the master and the call | |
109 ;; of foo from baz will not add to foo's total timing sums. Use | |
110 ;; elp-set-master and elp-unset-master to utilize this feature. Only | |
111 ;; one master function can be used at a time. | |
112 | |
113 ;; You can restore any function's original function definition with | |
114 ;; elp-restore-function. The other instrument, restore, and reset | |
115 ;; functions are provided for symmetry. | |
116 | |
117 ;;; Code: | |
118 | |
119 | |
120 ;; start user configuration variables | |
121 ;; vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv | |
122 | |
123 (defvar elp-function-list nil | |
124 "*List of function to profile.") | |
125 | |
126 (defvar elp-reset-after-results t | |
127 "*Non-nil means reset all profiling info after results are displayed. | |
128 Results are displayed with the `elp-results' command.") | |
129 | |
130 (defvar elp-sort-by-function nil | |
131 "*Non-nil specifies elp results sorting function. | |
132 These functions are currently available: | |
133 | |
134 elp-sort-by-call-count -- sort by the highest call count | |
135 elp-sort-by-total-time -- sort by the highest total time | |
136 elp-sort-by-average-time -- sort by the highest average times | |
137 | |
138 You can write you're own sort function. It should adhere to the | |
139 interface specified by the PRED argument for the `sort' defun. Each | |
140 \"element of LIST\" is really a 4 element vector where element 0 is | |
141 the call count, element 1 is the total time spent in the function, | |
142 element 2 is the average time spent in the function, and element 3 is | |
143 the symbol's name string.") | |
144 | |
145 | |
146 ;; ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ | |
147 ;; end user configuration variables | |
148 | |
149 | |
150 (defconst elp-version "2.11" | |
151 "ELP version number.") | |
152 | |
153 (defconst elp-help-address "tools-help@anthem.nlm.nih.gov" | |
154 "Address accepting submissions of bug reports and questions.") | |
155 | |
156 (defvar elp-results-buffer "*ELP Profiling Results*" | |
157 "Buffer name for outputting profiling results.") | |
158 | |
159 (defconst elp-timer-info-property 'elp-info | |
160 "ELP information property name.") | |
161 | |
162 (defvar elp-all-instrumented-list nil | |
163 "List of all functions currently being instrumented.") | |
164 | |
165 (defvar elp-record-p t | |
166 "Controls whether functions should record times or not. | |
167 This variable is set by the master function.") | |
168 | |
169 (defvar elp-master nil | |
170 "Master function symbol.") | |
171 | |
172 | |
173 (defun elp-instrument-function (funsym) | |
174 "Instrument FUNSYM for profiling. | |
175 FUNSYM must be a symbol of a defined function." | |
176 (interactive "aFunction to instrument: ") | |
177 ;; TBD what should we do if the function is already instrumented??? | |
178 (let* ((funguts (symbol-function funsym)) | |
179 (infovec (vector 0 0 funguts)) | |
180 (newguts '(lambda (&rest args)))) | |
181 ;; put rest of newguts together | |
182 (if (commandp funsym) | |
183 (setq newguts (append newguts '((interactive))))) | |
184 (setq newguts (append newguts (list | |
185 (list 'elp-wrapper | |
186 (list 'quote funsym) | |
187 (list 'and | |
188 '(interactive-p) | |
189 (not (not (commandp funsym)))) | |
190 'args)))) | |
191 ;; to record profiling times, we set the symbol's function | |
192 ;; definition so that it runs the elp-wrapper function with the | |
193 ;; function symbol as an argument. We place the old function | |
194 ;; definition on the info vector. | |
195 ;; | |
196 ;; The info vector data structure is a 3 element vector. The 0th | |
197 ;; element is the call-count, i.e. the total number of times this | |
198 ;; function has been entered. This value is bumped up on entry to | |
199 ;; the function so that non-local exists are still recorded. TBD: | |
200 ;; I haven't tested non-local exits at all, so no guarantees. | |
201 ;; | |
202 ;; The 1st element is the total amount of time in usecs that have | |
203 ;; been spent inside this function. This number is added to on | |
204 ;; function exit. | |
205 ;; | |
206 ;; The 2nd element is the old function definition list. This gets | |
207 ;; funcall'd in between start/end time retrievals. I believe that | |
208 ;; this lets us profile even byte-compiled functions. | |
209 | |
210 ;; put the info vector on the property list | |
211 (put funsym elp-timer-info-property infovec) | |
212 | |
213 ;; set the symbol's new profiling function definition to run | |
214 ;; elp-wrapper | |
215 (fset funsym newguts) | |
216 | |
217 ;; add this function to the instrumentation list | |
218 (or (memq funsym elp-all-instrumented-list) | |
219 (setq elp-all-instrumented-list | |
220 (cons funsym elp-all-instrumented-list))) | |
221 )) | |
222 | |
223 (defun elp-restore-function (funsym) | |
224 "Restore an instrumented function to its original definition. | |
225 Argument FUNSYM is the symbol of a defined function." | |
226 (interactive "aFunction to restore: ") | |
227 (let ((info (get funsym elp-timer-info-property))) | |
228 ;; delete the function from the all instrumented list | |
229 (setq elp-all-instrumented-list | |
230 (delq funsym elp-all-instrumented-list)) | |
231 | |
232 ;; if the function was the master, reset the master | |
233 (if (eq funsym elp-master) | |
234 (setq elp-master nil | |
235 elp-record-p t)) | |
236 | |
237 ;; zap the properties | |
238 (put funsym elp-timer-info-property nil) | |
239 | |
240 ;; restore the original function definition, but if the function | |
241 ;; wasn't instrumented do nothing. we do this after the above | |
242 ;; because its possible the function got un-instrumented due to | |
243 ;; circumstances beyond our control. Also, check to make sure | |
244 ;; that the current function symbol points to elp-wrapper. If | |
245 ;; not, then the user probably did an eval-defun while the | |
246 ;; function was instrumented and we don't want to destroy the new | |
247 ;; definition. | |
248 (and info | |
249 (assq 'elp-wrapper (symbol-function funsym)) | |
250 (fset funsym (aref info 2))))) | |
251 | |
252 (defun elp-instrument-list (&optional list) | |
253 "Instrument for profiling, all functions in `elp-function-list'. | |
254 Use optional LIST if provided instead." | |
255 (interactive "PList of functions to instrument: ") | |
256 (let ((list (or list elp-function-list))) | |
257 (mapcar 'elp-instrument-function list))) | |
258 | |
259 (defun elp-restore-list (&optional list) | |
260 "Restore the original definitions for all functions in `elp-function-list'. | |
261 Use optional LIST if provided instead." | |
262 (interactive "PList of functions to restore: ") | |
263 (let ((list (or list elp-function-list))) | |
264 (mapcar 'elp-restore-function list))) | |
265 | |
266 (defun elp-restore-all () | |
267 "Restores the original definitions of all functions being profiled." | |
268 (interactive) | |
269 (elp-restore-list elp-all-instrumented-list)) | |
270 | |
271 | |
272 (defun elp-reset-function (funsym) | |
273 "Reset the profiling information for FUNSYM." | |
274 (interactive "aFunction to reset: ") | |
275 (let ((info (get funsym elp-timer-info-property))) | |
276 (or info | |
277 (error "%s is not instrumented for profiling." funsym)) | |
278 (aset info 0 0) ;reset call counter | |
279 (aset info 1 0.0) ;reset total time | |
280 ;; don't muck with aref 2 as that is the old symbol definition | |
281 )) | |
282 | |
283 (defun elp-reset-list (&optional list) | |
284 "Reset the profiling information for all functions in `elp-function-list'. | |
285 Use optional LIST if provided instead." | |
286 (interactive "PList of functions to reset: ") | |
287 (let ((list (or list elp-function-list))) | |
288 (mapcar 'elp-reset-function list))) | |
289 | |
290 (defun elp-reset-all () | |
291 "Reset the profiling information for all functions being profiled." | |
292 (interactive) | |
293 (elp-reset-list elp-all-instrumented-list)) | |
294 | |
295 (defun elp-set-master (funsym) | |
296 "Set the master function for profiling." | |
297 (interactive "aMaster function: ") | |
298 ;; when there's a master function, recording is turned off by | |
299 ;; default | |
300 (setq elp-master funsym | |
301 elp-record-p nil) | |
302 ;; make sure master function is instrumented | |
303 (or (memq funsym elp-all-instrumented-list) | |
304 (elp-instrument-function funsym))) | |
305 | |
306 (defun elp-unset-master () | |
307 "Unsets the master function." | |
308 ;; when there's no master function, recording is turned on by default. | |
309 (setq elp-master nil | |
310 elp-record-p t)) | |
311 | |
312 | |
313 (defsubst elp-get-time () | |
314 ;; get current time in seconds and microseconds. I throw away the | |
315 ;; most significant 16 bits of seconds since I doubt we'll ever want | |
316 ;; to profile lisp on the order of 18 hours. See notes at top of file. | |
317 (let ((now (current-time))) | |
318 (+ (float (nth 1 now)) (/ (float (nth 2 now)) 1000000.0)))) | |
319 | |
320 (defun elp-wrapper (funsym interactive-p args) | |
321 "This function has been instrumented for profiling by the ELP. | |
322 ELP is the Emacs Lisp Profiler. To restore the function to its | |
323 original definition, use \\[elp-restore-function] or \\[elp-restore-all]." | |
324 ;; turn on recording if this is the master function | |
325 (if (and elp-master | |
326 (eq funsym elp-master)) | |
327 (setq elp-record-p t)) | |
328 ;; get info vector and original function symbol | |
329 (let* ((info (get funsym elp-timer-info-property)) | |
330 (func (aref info 2)) | |
331 result) | |
332 (or func | |
333 (error "%s is not instrumented for profiling." funsym)) | |
334 (if (not elp-record-p) | |
335 ;; when not recording, just call the original function symbol | |
336 ;; and return the results. | |
337 (setq result | |
338 (if interactive-p | |
339 (call-interactively func) | |
340 (apply func args))) | |
341 ;; we are recording times | |
342 (let ((enter-time (elp-get-time))) | |
343 ;; increment the call-counter | |
344 (aset info 0 (1+ (aref info 0))) | |
345 ;; now call the old symbol function, checking to see if it | |
346 ;; should be called interactively. make sure we return the | |
347 ;; correct value | |
348 (setq result | |
349 (if interactive-p | |
350 (call-interactively func) | |
351 (apply func args))) | |
352 ;; calculate total time in function | |
353 (aset info 1 (+ (aref info 1) (- (elp-get-time) enter-time))) | |
354 )) | |
355 ;; turn off recording if this is the master function | |
356 (if (and elp-master | |
357 (eq funsym elp-master)) | |
358 (setq elp-record-p nil)) | |
359 result)) | |
360 | |
361 | |
362 ;; shut the byte-compiler up | |
363 (defvar elp-field-len nil) | |
364 (defvar elp-cc-len nil) | |
365 (defvar elp-at-len nil) | |
366 (defvar elp-et-len nil) | |
367 | |
368 (defun elp-sort-by-call-count (vec1 vec2) | |
369 ;; sort by highest call count. See `sort'. | |
370 (>= (aref vec1 0) (aref vec2 0))) | |
371 | |
372 (defun elp-sort-by-total-time (vec1 vec2) | |
373 ;; sort by highest total time spent in function. See `sort'. | |
374 (>= (aref vec1 1) (aref vec2 1))) | |
375 | |
376 (defun elp-sort-by-average-time (vec1 vec2) | |
377 ;; sort by highest average time spent in function. See `sort'. | |
378 (>= (aref vec1 2) (aref vec2 2))) | |
379 | |
380 (defun elp-output-result (resultvec) | |
381 ;; output the RESULTVEC into the results buffer. RESULTVEC is a 4 or | |
382 ;; more element vector where aref 0 is the call count, aref 1 is the | |
383 ;; total time spent in the function, aref 2 is the average time | |
384 ;; spent in the function, and aref 3 is the symbol's string | |
385 ;; name. All other elements in the vector are ignored. | |
386 (let* ((cc (aref resultvec 0)) | |
387 (tt (aref resultvec 1)) | |
388 (at (aref resultvec 2)) | |
389 (symname (aref resultvec 3)) | |
390 callcnt totaltime avetime) | |
391 (insert symname) | |
392 (insert-char 32 (+ elp-field-len (- (length symname)) 2)) | |
393 (setq callcnt (number-to-string cc) | |
394 totaltime (number-to-string tt) | |
395 avetime (number-to-string at)) | |
396 ;; print stuff out, formatting it nicely | |
397 (insert callcnt) | |
398 (insert-char 32 (+ elp-cc-len (- (length callcnt)) 2)) | |
399 (if (> (length totaltime) elp-et-len) | |
400 (insert (substring totaltime 0 elp-et-len) " ") | |
401 (insert totaltime) | |
402 (insert-char 32 (+ elp-et-len (- (length totaltime)) 2))) | |
403 (if (> (length avetime) elp-at-len) | |
404 (insert (substring avetime 0 elp-at-len)) | |
405 (insert avetime)) | |
406 (insert "\n"))) | |
407 | |
408 (defun elp-results () | |
409 "Display current profiling results. | |
410 If `elp-reset-after-results' is non-nil, then current profiling | |
411 information for all instrumented functions are reset after results are | |
412 displayed." | |
413 (interactive) | |
414 (let ((curbuf (current-buffer)) | |
415 (resultsbuf (get-buffer-create elp-results-buffer))) | |
416 (set-buffer resultsbuf) | |
417 (erase-buffer) | |
418 (beginning-of-buffer) | |
419 ;; get the length of the longest function name being profiled | |
420 (let* ((longest 0) | |
421 (title "Function Name") | |
422 (titlelen (length title)) | |
423 (elp-field-len titlelen) | |
424 (cc-header "Call Count") | |
425 (elp-cc-len (length cc-header)) | |
426 (et-header "Elapsed Time") | |
427 (elp-et-len (length et-header)) | |
428 (at-header "Average Time") | |
429 (elp-at-len (length at-header)) | |
430 (resvec | |
431 (mapcar | |
432 (function | |
433 (lambda (funsym) | |
434 (let* ((info (get funsym elp-timer-info-property)) | |
435 (symname (format "%s" funsym)) | |
436 (cc (aref info 0)) | |
437 (tt (aref info 1))) | |
438 (if (not info) | |
439 (insert "No profiling information found for: " | |
440 symname) | |
441 (setq longest (max longest (length symname))) | |
442 (vector cc tt (if (zerop cc) | |
443 0.0 ;avoid arithmetic div-by-zero errors | |
444 (/ (float tt) (float cc))) | |
445 symname))))) | |
446 elp-all-instrumented-list)) | |
447 ) ; end let* | |
448 (insert title) | |
449 (if (> longest titlelen) | |
450 (progn | |
451 (insert-char 32 (- longest titlelen)) | |
452 (setq elp-field-len longest))) | |
453 (insert " " cc-header " " et-header " " at-header "\n") | |
454 (insert-char ?= elp-field-len) | |
455 (insert " ") | |
456 (insert-char ?= elp-cc-len) | |
457 (insert " ") | |
458 (insert-char ?= elp-et-len) | |
459 (insert " ") | |
460 (insert-char ?= elp-at-len) | |
461 (insert "\n") | |
462 ;; if sorting is enabled, then sort the results list. in either | |
463 ;; case, call elp-output-result to output the result in the | |
464 ;; buffer | |
465 (if elp-sort-by-function | |
466 (setq resvec (sort resvec elp-sort-by-function))) | |
467 (mapcar 'elp-output-result resvec)) | |
468 ;; now pop up results buffer | |
469 (set-buffer curbuf) | |
470 (pop-to-buffer resultsbuf) | |
471 ;; reset profiling info if desired | |
472 (and elp-reset-after-results | |
473 (elp-reset-all)))) | |
474 | |
475 | |
476 (eval-when-compile | |
477 (require 'reporter)) | |
478 | |
479 (defun elp-submit-bug-report () | |
480 "Submit via mail, a bug report on elp." | |
481 (interactive) | |
482 (and | |
483 (y-or-n-p "Do you want to submit a report on elp? ") | |
484 (require 'reporter) | |
485 (reporter-submit-bug-report | |
486 elp-help-address (concat "elp " elp-version) | |
487 '(elp-reset-after-results | |
488 elp-sort-by-function)))) | |
489 | |
490 | |
491 (provide 'elp) | |
492 ;; elp.el ends here | |
493 |