655
|
1 ;;; profile.el -- generate run time measurements of elisp functions
|
|
2 ;;;
|
|
3 ;;; Author: Boaz Ben-Zvi <boaz@lcs.mit.edu>
|
|
4 ;;; Created: Feb. 7, 1992
|
|
5 ;;; Last Modified: Feb. 7, 1992
|
|
6 ;;; Version: 1.0
|
|
7
|
|
8 ;; Copyright (C) 1992 Free Software Foundation, Inc.
|
|
9
|
|
10 ;; This file is part of GNU Emacs.
|
|
11
|
|
12 ;; GNU Emacs 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 1, or (at your option)
|
|
15 ;; any later version.
|
|
16
|
|
17 ;; GNU Emacs 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.
|
|
21
|
|
22 ;; You should have received a copy of the GNU General Public License
|
|
23 ;; along with GNU Emacs; see the file COPYING. If not, write to
|
|
24 ;; the Free Software Foundation, 675 Mass Ave, Cambridge, MA 02139, USA.
|
|
25
|
|
26
|
|
27 ; DESCRIPTION:
|
|
28 ; ------------
|
|
29 ; This program can be used to monitor running time performance of elisp
|
|
30 ; functions. It takes a list of functions and report the real time spent
|
|
31 ; inside these functions. It runs a process with a separate timer program.
|
|
32 ; Caveat: the C code included with this package requires BSD-compatible
|
|
33 ; time-of-day functions. If you're running an AT&T version prior to SVr4,
|
|
34 ; you may have difficulty getting it to work. Your X library may supply
|
|
35 ; the required routines if the standard C library does not.
|
|
36
|
|
37 ; HOW TO USE:
|
|
38 ; -----------
|
|
39 ; Set the variable profile-functions-list to the list of functions
|
|
40 ; (as symbols) You want to profile. Call M-x profile-functions to set
|
|
41 ; this list on and start using your program. Note that profile-functions
|
|
42 ; MUST be called AFTER all the functions in profile-functions-list have
|
|
43 ; been loaded !! (This call modifies the code of the profiled functions.
|
|
44 ; Hence if you reload these functions, you need to call profile-functions
|
|
45 ; again! ).
|
|
46 ; To display the results do M-x profile-results . For example:
|
|
47 ;-------------------------------------------------------------------
|
|
48 ; (setq profile-functions-list '(sokoban-set-mode-line sokoban-load-game
|
|
49 ; sokoban-move-vertical sokoban-move))
|
|
50 ; (load "sokoban")
|
|
51 ; M-x profile-functions
|
|
52 ; ... I play the sokoban game ..........
|
|
53 ; M-x profile-results
|
|
54 ;
|
|
55 ; Function Time (Seconds.Useconds)
|
|
56 ; ======== =======================
|
|
57 ; sokoban-move 0.539088
|
|
58 ; sokoban-move-vertical 0.410130
|
|
59 ; sokoban-load-game 0.453235
|
|
60 ; sokoban-set-mode-line 1.949203
|
|
61 ;-----------------------------------------------------
|
|
62 ; To clear all the settings to profile use profile-finish.
|
|
63 ; To set one function at a time (instead of or in addition to setting the
|
|
64 ; above list and M-x profile-functions ) use M-x profile-a-function .
|
|
65
|
|
66 ; HOW TO INSTALL:
|
|
67 ; ---------------
|
|
68 ; First you need to compile and install the following C program in your
|
|
69 ; path under the name "emacs-timer" (or set the variable
|
|
70 ; profile-timer-program to whatever name you picked).
|
|
71 ;
|
|
72 ;/**
|
|
73 ; ** To be run as an emacs process. Input string that starts with:
|
|
74 ; ** 'z' -- resets the watch (to zero).
|
|
75 ; ** 'p' -- return time (on stdout) as string with format <sec>.<micro-sec>
|
|
76 ; ** 'q' -- exit.
|
|
77 ; **
|
|
78 ; ** abstraction : a stopwatch
|
|
79 ; ** operations: reset_watch, get_time
|
|
80 ; */
|
|
81 ;#include <strings.h>
|
|
82 ;#include <sys/time.h>
|
|
83 ;#include <stdio.h>
|
|
84 ;static struct timeval TV1,TV2;
|
|
85 ;static struct timezone *tzp = (struct timezone *) NULL; /* no need timezone */
|
|
86 ;static int watch_not_started = 1 ; /* flag */
|
|
87 ;static char time_string[30]
|
|
88 ;
|
|
89 ;int reset_watch() /* this call resets the stopwatch to zero */
|
|
90 ;{
|
|
91 ; gettimeofday(&TV1, tzp) ;
|
|
92 ; watch_not_started = 0;
|
|
93 ;}
|
|
94 ;
|
|
95 ;char *get_time()
|
|
96 ; /* this call returns the time since the last reset_watch() call. The time
|
|
97 ; is returned as a string with the format <seconds>.<micro-seconds>
|
|
98 ; If reset_watch() was not called yet, returns NULL */
|
|
99 ;{
|
|
100 ; char *result = time_string ;
|
|
101 ; int i;
|
|
102 ; if (watch_not_started) return((char *) 0); /* call reset_watch first ! */
|
|
103 ; gettimeofday(&TV2, tzp);
|
|
104 ; if ( TV1.tv_usec > TV2.tv_usec )
|
|
105 ; {
|
|
106 ; TV2.tv_usec += 1000000;
|
|
107 ; TV2.tv_sec--;
|
|
108 ; }
|
|
109 ; sprintf(result,"%lu.%6lu",
|
|
110 ; TV2.tv_sec - TV1.tv_sec, TV2.tv_usec - TV1.tv_usec);
|
|
111 ; for (result = index(result,'.') + 1 ; *result == ' ' ; result++ )
|
|
112 ; *result = '0';
|
|
113 ; return(time_string);
|
|
114 ;}
|
|
115 ;
|
|
116 ;void main()
|
|
117 ;{
|
|
118 ; char inp[10];
|
|
119 ; while (1)
|
|
120 ; {
|
|
121 ; gets(inp);
|
|
122 ; switch (inp[0])
|
|
123 ; {
|
|
124 ; case 'z': reset_watch();
|
|
125 ; break;
|
|
126 ; case 'p': puts(get_time());
|
|
127 ; break;
|
|
128 ; case 'q': exit(0);
|
|
129 ; }
|
|
130 ; }
|
|
131 ;}
|
|
132 ; -------- end of clip ----------------
|
|
133
|
|
134 ;;;
|
|
135 ;;; User modifiable VARIABLES
|
|
136 ;;;
|
|
137
|
|
138 (defvar profile-functions-list nil "*List of functions to profile")
|
|
139 (defvar profile-timer-program "emacs-timer" "*Name of the timer program")
|
|
140
|
|
141 ;;;
|
|
142 ;;; V A R I A B L E S
|
|
143 ;;;
|
|
144
|
|
145 (defvar profile-timer-process nil "Process running the timer")
|
|
146 (defvar profile-time-list nil
|
|
147 "List of accumulative time for each profiled function")
|
|
148 (defvar profile-init-list nil
|
|
149 "List of entry time for each function. \n\
|
|
150 Both how many times invoked and real time of start.")
|
|
151 (defvar profile-max-fun-name 0 "Max length of name of any function profiled")
|
|
152 (defvar profile-temp-result- nil "Should NOT be used anywhere else")
|
|
153 (defvar profile-time (cons 0 0) "Used to return result from a filter")
|
|
154 (defvar profile-buffer "*profile*" "Name of profile buffer")
|
|
155
|
|
156 ;;;
|
|
157 ;;; F U N C T I O N S
|
|
158 ;;;
|
|
159
|
|
160 (defun profile-functions (&optional flist)
|
|
161 "Profile all the functions listed in profile-functions-list.\n\
|
|
162 With argument FLIST, use the list FLIST instead."
|
|
163 (interactive "*P")
|
|
164 (if (null flist) (setq flist profile-functions-list))
|
|
165 (mapcar 'profile-a-function flist))
|
|
166
|
|
167 (defun profile-filter (process input)
|
|
168 "Filter for the timer process. Sets profile-time to the returned time."
|
|
169 (if (zerop (string-match "\\." input))
|
|
170 (error "Bad output from %s" profile-timer-program)
|
|
171 (setcar profile-time
|
|
172 (string-to-int (substring input 0 (match-beginning 0))))
|
|
173 (setcdr profile-time
|
|
174 (string-to-int (substring input (match-end 0))))))
|
|
175
|
|
176
|
|
177 (defun profile-print (entry)
|
|
178 "Print one ENTRY (from profile-time-list) ."
|
|
179 (let ((time (cdr entry)) str (offset 5))
|
|
180 (insert (format "%s" (car entry)) space)
|
|
181 (move-to-column ref-column)
|
|
182 (setq str (int-to-string (car time)))
|
|
183 (insert str)
|
|
184 (if (>= (length str) offset) nil
|
|
185 (move-to-column ref-column)
|
|
186 (insert (substring spaces 0 (- offset (length str))))
|
|
187 (forward-char (length str)))
|
|
188 (setq str (int-to-string (cdr time)))
|
|
189 (insert "." (substring "000000" 0 (- 6 (length str))) str "\n")
|
|
190 ))
|
|
191
|
|
192 (defconst spaces " ")
|
|
193
|
|
194 (defun profile-results ()
|
|
195 "Display profiling results in profile-buffer ."
|
|
196 (interactive)
|
|
197 (let* ((ref-column (+ 8 profile-max-fun-name))
|
|
198 (space (substring spaces 0 ref-column)))
|
|
199 (switch-to-buffer profile-buffer)
|
|
200 (erase-buffer)
|
|
201 (insert "Function" space)
|
|
202 (move-to-column ref-column)
|
|
203 (insert "Time (Seconds.Useconds)\n" "========" space )
|
|
204 (move-to-column ref-column)
|
|
205 (insert "=======================\n")
|
|
206 (mapcar 'profile-print profile-time-list)))
|
|
207
|
|
208 (defun profile-reset-timer ()
|
|
209 (process-send-string profile-timer-process "z\n"))
|
|
210
|
|
211 (defun profile-check-zero-init-times (entry)
|
|
212 "If ENTRY has non zero time, give an error."
|
|
213 (let ((time (cdr (cdr entry))))
|
|
214 (if (and (zerop (car time)) (zerop (cdr time))) nil ; OK
|
|
215 (error "Process timer died while making performance profile."))))
|
|
216
|
|
217 (defun profile-get-time ()
|
|
218 "Get time from timer process into profile-time ."
|
|
219 ;; first time or if process dies
|
|
220 (if (and (processp profile-timer-process)
|
|
221 (eq 'run (process-status profile-timer-process))) nil
|
|
222 (setq profile-timer-process ;; [re]start the timer process
|
|
223 (start-process "timer"
|
|
224 (get-buffer-create profile-buffer)
|
|
225 profile-timer-program))
|
|
226 (set-process-filter profile-timer-process 'profile-filter)
|
|
227 (process-kill-without-query profile-timer-process)
|
|
228 (profile-reset-timer)
|
|
229 ;; check if timer died during time measurement
|
|
230 (mapcar 'profile-check-zero-init-times profile-init-list))
|
|
231 ;; make timer process return current time
|
|
232 (process-send-string profile-timer-process "p\n")
|
|
233 (accept-process-output))
|
|
234
|
|
235 (defun profile-find-function (fun flist)
|
|
236 "Linear search for FUN in FLIST ."
|
|
237 (if (null flist) nil
|
|
238 (if (eq fun (car (car flist))) (cdr (car flist))
|
|
239 (profile-find-function fun (cdr flist)))))
|
|
240
|
|
241 (defun profile-start-function (fun)
|
|
242 "On entry, keep current time for function FUN."
|
|
243 ;; assumes that profile-time contains the current time
|
|
244 (let ((init-time (profile-find-function fun profile-init-list)))
|
|
245 (if (null init-time) (error "Function %s missing from list" fun))
|
|
246 (if (not (zerop (car init-time))) ;; is it a recursive call ?
|
|
247 (setcar init-time (1+ (car init-time)))
|
|
248 (setcar init-time 1) ; mark first entry
|
|
249 (setq init-time (cdr init-time))
|
|
250 (setcar init-time (car profile-time))
|
|
251 (setcdr init-time (cdr profile-time)))
|
|
252 ))
|
|
253
|
|
254 (defconst profile-million 1000000)
|
|
255
|
|
256 (defun profile-update-function (fun)
|
|
257 "When the call to the function FUN is finished, add its run time."
|
|
258 ;; assumes that profile-time contains the current time
|
|
259 (let ((init-time (profile-find-function fun profile-init-list))
|
|
260 (accum (profile-find-function fun profile-time-list))
|
|
261 sec usec)
|
|
262 (if (or (null init-time)
|
|
263 (null accum)) (error "Function %s missing from list" fun))
|
|
264 (setcar init-time (1- (car init-time))) ; pop one level in recursion
|
|
265 (if (not (zerop (car init-time)))
|
|
266 nil ; in some recursion level, do not update accum. time
|
|
267 (setq init-time (cdr init-time))
|
|
268 (setq sec (- (car profile-time) (car init-time))
|
|
269 usec (- (cdr profile-time) (cdr init-time)))
|
|
270 (setcar init-time 0) ; reset time to check for error
|
|
271 (setcdr init-time 0) ; in case timer process dies
|
|
272 (if (>= usec 0) nil
|
|
273 (setq usec (+ usec profile-million))
|
|
274 (setq sec (1- sec)))
|
|
275 (setcar accum (+ sec (car accum)))
|
|
276 (setcdr accum (+ usec (cdr accum)))
|
|
277 (if (< (cdr accum) profile-million) nil
|
|
278 (setcar accum (1+ (car accum)))
|
|
279 (setcdr accum (- (cdr accum) profile-million)))
|
|
280 )))
|
|
281
|
|
282 (defun profile-a-function (fun)
|
|
283 "Profile the function FUN"
|
|
284 (interactive "aFunction to profile: ")
|
|
285 (let ((def (symbol-function fun)) (funlen (length (symbol-name fun))))
|
|
286 (if (eq (car def) 'lambda) nil
|
|
287 (error "To profile: %s must be a user-defined function" fun))
|
|
288 (setq profile-time-list ; add a new entry
|
|
289 (cons (cons fun (cons 0 0)) profile-time-list))
|
|
290 (setq profile-init-list ; add a new entry
|
|
291 (cons (cons fun (cons 0 (cons 0 0))) profile-init-list))
|
|
292 (if (< profile-max-fun-name funlen) (setq profile-max-fun-name funlen))
|
|
293 (fset fun (profile-fix-fun fun def))))
|
|
294
|
|
295 (defun profile-fix-fun (fun def)
|
|
296 "Take function FUN and return it fixed for profiling.\n\
|
|
297 DEF is (symbol-function FUN) ."
|
|
298 (let (prefix first second third (count 2) inter suffix)
|
|
299 (if (< (length def) 3) nil ; nothing to see
|
|
300 (setq first (car def) second (car (cdr def))
|
|
301 third (car (nthcdr 2 def)))
|
|
302 (setq prefix (list first second))
|
|
303 (if (and (stringp third) (< (length def) 3)) nil ; nothing to see
|
|
304 (if (not (stringp third)) (setq inter third)
|
|
305 (setq count 3 ; suffix to start after doc string
|
|
306 prefix (nconc prefix (list third))
|
|
307 inter (car (nthcdr 3 def))) ; fourth sexp
|
|
308 )
|
|
309 (if (not (and (listp inter)
|
|
310 (eq (car inter) 'interactive))) nil
|
|
311 (setq prefix (nconc prefix (list inter)))
|
|
312 (setq count (1+ count))) ; skip this sexp for suffix
|
|
313 (setq suffix (nthcdr count def))
|
|
314 (if (equal (car suffix) '(profile-get-time)) nil ;; already set
|
|
315 ;; prepare new function
|
|
316 (nconc prefix
|
|
317 (list '(profile-get-time)) ; read time
|
|
318 (list (list 'profile-start-function
|
|
319 (list 'quote fun)))
|
|
320 (list (list 'setq 'profile-temp-result-
|
|
321 (nconc (list 'progn) suffix)))
|
|
322 (list '(profile-get-time)) ; read time
|
|
323 (list (list 'profile-update-function
|
|
324 (list 'quote fun)))
|
|
325 (list 'profile-temp-result-)
|
|
326 ))))))
|
|
327
|
|
328 (defun profile-restore-fun (fun)
|
|
329 "Restore profiled function FUN to its original state."
|
|
330 (let ((def (symbol-function (car fun))) body index)
|
|
331 ;; move index beyond header
|
|
332 (setq index (cdr def))
|
|
333 (if (stringp (car (cdr index))) (setq index (cdr index)))
|
|
334 (if (and (listp (car (cdr index)))
|
|
335 (eq (car (car (cdr index))) 'interactive))
|
|
336 (setq index (cdr index)))
|
|
337 (setq body (car (nthcdr 3 index)))
|
|
338 (if (and (listp body) ; the right element ?
|
|
339 (eq (car (cdr body)) 'profile-temp-result-))
|
|
340 (setcdr index (cdr (car (cdr (cdr body))))))))
|
|
341
|
|
342 (defun profile-finish ()
|
|
343 "Stop profiling functions. Clear all the settings."
|
|
344 (interactive)
|
|
345 (mapcar 'profile-restore-fun profile-time-list)
|
|
346 (setq profile-max-fun-name 0)
|
|
347 (setq profile-time-list nil)
|
|
348 (setq profile-init-list nil))
|
|
349
|
|
350 (defun profile-quit ()
|
|
351 "Kill the timer process."
|
|
352 (interactive)
|
|
353 (process-send-string profile-timer-process "q\n"))
|
|
354
|
|
355 ;; profile.el ends here
|