|
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
|
|
|
38 ;; this, `pretty-print-profiling-info' easily extracts the total
|
|
|
39 ;; number of ticks, and the percentage CPU time of each function.
|
|
|
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
|
|
|
54 ;; `pretty-print-profiling-info'.
|
|
|
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
|
|
|
63 ;;;###autoload
|
|
167
|
64 (defun pretty-print-profiling-info (&optional info stream)
|
|
|
65 "Print profiling info INFO to STREAM in a pretty format.
|
|
0
|
66 If INFO is omitted, the current profiling info is retrieved using
|
|
199
|
67 `get-profiling-info'.
|
|
|
68 If STREAM is omitted, either a *Profiling Results* buffer or standard
|
|
|
69 output are used, depending on whether the function was called
|
|
|
70 interactively or not."
|
|
167
|
71 (interactive)
|
|
199
|
72 (setq info (if info
|
|
|
73 (copy-alist info)
|
|
|
74 (get-profiling-info)))
|
|
|
75 (when (and (not stream)
|
|
|
76 (interactive-p))
|
|
|
77 (pop-to-buffer (get-buffer-create "*Profiling Results*"))
|
|
|
78 (erase-buffer))
|
|
|
79 (let* ((standard-output (or stream (if (interactive-p)
|
|
|
80 (current-buffer)
|
|
|
81 standard-output)))
|
|
|
82 (maxfunlen (max (length "Function Name")
|
|
|
83 (apply 'max (mapcar (lambda (sym)
|
|
|
84 (length (symbol-name
|
|
|
85 (car sym))))
|
|
|
86 info))))
|
|
|
87 (formatstr (format "%%-%ds" maxfunlen)))
|
|
167
|
88 (setq info (nreverse (sort info #'cdr-less-than-cdr)))
|
|
199
|
89 (princ (format (concat formatstr " Ticks %%/Total\n")
|
|
|
90 "Function Name"))
|
|
|
91 (princ (make-string maxfunlen ?=))
|
|
|
92 (princ " ===== =======\n")
|
|
167
|
93 (let ((sum 0.0))
|
|
|
94 (dolist (info2 info)
|
|
|
95 (incf sum (cdr info2)))
|
|
|
96 (while info
|
|
|
97 (let ((f (caar info)))
|
|
199
|
98 (princ (format (concat formatstr " %-5d %-6.3f\n")
|
|
|
99 f (cdar info) (* 100 (/ (cdar info) sum)))))
|
|
|
100 (pop info))
|
|
|
101 (princ (make-string maxfunlen ?-))
|
|
|
102 (princ "--------------------\n")
|
|
|
103 (princ (format (concat formatstr " %-5d %-6.2f\n")
|
|
|
104 "Total" sum 100.0))
|
|
|
105 (princ (format "\n\nOne tick = %g ms\n"
|
|
|
106 (/ default-profiling-interval 1000.0)))))
|
|
|
107 (when (and (not stream)
|
|
|
108 (interactive-p))
|
|
|
109 (goto-char (point-min))))
|
|
155
|
110
|
|
199
|
111 ;; Is it really necessary for this to be a macro?
|
|
165
|
112 ;;;###autoload
|
|
|
113 (defmacro profile (&rest forms)
|
|
173
|
114 "Turn on profiling, execute FORMS and restore profiling state.
|
|
|
115 Profiling state here means that if profiling was not in effect when
|
|
|
116 PROFILE was called, it will be turned off after FORMS are evaluated.
|
|
|
117 Otherwise, profiling will be left running.
|
|
|
118
|
|
165
|
119 Returns the profiling info, printable by `pretty-print-profiling-info'."
|
|
|
120 `(progn
|
|
173
|
121 (if (profiling-active-p)
|
|
165
|
122 (progn
|
|
|
123 ,@forms)
|
|
173
|
124 (unwind-protect
|
|
|
125 (progn
|
|
|
126 (start-profiling)
|
|
|
127 ,@forms)
|
|
|
128 (stop-profiling)))
|
|
165
|
129 (get-profiling-info)))
|
|
|
130
|
|
|
131 (put 'profile 'lisp-indent-function 0)
|
|
|
132
|
|
167
|
133 ;;;###autoload
|
|
|
134 (defun profile-key-sequence (keys)
|
|
|
135 "Dispatch the key sequence KEYS and profile the execution.
|
|
|
136 KEYS can be a vector of keypress events, a keypress event, or a character.
|
|
|
137 The function returns the profiling info."
|
|
|
138 (interactive "kProfile keystroke: ")
|
|
|
139 (and (characterp keys)
|
|
|
140 (setq keys (character-to-event keys)))
|
|
|
141 (or (vectorp keys)
|
|
|
142 (setq keys (vector keys)))
|
|
|
143 (profile
|
|
|
144 (mapc 'dispatch-event keys)))
|
|
|
145
|
|
155
|
146 ;;; profile.el ends here
|
