Commit | Line | Data |
---|---|---|
76550a57 | 1 | ;;; profile.el --- generate run time measurements of Emacs Lisp functions |
4821e2af | 2 | |
c7f8bd78 | 3 | ;; Copyright (C) 1992, 1994, 1998 Free Software Foundation, Inc. |
9750e079 | 4 | |
4821e2af | 5 | ;; Author: Boaz Ben-Zvi <boaz@lcs.mit.edu> |
e5167999 | 6 | ;; Created: 07 Feb 1992 |
4821e2af ER |
7 | ;; Version: 1.0 |
8 | ;; Adapted-By: ESR | |
d7b4d18f | 9 | ;; Keywords: lisp, tools |
ecb4184d | 10 | |
ecb4184d ER |
11 | ;; This file is part of GNU Emacs. |
12 | ||
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 | |
e5167999 | 15 | ;; the Free Software Foundation; either version 2, or (at your option) |
ecb4184d ER |
16 | ;; any later version. |
17 | ||
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. | |
22 | ||
23 | ;; You should have received a copy of the GNU General Public License | |
b578f267 EN |
24 | ;; along with GNU Emacs; see the file COPYING. If not, write to the |
25 | ;; Free Software Foundation, Inc., 59 Temple Place - Suite 330, | |
26 | ;; Boston, MA 02111-1307, USA. | |
ecb4184d | 27 | |
4821e2af | 28 | ;;; Commentary: |
ecb4184d | 29 | |
b578f267 EN |
30 | ;; DESCRIPTION: |
31 | ;; ------------ | |
32 | ;; This program can be used to monitor running time performance of Emacs Lisp | |
c7f8bd78 KH |
33 | ;; functions. It takes a list of functions and report the real time spent |
34 | ;; inside these functions. (Actually, for each function it reports the amount | |
35 | ;; of time spent while at least one instance of that function is on the call | |
36 | ;; stack. So if profiled function FOO calls profiled function BAR, the time | |
37 | ;; spent inside BAR is credited to both functions.) | |
ecb4184d | 38 | |
b578f267 EN |
39 | ;; HOW TO USE: |
40 | ;; ----------- | |
41 | ;; Set the variable profile-functions-list to the list of functions | |
c7f8bd78 KH |
42 | ;; (as symbols) You want to profile. Call M-x profile-functions to set |
43 | ;; this list on and start using your program. Note that profile-functions | |
44 | ;; MUST be called AFTER all the functions in profile-functions-list have | |
b578f267 | 45 | ;; been loaded !! (This call modifies the code of the profiled functions. |
c7f8bd78 | 46 | ;; Hence if you reload these functions, you need to call profile-functions |
b578f267 EN |
47 | ;; again! ). |
48 | ;; To display the results do M-x profile-results . For example: | |
49 | ;;------------------------------------------------------------------- | |
c7f8bd78 | 50 | ;; (setq profile-functions-list '(sokoban-set-mode-line sokoban-load-game |
b578f267 EN |
51 | ;; sokoban-move-vertical sokoban-move)) |
52 | ;; (load "sokoban") | |
53 | ;; M-x profile-functions | |
54 | ;; ... I play the sokoban game .......... | |
55 | ;; M-x profile-results | |
56 | ;; | |
57 | ;; Function Time (Seconds.Useconds) | |
58 | ;; ======== ======================= | |
59 | ;; sokoban-move 0.539088 | |
60 | ;; sokoban-move-vertical 0.410130 | |
61 | ;; sokoban-load-game 0.453235 | |
62 | ;; sokoban-set-mode-line 1.949203 | |
63 | ;;----------------------------------------------------- | |
c7f8bd78 KH |
64 | ;; To clear all the settings to profile use profile-finish. |
65 | ;; To set one function at a time (instead of or in addition to setting the | |
b578f267 | 66 | ;; above list and M-x profile-functions) use M-x profile-a-function. |
ecb4184d | 67 | |
4821e2af ER |
68 | ;;; Code: |
69 | ||
ecb4184d ER |
70 | ;;; |
71 | ;;; User modifiable VARIABLES | |
72 | ;;; | |
73 | ||
c7f8bd78 KH |
74 | (defvar profile-functions-list nil "*List of functions to profile.") |
75 | (defvar profile-buffer "*profile*" | |
76 | "Name of profile buffer.") | |
77 | (defvar profile-distinct nil | |
78 | "If non-nil, each time slice gets credited to at most one function. | |
79 | \(Namely, the most recent one in the call stack.) If nil, then the | |
80 | time reported for a function includes the entire time from beginning | |
81 | to end, even if it called some other function that was also profiled.") | |
ecb4184d ER |
82 | |
83 | ;;; | |
84 | ;;; V A R I A B L E S | |
85 | ;;; | |
86 | ||
c7f8bd78 KH |
87 | (defvar profile-time-list nil |
88 | "List of cumulative calls and time for each profiled function. | |
89 | Each element looks like (FUN NCALLS SEC . USEC).") | |
ecb4184d | 90 | (defvar profile-init-list nil |
c7f8bd78 KH |
91 | "List of entry time for each function. |
92 | Both how many times invoked and real time of start. | |
93 | Each element looks like (FUN DEPTH HISEC LOSEC USEC), where DEPTH is | |
94 | the current recursion depth, and HISEC, LOSEC, and USEC represent the | |
95 | starting time of the call (or of the outermost recursion).") | |
96 | (defvar profile-max-fun-name 0 | |
97 | "Max length of name of any function profiled.") | |
98 | (defvar profile-call-stack nil | |
99 | "A list of the profiled functions currently executing. | |
100 | Used only when profile-distinct is non-nil.") | |
101 | (defvar profile-last-time nil | |
102 | "The start time of the current time slice. | |
103 | Used only when profile-distinct is non-nil.") | |
ecb4184d | 104 | |
51eb91c2 RS |
105 | (defconst profile-million 1000000) |
106 | ||
ecb4184d ER |
107 | ;;; |
108 | ;;; F U N C T I O N S | |
109 | ;;; | |
110 | ||
111 | (defun profile-functions (&optional flist) | |
52fb15fa | 112 | "Profile all the functions listed in `profile-functions-list'. |
ecb4184d | 113 | With argument FLIST, use the list FLIST instead." |
37ae4d5c | 114 | (interactive "P") |
c7f8bd78 | 115 | (mapcar 'profile-a-function (or flist profile-functions-list))) |
ecb4184d ER |
116 | |
117 | (defun profile-print (entry) | |
184c7493 | 118 | "Print one ENTRY (from `profile-time-list')." |
37ae4d5c RS |
119 | (let* ((calls (car (cdr entry))) |
120 | (timec (cdr (cdr entry))) | |
c7f8bd78 KH |
121 | (avgtime (and (not (zerop calls)) |
122 | (/ (+ (car timec) | |
123 | (/ (cdr timec) (float profile-million))) | |
124 | calls)))) | |
37ae4d5c RS |
125 | (insert (format (concat "%-" |
126 | (int-to-string profile-max-fun-name) | |
c7f8bd78 | 127 | "s %7d %10d.%06d") |
37ae4d5c | 128 | (car entry) calls (car timec) (cdr timec)) |
c7f8bd78 | 129 | (if (null avgtime) |
37ae4d5c | 130 | "\n" |
c7f8bd78 | 131 | (format " %18.6f\n" avgtime))))) |
ecb4184d ER |
132 | |
133 | (defun profile-results () | |
184c7493 RS |
134 | "Display profiling results in the buffer `*profile*'. |
135 | \(The buffer name comes from `profile-buffer'.)" | |
136 | (interactive) | |
37ae4d5c RS |
137 | (switch-to-buffer profile-buffer) |
138 | (erase-buffer) | |
139 | (insert "Function" (make-string (- profile-max-fun-name 6) ? )) | |
140 | (insert " Calls Total time (sec) Avg time per call\n") | |
141 | (insert (make-string profile-max-fun-name ?=) " ") | |
142 | (insert "====== ================ =================\n") | |
143 | (mapcar 'profile-print profile-time-list)) | |
ecb4184d | 144 | |
c7f8bd78 KH |
145 | (defun profile-add-time (dest now prev) |
146 | "Add to DEST the difference between timestamps NOW and PREV. | |
147 | DEST is a pair (SEC . USEC) which is modified in place. | |
148 | NOW and PREV are triples as returned by `current-time'." | |
149 | (let ((sec (+ (car dest) | |
150 | (* 65536 (- (car now) (car prev))) | |
151 | (- (cadr now) (cadr prev)))) | |
152 | (usec (+ (cdr dest) | |
153 | (- (car (cddr now)) (car (cddr prev)))))) | |
154 | (if (< usec 0) | |
155 | (setq sec (1- sec) | |
156 | usec (+ usec profile-million)) | |
157 | (if (>= usec profile-million) | |
158 | (setq sec (1+ sec) | |
159 | usec (- usec profile-million)))) | |
160 | (setcar dest sec) | |
161 | (setcdr dest usec))) | |
162 | ||
163 | (defun profile-function-prolog (fun) | |
164 | "Mark the beginning of a call to function FUN." | |
165 | (if profile-distinct | |
166 | (let ((profile-time (current-time))) | |
167 | (if profile-call-stack | |
168 | (profile-add-time (cdr (cdr (assq (car profile-call-stack) | |
169 | profile-time-list))) | |
170 | profile-time profile-last-time)) | |
171 | (setq profile-call-stack (cons fun profile-call-stack) | |
172 | profile-last-time profile-time)) | |
173 | (let ((profile-time (current-time)) | |
174 | (init-time (cdr (assq fun profile-init-list)))) | |
175 | (if (null init-time) (error "Function %s missing from list" fun)) | |
176 | (if (not (zerop (car init-time)));; is it a recursive call ? | |
177 | (setcar init-time (1+ (car init-time))) | |
178 | (setcar init-time 1) ; mark first entry | |
179 | (setcdr init-time profile-time))))) | |
180 | ||
181 | (defun profile-function-epilog (fun) | |
182 | "Mark the end of a call to function FUN." | |
183 | (if profile-distinct | |
184 | (let ((profile-time (current-time)) | |
185 | (accum (cdr (assq fun profile-time-list)))) | |
186 | (setcar accum (1+ (car accum))) | |
187 | (profile-add-time (cdr accum) profile-time profile-last-time) | |
188 | (setq profile-call-stack (cdr profile-call-stack) | |
189 | profile-last-time profile-time)) | |
190 | (let ((profile-time (current-time)) | |
191 | (init-time (cdr (assq fun profile-init-list))) | |
192 | (accum (cdr (assq fun profile-time-list)))) | |
193 | (if (or (null init-time) | |
194 | (null accum)) | |
195 | (error "Function %s missing from list" fun)) | |
196 | (setcar init-time (1- (car init-time))) ; pop one level in recursion | |
197 | ;; Update only if we've finished the outermost recursive call | |
198 | (when (zerop (car init-time)) | |
199 | (setcar accum (1+ (car accum))) | |
200 | (profile-add-time (cdr accum) profile-time (cdr init-time)))))) | |
ecb4184d | 201 | |
61939396 RS |
202 | (defun profile-convert-byte-code (function) |
203 | (let ((defn (symbol-function function))) | |
204 | (if (byte-code-function-p defn) | |
205 | ;; It is a compiled code object. | |
206 | (let* ((contents (append defn nil)) | |
207 | (body | |
208 | (list (list 'byte-code (nth 1 contents) | |
209 | (nth 2 contents) (nth 3 contents))))) | |
210 | (if (nthcdr 5 contents) | |
211 | (setq body (cons (list 'interactive (nth 5 contents)) body))) | |
212 | (if (nth 4 contents) | |
213 | ;; Use `documentation' here, to get the actual string, | |
214 | ;; in case the compiled function has a reference | |
215 | ;; to the .elc file. | |
216 | (setq body (cons (documentation function) body))) | |
217 | (fset function (cons 'lambda (cons (car contents) body))))))) | |
218 | ||
ecb4184d | 219 | (defun profile-a-function (fun) |
184c7493 RS |
220 | "Profile the function FUN." |
221 | (interactive "aFunction to profile: ") | |
c7f8bd78 KH |
222 | (let ((def (symbol-function fun))) |
223 | (when (eq (car-safe def) 'autoload) | |
224 | (load (car (cdr def))) | |
225 | (setq def (symbol-function fun))) | |
226 | (fetch-bytecode def)) | |
61939396 | 227 | (profile-convert-byte-code fun) |
184c7493 | 228 | (let ((def (symbol-function fun)) (funlen (length (symbol-name fun)))) |
c7f8bd78 KH |
229 | (or (eq (car def) 'lambda) |
230 | (error "To profile: %s must be a user-defined function" fun)) | |
184c7493 | 231 | (setq profile-time-list ; add a new entry |
37ae4d5c | 232 | (cons (cons fun (cons 0 (cons 0 0))) profile-time-list)) |
184c7493 | 233 | (setq profile-init-list ; add a new entry |
c7f8bd78 | 234 | (cons (cons fun (cons 0 nil)) profile-init-list)) |
184c7493 RS |
235 | (if (< profile-max-fun-name funlen) (setq profile-max-fun-name funlen)) |
236 | (fset fun (profile-fix-fun fun def)))) | |
ecb4184d ER |
237 | |
238 | (defun profile-fix-fun (fun def) | |
52fb15fa | 239 | "Take function FUN and return it fixed for profiling. |
184c7493 | 240 | DEF is (symbol-function FUN)." |
1fdd3601 | 241 | (if (< (length def) 3) |
c7f8bd78 | 242 | def ; nothing to change |
1fdd3601 KH |
243 | (let ((prefix (list (car def) (car (cdr def)))) |
244 | (suffix (cdr (cdr def)))) | |
52fb15fa RS |
245 | ;; Skip the doc string, if there is a string |
246 | ;; which serves only as a doc string, | |
247 | ;; and put it in PREFIX. | |
1fdd3601 KH |
248 | (if (and (stringp (car suffix)) (cdr suffix)) |
249 | (setq prefix (nconc prefix (list (car suffix))) | |
250 | suffix (cdr suffix))) | |
52fb15fa | 251 | ;; Check for an interactive spec. |
1fdd3601 | 252 | ;; If found, put it into PREFIX and skip it. |
c7f8bd78 | 253 | (if (and (listp (car suffix)) |
1fdd3601 KH |
254 | (eq (car (car suffix)) 'interactive)) |
255 | (setq prefix (nconc prefix (list (car suffix))) | |
256 | suffix (cdr suffix))) | |
c7f8bd78 | 257 | (if (eq (car-safe (car suffix)) 'profile-function-prolog) |
1fdd3601 | 258 | def ; already profiled |
52fb15fa | 259 | ;; Prepare new function definition. |
c7f8bd78 | 260 | ;; If you change this structure, also change profile-restore-fun. |
52fb15fa | 261 | (nconc prefix |
c7f8bd78 | 262 | (list (list 'profile-function-prolog |
1fdd3601 | 263 | (list 'quote fun)) |
c7f8bd78 KH |
264 | (list 'unwind-protect |
265 | (cons 'progn suffix) | |
266 | (list 'profile-function-epilog | |
267 | (list 'quote fun))))))))) | |
ecb4184d ER |
268 | |
269 | (defun profile-restore-fun (fun) | |
184c7493 | 270 | "Restore profiled function FUN to its original state." |
c7f8bd78 | 271 | (let ((def (symbol-function fun)) body index) |
184c7493 | 272 | ;; move index beyond header |
c7f8bd78 KH |
273 | (setq index (cdr-safe def)) |
274 | (if (stringp (car (cdr index))) | |
184c7493 | 275 | (setq index (cdr index))) |
c7f8bd78 KH |
276 | (if (eq (car-safe (car (cdr index))) 'interactive) |
277 | (setq index (cdr index))) | |
278 | (if (eq (car-safe (car (cdr index))) 'profile-function-prolog) | |
279 | (setcdr index (cdr (car (cdr (car (cdr (cdr index)))))))))) | |
ecb4184d ER |
280 | |
281 | (defun profile-finish () | |
184c7493 RS |
282 | "Stop profiling functions. Clear all the settings." |
283 | (interactive) | |
c7f8bd78 KH |
284 | (while profile-time-list |
285 | (profile-restore-fun (car (car profile-time-list))) | |
286 | (setq profile-time-list (cdr profile-time-list))) | |
184c7493 | 287 | (setq profile-max-fun-name 0) |
184c7493 | 288 | (setq profile-init-list nil)) |
ecb4184d | 289 | |
896546cd RS |
290 | (provide 'profile) |
291 | ||
76550a57 | 292 | ;;; profile.el ends here |