|
0
|
1 ;;; profile.el --- basic profiling commands for XEmacs
|
|
|
2
|
|
199
|
3 ;; Copyright (C) 1996 Ben Wing, (C) 1997 Free Software Foundation.
|
|
0
|
4
|
|
155
|
5 ;; Maintainer: XEmacs Development Team
|
|
|
6 ;; Keywords: internal
|
|
|
7
|
|
0
|
8 ;; This file is part of XEmacs.
|
|
|
9
|
|
|
10 ;; XEmacs is free software; you can redistribute it and/or modify it
|
|
|
11 ;; under the terms of the GNU General Public License as published by
|
|
|
12 ;; the Free Software Foundation; either version 2, or (at your option)
|
|
|
13 ;; any later version.
|
|
|
14
|
|
|
15 ;; XEmacs is distributed in the hope that it will be useful, but
|
|
|
16 ;; WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
17 ;; MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
|
|
|
18 ;; General Public License for more details.
|
|
|
19
|
|
|
20 ;; You should have received a copy of the GNU General Public License
|
|
16
|
21 ;; along with XEmacs; see the file COPYING. If not, write to the
|
|
70
|
22 ;; Free Software Foundation, 59 Temple Place - Suite 330,
|
|
16
|
23 ;; Boston, MA 02111-1307, USA.
|
|
0
|
24
|
|
|
25 ;;; Synched up with: Not in FSF.
|
|
|
26
|
|
155
|
27 ;;; Commentary:
|
|
|
28
|
|
199
|
29 ;; In addition to Lisp-based `elp', XEmacs contains a set of
|
|
|
30 ;; primitives able to profile evaluation of Lisp functions, created by
|
|
|
31 ;; the illustrious Ben Wing. The functions in this file can be used
|
|
|
32 ;; to gain easy access to the internal profiling functions.
|
|
|
33
|
|
|
34 ;; The profiler works by catching "ticks" (actually SIGPROF signals),
|
|
|
35 ;; and looking at the current Lisp function, at the time of each tick.
|
|
|
36 ;; The output of this process is an alist with keys being the
|
|
|
37 ;; functions, and values being the number of ticks per function. From
|
|
201
|
38 ;; this, `profiling-results' easily extracts the total number of
|
|
|
39 ;; ticks, and the percentage CPU time of each function.
|
|
199
|
40
|
|
|
41 ;; Unless stated otherwise, profiling info is being accumulated (the
|
|
|
42 ;; current info is returned by `get-profiling-info'). Use
|
|
|
43 ;; `clear-profiling-info' to break the accumulation chain.
|
|
|
44
|
|
|
45 ;; Caveats (ELP users should read this):
|
|
|
46 ;; 1) The time reported is function time, rather than
|
|
|
47 ;; function+descendants time;
|
|
|
48 ;; 2) The Time/ms is CPU time (user+kernel), not the real time;
|
|
|
49 ;; 3) Only the actuall funcalls are profiled. If a subr Ffoo calls
|
|
|
50 ;; Fbar using Fbar (), only Ffoo will appear in the profile.
|
|
|
51
|
|
|
52 ;; A typical profiling session consists of using `clear-profiling-info'
|
|
|
53 ;; followed by `profile' or `profile-key-sequence', followed by
|
|
201
|
54 ;; `profiling-results'.
|
|
199
|
55
|
|
|
56 ;; For instance, to see where Gnus spends time when generating Summary
|
|
|
57 ;; buffer, go to the group buffer, and press `M-x clear-profiling-info'
|
|
|
58 ;; followed by `M-x profile-key-sequence RET SPC'.
|
|
167
|
59
|
|
|
60
|
|
155
|
61 ;;; Code:
|
|
|
62
|
|
203
|
63 (defun profile-align (form width)
|
|
|
64 ;; Bletch! this is what (format "%-*s" width form) should do.
|
|
|
65 (let ((printed-form (format "%s" form)))
|
|
|
66 (concat printed-form
|
|
|
67 (make-string (max 0 (- width (length printed-form))) ?\ ))))
|
|
|
68
|
|
155
|
69 ;;;###autoload
|
|
203
|
70 (defun profile-results (&optional info stream)
|
|
167
|
71 "Print profiling info INFO to STREAM in a pretty format.
|
|
0
|
72 If INFO is omitted, the current profiling info is retrieved using
|
|
199
|
73 `get-profiling-info'.
|
|
|
74 If STREAM is omitted, either a *Profiling Results* buffer or standard
|
|
|
75 output are used, depending on whether the function was called
|
|
|
76 interactively or not."
|
|
167
|
77 (interactive)
|
|
199
|
78 (setq info (if info
|
|
|
79 (copy-alist info)
|
|
|
80 (get-profiling-info)))
|
|
|
81 (when (and (not stream)
|
|
|
82 (interactive-p))
|
|
|
83 (pop-to-buffer (get-buffer-create "*Profiling Results*"))
|
|
|
84 (erase-buffer))
|
|
203
|
85 (let ((standard-output (or stream (if (interactive-p)
|
|
|
86 (current-buffer)
|
|
|
87 standard-output)))
|
|
|
88 ;; Calculate the longest function
|
|
|
89 (maxfunlen (apply #'max
|
|
|
90 (length "Function Name")
|
|
|
91 (mapcar (lambda (el)
|
|
|
92 ;; Functions longer than 40
|
|
|
93 ;; characters don't qualify
|
|
|
94 (let ((l (length (format "%s" (car el)))))
|
|
|
95 (if (< l 40)
|
|
|
96 l 0)))
|
|
|
97 info))))
|
|
|
98 (princ (format "%s Ticks %%/Total\n"
|
|
|
99 (profile-align "Function Name" maxfunlen)))
|
|
199
|
100 (princ (make-string maxfunlen ?=))
|
|
|
101 (princ " ===== =======\n")
|
|
203
|
102 (let ((sum (float (apply #'+ (mapcar #'cdr info)))))
|
|
|
103 (dolist (entry (nreverse (sort info #'cdr-less-than-cdr)))
|
|
|
104 (princ (format "%s %-5d %-6.3f\n"
|
|
|
105 (profile-align (car entry) maxfunlen)
|
|
|
106 (cdr entry) (* 100 (/ (cdr entry) sum)))))
|
|
199
|
107 (princ (make-string maxfunlen ?-))
|
|
|
108 (princ "--------------------\n")
|
|
203
|
109 (princ (format "%s %-5d %-6.2f\n"
|
|
|
110 (profile-align "Total" maxfunlen) sum 100.0))
|
|
199
|
111 (princ (format "\n\nOne tick = %g ms\n"
|
|
|
112 (/ default-profiling-interval 1000.0)))))
|
|
|
113 (when (and (not stream)
|
|
|
114 (interactive-p))
|
|
|
115 (goto-char (point-min))))
|
|
155
|
116
|
|
201
|
117 ;; Support the old name for a while.
|
|
|
118 (define-obsolete-function-alias 'pretty-print-profiling-info
|
|
|
119 'profile-results)
|
|
|
120
|
|
165
|
121 ;;;###autoload
|
|
|
122 (defmacro profile (&rest forms)
|
|
173
|
123 "Turn on profiling, execute FORMS and restore profiling state.
|
|
|
124 Profiling state here means that if profiling was not in effect when
|
|
|
125 PROFILE was called, it will be turned off after FORMS are evaluated.
|
|
|
126 Otherwise, profiling will be left running.
|
|
|
127
|
|
201
|
128 Returns the profiling info, printable by `profiling-results'."
|
|
203
|
129 `(let ((was-profiling (profiling-active-p)))
|
|
|
130 (unwind-protect
|
|
165
|
131 (progn
|
|
203
|
132 (start-profiling)
|
|
165
|
133 ,@forms)
|
|
203
|
134 (unless was-profiling
|
|
173
|
135 (stop-profiling)))
|
|
165
|
136 (get-profiling-info)))
|
|
|
137
|
|
|
138 (put 'profile 'lisp-indent-function 0)
|
|
|
139
|
|
167
|
140 ;;;###autoload
|
|
|
141 (defun profile-key-sequence (keys)
|
|
|
142 "Dispatch the key sequence KEYS and profile the execution.
|
|
|
143 KEYS can be a vector of keypress events, a keypress event, or a character.
|
|
|
144 The function returns the profiling info."
|
|
|
145 (interactive "kProfile keystroke: ")
|
|
|
146 (and (characterp keys)
|
|
|
147 (setq keys (character-to-event keys)))
|
|
|
148 (or (vectorp keys)
|
|
|
149 (setq keys (vector keys)))
|
|
|
150 (profile
|
|
|
151 (mapc 'dispatch-event keys)))
|
|
|
152
|
|
155
|
153 ;;; profile.el ends here
|
