|
0
|
1 /* Why the hell is XEmacs so fucking slow?
|
|
|
2 Copyright (C) 1996 Ben Wing.
|
|
|
3
|
|
|
4 This file is part of XEmacs.
|
|
|
5
|
|
|
6 XEmacs is free software; you can redistribute it and/or modify it
|
|
|
7 under the terms of the GNU General Public License as published by the
|
|
|
8 Free Software Foundation; either version 2, or (at your option) any
|
|
|
9 later version.
|
|
|
10
|
|
|
11 XEmacs is distributed in the hope that it will be useful, but WITHOUT
|
|
|
12 ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
|
|
|
13 FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
|
|
|
14 for more details.
|
|
|
15
|
|
|
16 You should have received a copy of the GNU General Public License
|
|
|
17 along with XEmacs; see the file COPYING. If not, write to
|
|
|
18 the Free Software Foundation, Inc., 59 Temple Place - Suite 330,
|
|
|
19 Boston, MA 02111-1307, USA. */
|
|
|
20
|
|
|
21 #include <config.h>
|
|
|
22 #include "lisp.h"
|
|
|
23
|
|
|
24 #include "backtrace.h"
|
|
|
25 #include "bytecode.h"
|
|
|
26 #include "hash.h"
|
|
|
27
|
|
|
28 #include "syssignal.h"
|
|
|
29 #include "systime.h"
|
|
|
30
|
|
|
31 /*
|
|
|
32
|
|
|
33 We implement our own profiling scheme so that we can determine things
|
|
|
34 like which Lisp functions are occupying the most time. Any standard
|
|
|
35 OS-provided profiling works on C functions, which is somewhat useless.
|
|
|
36
|
|
|
37 The basic idea is simple. We set a profiling timer using
|
|
|
38 setitimer (ITIMER_PROF), which generates a SIGPROF every so often.
|
|
|
39 \(This runs not in real time but rather when the process is executing
|
|
|
40 or the system is running on behalf of the process.) When the signal
|
|
|
41 goes off, we see what we're in, and add by 1 the count associated with
|
|
|
42 that function.
|
|
|
43
|
|
|
44 It would be nice to use the Lisp allocation mechanism etc. to keep
|
|
|
45 track of the profiling information, but we can't because that's not
|
|
|
46 safe, and trying to make it safe would be much more work than is
|
|
|
47 worth.
|
|
|
48
|
|
|
49 */
|
|
|
50
|
|
|
51 c_hashtable big_profile_table;
|
|
|
52
|
|
|
53 int default_profiling_interval;
|
|
|
54
|
|
|
55 int profiling_active;
|
|
|
56
|
|
|
57 /* The normal flag in_display is used as a critical-section flag
|
|
|
58 and is not set the whole time we're in redisplay. */
|
|
|
59 int profiling_redisplay_flag;
|
|
|
60
|
|
|
61 Lisp_Object QSin_redisplay;
|
|
|
62 Lisp_Object QSin_garbage_collection;
|
|
|
63 Lisp_Object QSprocessing_events_at_top_level;
|
|
|
64 Lisp_Object QSunknown;
|
|
|
65
|
|
44
|
66 /* We use inside_profiling to prevent the handler from writing to
|
|
|
67 the table while another routine is operating on it. We also set
|
|
|
68 inside_profiling in case the timeout between signal calls is short
|
|
|
69 enough to catch us while we're already in there. */
|
|
|
70 volatile static int inside_profiling;
|
|
|
71
|
|
0
|
72 static SIGTYPE
|
|
|
73 sigprof_handler (int signo)
|
|
|
74 {
|
|
44
|
75 /* Don't do anything if we are shutting down, or are doing a maphash
|
|
|
76 or clrhash on the table. */
|
|
|
77 if (!inside_profiling && !preparing_for_armageddon)
|
|
|
78 {
|
|
|
79 Lisp_Object fun;
|
|
|
80
|
|
|
81 /* If something below causes an error to be signaled, we'll
|
|
|
82 not correctly reset this flag. But we'll be in worse shape
|
|
|
83 than that anyways, since we'll longjmp back to the last
|
|
|
84 condition case. */
|
|
|
85 inside_profiling = 1;
|
|
|
86
|
|
|
87 if (profiling_redisplay_flag)
|
|
|
88 fun = QSin_redisplay;
|
|
|
89 else if (gc_in_progress)
|
|
|
90 fun = QSin_garbage_collection;
|
|
|
91 else if (backtrace_list)
|
|
|
92 {
|
|
|
93 fun = *backtrace_list->function;
|
|
0
|
94
|
|
44
|
95 /* #### dmoore - why do we need to unmark it, we aren't in GC. */
|
|
|
96 XUNMARK (fun);
|
|
|
97 if (!GC_SYMBOLP (fun) && !GC_COMPILED_FUNCTIONP (fun))
|
|
|
98 fun = QSunknown;
|
|
|
99 }
|
|
|
100 else
|
|
|
101 fun = QSprocessing_events_at_top_level;
|
|
0
|
102
|
|
44
|
103 {
|
|
|
104 /* #### see comment about memory allocation in start-profiling.
|
|
|
105 Allocating memory in a signal handler is BAD BAD BAD.
|
|
|
106 If you are using the non-mmap rel-alloc code, you might
|
|
|
107 lose because of this. Even worse, if the memory allocation
|
|
|
108 fails, the `error' generated whacks everything hard. */
|
|
|
109 long count;
|
|
|
110 CONST void *vval;
|
|
|
111
|
|
|
112 if (gethash (LISP_TO_VOID (fun), big_profile_table, &vval))
|
|
|
113 count = (long) vval;
|
|
|
114 else
|
|
|
115 count = 0;
|
|
|
116 count++;
|
|
|
117 vval = (CONST void *) count;
|
|
|
118 puthash (LISP_TO_VOID (fun), (void *) vval, big_profile_table);
|
|
|
119 }
|
|
|
120
|
|
|
121 inside_profiling = 0;
|
|
0
|
122 }
|
|
|
123 }
|
|
|
124
|
|
20
|
125 DEFUN ("start-profiling", Fstart_profiling, 0, 1, 0, /*
|
|
0
|
126 Start profiling, with profile queries every MICROSECS.
|
|
|
127 If MICROSECS is nil or omitted, the value of `default-profiling-interval'
|
|
|
128 is used.
|
|
|
129
|
|
|
130 You can retrieve the recorded profiling info using `get-profiling-info'.
|
|
|
131
|
|
|
132 Starting and stopping profiling does not clear the currently recorded
|
|
|
133 info. Thus you can start and stop as many times as you want and everything
|
|
20
|
134 will be properly accumulated.
|
|
|
135 */
|
|
|
136 (microsecs))
|
|
0
|
137 {
|
|
44
|
138 /* This function can GC */
|
|
0
|
139 int msecs;
|
|
|
140 struct itimerval foo;
|
|
|
141
|
|
|
142 /* #### The hash code can safely be called from a signal handler
|
|
|
143 except when it has to grow the hashtable. In this case, it calls
|
|
|
144 realloc(), which is not (in general) re-entrant. We just be
|
|
|
145 sleazy and make the table large enough that it (hopefully) won't
|
|
|
146 need to be realloc()ed. */
|
|
|
147 if (!big_profile_table)
|
|
|
148 big_profile_table = make_hashtable (10000);
|
|
|
149 if (NILP (microsecs))
|
|
|
150 msecs = default_profiling_interval;
|
|
|
151 else
|
|
|
152 {
|
|
|
153 CHECK_NATNUM (microsecs);
|
|
|
154 msecs = XINT (microsecs);
|
|
|
155 }
|
|
|
156 if (msecs <= 0)
|
|
|
157 msecs = 1000;
|
|
|
158
|
|
|
159 signal (SIGPROF, sigprof_handler);
|
|
|
160 foo.it_value.tv_sec = 0;
|
|
|
161 foo.it_value.tv_usec = msecs;
|
|
|
162 EMACS_NORMALIZE_TIME (foo.it_value);
|
|
|
163 foo.it_interval = foo.it_value;
|
|
|
164 profiling_active = 1;
|
|
44
|
165 inside_profiling = 0;
|
|
0
|
166 setitimer (ITIMER_PROF, &foo, 0);
|
|
|
167 return Qnil;
|
|
|
168 }
|
|
|
169
|
|
20
|
170 DEFUN ("stop-profiling", Fstop_profiling, 0, 0, 0, /*
|
|
0
|
171 Stop profiling.
|
|
20
|
172 */
|
|
|
173 ())
|
|
0
|
174 {
|
|
44
|
175 /* This function does not GC */
|
|
0
|
176 struct itimerval foo;
|
|
|
177
|
|
|
178 foo.it_value.tv_sec = 0;
|
|
|
179 foo.it_value.tv_usec = 0;
|
|
|
180 foo.it_interval = foo.it_value;
|
|
|
181 setitimer (ITIMER_PROF, &foo, 0);
|
|
|
182 profiling_active = 0;
|
|
|
183 signal (SIGPROF, fatal_error_signal);
|
|
|
184 return Qnil;
|
|
|
185 }
|
|
|
186
|
|
44
|
187 static Lisp_Object
|
|
|
188 profile_lock_unwind (Lisp_Object ignore)
|
|
|
189 {
|
|
|
190 inside_profiling = 0;
|
|
|
191 return Qnil;
|
|
|
192 }
|
|
|
193
|
|
0
|
194 struct get_profiling_info_closure
|
|
|
195 {
|
|
|
196 Lisp_Object accum;
|
|
|
197 };
|
|
|
198
|
|
|
199 static void
|
|
|
200 get_profiling_info_maphash (CONST void *void_key,
|
|
|
201 void *void_val,
|
|
|
202 void *void_closure)
|
|
|
203 {
|
|
44
|
204 /* This function does not GC */
|
|
0
|
205 Lisp_Object key;
|
|
|
206 struct get_profiling_info_closure *closure = void_closure;
|
|
|
207 EMACS_INT val;
|
|
|
208
|
|
|
209 CVOID_TO_LISP (key, void_key);
|
|
|
210 val = (EMACS_INT) void_val;
|
|
|
211
|
|
|
212 closure->accum = Fcons (Fcons (key, make_int (val)),
|
|
|
213 closure->accum);
|
|
|
214 }
|
|
|
215
|
|
20
|
216 DEFUN ("get-profiling-info", Fget_profiling_info, 0, 0, 0, /*
|
|
0
|
217 Return the profiling info as an alist.
|
|
20
|
218 */
|
|
|
219 ())
|
|
0
|
220 {
|
|
44
|
221 /* This function does not GC */
|
|
0
|
222 struct get_profiling_info_closure closure;
|
|
|
223
|
|
|
224 closure.accum = Qnil;
|
|
|
225 if (big_profile_table)
|
|
44
|
226 {
|
|
|
227 int count = specpdl_depth ();
|
|
|
228 record_unwind_protect (profile_lock_unwind, Qnil);
|
|
|
229 inside_profiling = 1;
|
|
|
230 maphash (get_profiling_info_maphash, big_profile_table, &closure);
|
|
|
231 unbind_to (count, Qnil);
|
|
|
232 }
|
|
0
|
233 return closure.accum;
|
|
|
234 }
|
|
|
235
|
|
|
236 struct mark_profiling_info_closure
|
|
|
237 {
|
|
|
238 void (*markfun) (Lisp_Object);
|
|
|
239 };
|
|
|
240
|
|
|
241 static void
|
|
|
242 mark_profiling_info_maphash (CONST void *void_key,
|
|
|
243 void *void_val,
|
|
|
244 void *void_closure)
|
|
|
245 {
|
|
|
246 Lisp_Object key;
|
|
|
247 struct mark_profiling_info_closure *closure = void_closure;
|
|
|
248
|
|
|
249 CVOID_TO_LISP (key, void_key);
|
|
|
250 (closure->markfun) (key);
|
|
|
251 }
|
|
|
252
|
|
|
253 void
|
|
|
254 mark_profiling_info (void (*markfun) (Lisp_Object))
|
|
|
255 {
|
|
44
|
256 /* This function does not GC (if markfun doesn't) */
|
|
0
|
257 struct mark_profiling_info_closure closure;
|
|
|
258
|
|
|
259 closure.markfun = markfun;
|
|
|
260 if (big_profile_table)
|
|
44
|
261 {
|
|
|
262 inside_profiling = 1;
|
|
|
263 maphash (mark_profiling_info_maphash, big_profile_table, &closure);
|
|
|
264 inside_profiling = 0;
|
|
|
265 }
|
|
0
|
266 }
|
|
|
267
|
|
20
|
268 DEFUN ("clear-profiling-info", Fclear_profiling_info, 0, 0, 0, /*
|
|
0
|
269 Clear out the recorded profiling info.
|
|
20
|
270 */
|
|
|
271 ())
|
|
0
|
272 {
|
|
44
|
273 /* This function does not GC */
|
|
0
|
274 if (big_profile_table)
|
|
44
|
275 {
|
|
|
276 inside_profiling = 1;
|
|
|
277 clrhash (big_profile_table);
|
|
|
278 inside_profiling = 0;
|
|
|
279 }
|
|
0
|
280 return Qnil;
|
|
|
281 }
|
|
|
282
|
|
20
|
283 DEFUN ("profiling-active-p", Fprofiling_active_p, 0, 0, 0, /*
|
|
0
|
284 Return non-nil if profiling information is currently being recorded.
|
|
20
|
285 */
|
|
|
286 ())
|
|
0
|
287 {
|
|
|
288 return profiling_active ? Qt : Qnil;
|
|
|
289 }
|
|
|
290
|
|
|
291 void
|
|
|
292 syms_of_profile (void)
|
|
|
293 {
|
|
20
|
294 DEFSUBR (Fstart_profiling);
|
|
|
295 DEFSUBR (Fstop_profiling);
|
|
|
296 DEFSUBR (Fget_profiling_info);
|
|
|
297 DEFSUBR (Fclear_profiling_info);
|
|
|
298 DEFSUBR (Fprofiling_active_p);
|
|
0
|
299 }
|
|
|
300
|
|
|
301 void
|
|
|
302 vars_of_profile (void)
|
|
|
303 {
|
|
|
304 DEFVAR_INT ("default-profiling-interval", &default_profiling_interval /*
|
|
|
305 Default time in microseconds between profiling queries.
|
|
|
306 Used when the argument to `start-profiling' is nil or omitted.
|
|
|
307 Note that the time in question is CPU time (when the program is executing
|
|
|
308 or the kernel is executing on behalf of the program) and not real time.
|
|
|
309 */ );
|
|
|
310 default_profiling_interval = 1000;
|
|
|
311
|
|
44
|
312 inside_profiling = 0;
|
|
|
313
|
|
0
|
314 QSin_redisplay = build_string ("(in redisplay)");
|
|
|
315 staticpro (&QSin_redisplay);
|
|
|
316 QSin_garbage_collection = build_string ("(in garbage collection)");
|
|
|
317 staticpro (&QSin_garbage_collection);
|
|
|
318 QSunknown = build_string ("(unknown)");
|
|
|
319 staticpro (&QSunknown);
|
|
|
320 QSprocessing_events_at_top_level =
|
|
|
321 build_string ("(processing events at top level)");
|
|
|
322 staticpro (&QSprocessing_events_at_top_level);
|
|
|
323 }
|
