|
428
|
1 /* Why the hell is XEmacs so fucking slow?
|
|
1123
|
2 Copyright (C) 1996, 2002 Ben Wing.
|
|
428
|
3 Copyright (C) 1998 Free Software Foundation, Inc.
|
|
|
4
|
|
|
5 This file is part of XEmacs.
|
|
|
6
|
|
|
7 XEmacs is free software; you can redistribute it and/or modify it
|
|
|
8 under the terms of the GNU General Public License as published by the
|
|
|
9 Free Software Foundation; either version 2, or (at your option) any
|
|
|
10 later version.
|
|
|
11
|
|
|
12 XEmacs is distributed in the hope that it will be useful, but WITHOUT
|
|
|
13 ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
|
|
|
14 FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
|
|
|
15 for more details.
|
|
|
16
|
|
|
17 You should have received a copy of the GNU General Public License
|
|
|
18 along with XEmacs; see the file COPYING. If not, write to
|
|
|
19 the Free Software Foundation, Inc., 59 Temple Place - Suite 330,
|
|
|
20 Boston, MA 02111-1307, USA. */
|
|
|
21
|
|
|
22 #include <config.h>
|
|
|
23 #include "lisp.h"
|
|
|
24
|
|
|
25 #include "backtrace.h"
|
|
|
26 #include "bytecode.h"
|
|
|
27 #include "elhash.h"
|
|
|
28 #include "hash.h"
|
|
|
29
|
|
|
30 #include "syssignal.h"
|
|
|
31 #include "systime.h"
|
|
|
32
|
|
611
|
33 #ifndef HAVE_SETITIMER
|
|
|
34 #error Sorry charlie. We need a scalpel and all we have is a lawnmower.
|
|
|
35 #endif
|
|
|
36
|
|
428
|
37 /* We implement our own profiling scheme so that we can determine
|
|
|
38 things like which Lisp functions are occupying the most time. Any
|
|
|
39 standard OS-provided profiling works on C functions, which is
|
|
|
40 somewhat useless.
|
|
|
41
|
|
|
42 The basic idea is simple. We set a profiling timer using setitimer
|
|
|
43 (ITIMER_PROF), which generates a SIGPROF every so often. (This
|
|
|
44 runs not in real time but rather when the process is executing or
|
|
|
45 the system is running on behalf of the process.) When the signal
|
|
|
46 goes off, we see what we're in, and add 1 to the count associated
|
|
|
47 with that function.
|
|
|
48
|
|
|
49 It would be nice to use the Lisp allocation mechanism etc. to keep
|
|
|
50 track of the profiling information, but we can't because that's not
|
|
|
51 safe, and trying to make it safe would be much more work than it's
|
|
|
52 worth.
|
|
|
53
|
|
|
54 Jan 1998: In addition to this, I have added code to remember call
|
|
|
55 counts of Lisp funcalls. The profile_increase_call_count()
|
|
|
56 function is called from Ffuncall(), and serves to add data to
|
|
|
57 Vcall_count_profile_table. This mechanism is much simpler and
|
|
|
58 independent of the SIGPROF-driven one. It uses the Lisp allocation
|
|
|
59 mechanism normally, since it is not called from a handler. It may
|
|
|
60 even be useful to provide a way to turn on only one profiling
|
|
|
61 mechanism, but I haven't done so yet. --hniksic */
|
|
|
62
|
|
|
63 static struct hash_table *big_profile_table;
|
|
|
64 Lisp_Object Vcall_count_profile_table;
|
|
|
65
|
|
458
|
66 Fixnum default_profiling_interval;
|
|
428
|
67
|
|
|
68 int profiling_active;
|
|
|
69
|
|
|
70 /* The normal flag in_display is used as a critical-section flag
|
|
|
71 and is not set the whole time we're in redisplay. */
|
|
|
72 int profiling_redisplay_flag;
|
|
|
73
|
|
|
74 static Lisp_Object QSin_redisplay;
|
|
|
75 static Lisp_Object QSin_garbage_collection;
|
|
|
76 static Lisp_Object QSprocessing_events_at_top_level;
|
|
|
77 static Lisp_Object QSunknown;
|
|
|
78
|
|
1123
|
79 static Lisp_Object Qtiming, Qcall_count;
|
|
|
80
|
|
428
|
81 /* We use inside_profiling to prevent the handler from writing to
|
|
|
82 the table while another routine is operating on it. We also set
|
|
|
83 inside_profiling in case the timeout between signal calls is short
|
|
|
84 enough to catch us while we're already in there. */
|
|
|
85 static volatile int inside_profiling;
|
|
|
86
|
|
1123
|
87 static void
|
|
|
88 create_call_count_profile_table (void)
|
|
|
89 {
|
|
|
90 if (NILP (Vcall_count_profile_table))
|
|
|
91 Vcall_count_profile_table =
|
|
|
92 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQ);
|
|
|
93 }
|
|
|
94
|
|
|
95 static void
|
|
|
96 create_timing_profile_table (void)
|
|
|
97 {
|
|
|
98 /* #### The hash code can safely be called from a signal handler
|
|
|
99 except when it has to grow the hash table. In this case, it calls
|
|
|
100 realloc(), which is not (in general) re-entrant. We'll just be
|
|
|
101 sleazy and make the table large enough that it (hopefully) won't
|
|
|
102 need to be realloc()ed. */
|
|
|
103 if (!big_profile_table)
|
|
|
104 big_profile_table = make_hash_table (10000);
|
|
|
105 }
|
|
|
106
|
|
428
|
107 /* Increase the value of OBJ in Vcall_count_profile_table hash table.
|
|
|
108 If the hash table is nil, create it first. */
|
|
|
109 void
|
|
|
110 profile_increase_call_count (Lisp_Object obj)
|
|
|
111 {
|
|
|
112 Lisp_Object count;
|
|
|
113
|
|
1123
|
114 create_call_count_profile_table ();
|
|
428
|
115
|
|
|
116 count = Fgethash (obj, Vcall_count_profile_table, Qzero);
|
|
|
117 if (!INTP (count))
|
|
|
118 count = Qzero;
|
|
|
119 Fputhash (obj, make_int (1 + XINT (count)), Vcall_count_profile_table);
|
|
|
120 }
|
|
|
121
|
|
|
122 static SIGTYPE
|
|
|
123 sigprof_handler (int signo)
|
|
|
124 {
|
|
|
125 /* Don't do anything if we are shutting down, or are doing a maphash
|
|
|
126 or clrhash on the table. */
|
|
|
127 if (!inside_profiling && !preparing_for_armageddon)
|
|
|
128 {
|
|
|
129 Lisp_Object fun;
|
|
|
130
|
|
|
131 /* If something below causes an error to be signaled, we'll
|
|
|
132 not correctly reset this flag. But we'll be in worse shape
|
|
|
133 than that anyways, since we'll longjmp back to the last
|
|
|
134 condition case. */
|
|
|
135 inside_profiling = 1;
|
|
|
136
|
|
|
137 if (profiling_redisplay_flag)
|
|
|
138 fun = QSin_redisplay;
|
|
|
139 else if (gc_in_progress)
|
|
|
140 fun = QSin_garbage_collection;
|
|
|
141 else if (backtrace_list)
|
|
|
142 {
|
|
|
143 fun = *backtrace_list->function;
|
|
|
144
|
|
434
|
145 if (!SYMBOLP (fun)
|
|
|
146 && !COMPILED_FUNCTIONP (fun)
|
|
|
147 && !SUBRP (fun)
|
|
|
148 && !CONSP (fun))
|
|
428
|
149 fun = QSunknown;
|
|
|
150 }
|
|
|
151 else
|
|
|
152 fun = QSprocessing_events_at_top_level;
|
|
|
153
|
|
|
154 {
|
|
|
155 /* #### see comment about memory allocation in start-profiling.
|
|
|
156 Allocating memory in a signal handler is BAD BAD BAD.
|
|
|
157 If you are using the non-mmap rel-alloc code, you might
|
|
|
158 lose because of this. Even worse, if the memory allocation
|
|
|
159 fails, the `error' generated whacks everything hard. */
|
|
|
160 long count;
|
|
442
|
161 const void *vval;
|
|
428
|
162
|
|
|
163 if (gethash (LISP_TO_VOID (fun), big_profile_table, &vval))
|
|
|
164 count = (long) vval;
|
|
|
165 else
|
|
|
166 count = 0;
|
|
|
167 count++;
|
|
442
|
168 vval = (const void *) count;
|
|
428
|
169 puthash (LISP_TO_VOID (fun), (void *) vval, big_profile_table);
|
|
|
170 }
|
|
|
171
|
|
|
172 inside_profiling = 0;
|
|
|
173 }
|
|
|
174 }
|
|
|
175
|
|
|
176 DEFUN ("start-profiling", Fstart_profiling, 0, 1, 0, /*
|
|
|
177 Start profiling, with profile queries every MICROSECS.
|
|
|
178 If MICROSECS is nil or omitted, the value of `default-profiling-interval'
|
|
|
179 is used.
|
|
|
180
|
|
1123
|
181 Information on function timings and call counts is currently recorded.
|
|
428
|
182 You can retrieve the recorded profiling info using `get-profiling-info'.
|
|
|
183
|
|
|
184 Starting and stopping profiling does not clear the currently recorded
|
|
|
185 info. Thus you can start and stop as many times as you want and everything
|
|
|
186 will be properly accumulated.
|
|
|
187 */
|
|
|
188 (microsecs))
|
|
|
189 {
|
|
|
190 /* This function can GC */
|
|
|
191 int msecs;
|
|
|
192 struct itimerval foo;
|
|
|
193
|
|
|
194 /* #### The hash code can safely be called from a signal handler
|
|
|
195 except when it has to grow the hash table. In this case, it calls
|
|
|
196 realloc(), which is not (in general) re-entrant. We'll just be
|
|
|
197 sleazy and make the table large enough that it (hopefully) won't
|
|
|
198 need to be realloc()ed. */
|
|
1123
|
199 create_timing_profile_table ();
|
|
428
|
200
|
|
|
201 if (NILP (microsecs))
|
|
|
202 msecs = default_profiling_interval;
|
|
|
203 else
|
|
|
204 {
|
|
|
205 CHECK_NATNUM (microsecs);
|
|
|
206 msecs = XINT (microsecs);
|
|
|
207 }
|
|
|
208 if (msecs <= 0)
|
|
|
209 msecs = 1000;
|
|
|
210
|
|
613
|
211 set_timeout_signal (SIGPROF, sigprof_handler);
|
|
428
|
212 foo.it_value.tv_sec = 0;
|
|
|
213 foo.it_value.tv_usec = msecs;
|
|
|
214 EMACS_NORMALIZE_TIME (foo.it_value);
|
|
|
215 foo.it_interval = foo.it_value;
|
|
|
216 profiling_active = 1;
|
|
|
217 inside_profiling = 0;
|
|
611
|
218 qxe_setitimer (ITIMER_PROF, &foo, 0);
|
|
428
|
219 return Qnil;
|
|
|
220 }
|
|
|
221
|
|
|
222 DEFUN ("stop-profiling", Fstop_profiling, 0, 0, 0, /*
|
|
|
223 Stop profiling.
|
|
|
224 */
|
|
|
225 ())
|
|
|
226 {
|
|
|
227 /* This function does not GC */
|
|
|
228 struct itimerval foo;
|
|
|
229
|
|
|
230 foo.it_value.tv_sec = 0;
|
|
|
231 foo.it_value.tv_usec = 0;
|
|
|
232 foo.it_interval = foo.it_value;
|
|
611
|
233 qxe_setitimer (ITIMER_PROF, &foo, 0);
|
|
428
|
234 profiling_active = 0;
|
|
613
|
235 set_timeout_signal (SIGPROF, fatal_error_signal);
|
|
428
|
236 return Qnil;
|
|
|
237 }
|
|
|
238
|
|
1123
|
239 DEFUN ("clear-profiling-info", Fclear_profiling_info, 0, 0, "", /*
|
|
|
240 Clear out the recorded profiling info.
|
|
|
241 This clears both the internal timing information and the call counts in
|
|
|
242 `call-count-profile-table'.
|
|
|
243 */
|
|
|
244 ())
|
|
|
245 {
|
|
|
246 /* This function does not GC */
|
|
|
247 if (big_profile_table)
|
|
|
248 {
|
|
|
249 inside_profiling = 1;
|
|
|
250 clrhash (big_profile_table);
|
|
|
251 inside_profiling = 0;
|
|
|
252 }
|
|
|
253 if (!NILP (Vcall_count_profile_table))
|
|
|
254 Fclrhash (Vcall_count_profile_table);
|
|
|
255 return Qnil;
|
|
|
256 }
|
|
|
257
|
|
428
|
258 struct get_profiling_info_closure
|
|
|
259 {
|
|
1123
|
260 Lisp_Object timing;
|
|
428
|
261 };
|
|
|
262
|
|
|
263 static int
|
|
1123
|
264 get_profiling_info_timing_maphash (const void *void_key,
|
|
|
265 void *void_val,
|
|
|
266 void *void_closure)
|
|
428
|
267 {
|
|
|
268 /* This function does not GC */
|
|
|
269 Lisp_Object key;
|
|
|
270 struct get_profiling_info_closure *closure
|
|
|
271 = (struct get_profiling_info_closure *) void_closure;
|
|
|
272 EMACS_INT val;
|
|
|
273
|
|
826
|
274 key = VOID_TO_LISP (void_key);
|
|
428
|
275 val = (EMACS_INT) void_val;
|
|
|
276
|
|
1123
|
277 Fputhash (key, make_int (val), closure->timing);
|
|
428
|
278 return 0;
|
|
|
279 }
|
|
|
280
|
|
|
281 DEFUN ("get-profiling-info", Fget_profiling_info, 0, 0, 0, /*
|
|
1123
|
282 Return the currently recorded profiling info.
|
|
|
283 The format is a plist of symbols describing type of info recorded and
|
|
|
284 an associated type-specific entry. Currently, the following info types
|
|
|
285 are recorded
|
|
|
286
|
|
|
287 `timing'
|
|
|
288 A hash table of funcallable objects or strings describing internal processing
|
|
|
289 operations \(redisplay, garbage collection, etc.), along with associated
|
|
|
290 tick counts (the frequency of ticks is controlled by
|
|
|
291 `default-profiling-interval' or the argument to `start-profiling').
|
|
|
292
|
|
|
293 `call-count'
|
|
|
294 A hash table of funcallable objects and associated call counts.
|
|
428
|
295 */
|
|
|
296 ())
|
|
|
297 {
|
|
|
298 /* This function does not GC */
|
|
|
299 struct get_profiling_info_closure closure;
|
|
|
300
|
|
1123
|
301 closure.timing =
|
|
|
302 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQUAL);
|
|
|
303
|
|
428
|
304 if (big_profile_table)
|
|
|
305 {
|
|
853
|
306 int count = internal_bind_int ((int *) &inside_profiling, 1);
|
|
1123
|
307 maphash (get_profiling_info_timing_maphash, big_profile_table, &closure);
|
|
771
|
308 unbind_to (count);
|
|
428
|
309 }
|
|
1123
|
310
|
|
|
311 return list4 (Qtiming, closure.timing, Qcall_count,
|
|
|
312 !NILP (Vcall_count_profile_table) ?
|
|
|
313 Fcopy_hash_table (Vcall_count_profile_table) :
|
|
|
314 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK,
|
|
|
315 HASH_TABLE_EQ));
|
|
|
316 }
|
|
|
317
|
|
|
318 struct set_profiling_info_closure
|
|
|
319 {
|
|
|
320 Lisp_Object timing;
|
|
|
321 };
|
|
|
322
|
|
|
323 static int
|
|
|
324 set_profiling_info_timing_maphash (Lisp_Object key,
|
|
|
325 Lisp_Object val,
|
|
|
326 void *void_closure)
|
|
|
327 {
|
|
|
328 /* This function does not GC */
|
|
|
329 if (!INTP (val))
|
|
|
330 invalid_argument_2
|
|
|
331 ("Function timing count is not an integer in given entry",
|
|
|
332 key, val);
|
|
|
333
|
|
|
334 puthash (LISP_TO_VOID (key), (void *) XINT (val), big_profile_table);
|
|
|
335
|
|
|
336 return 0;
|
|
|
337 }
|
|
|
338
|
|
|
339 DEFUN ("set-profiling-info", Fset_profiling_info, 1, 1, 0, /*
|
|
|
340 Set the currently recorded profiling info.
|
|
|
341 INFO should be in the same format returned by `get-profiling-info',
|
|
|
342 as described there.
|
|
|
343 */
|
|
|
344 (info))
|
|
|
345 {
|
|
|
346 /* This function does not GC */
|
|
|
347 Fclear_profiling_info ();
|
|
|
348
|
|
|
349 {
|
|
|
350 EXTERNAL_PROPERTY_LIST_LOOP_3 (key, value, info)
|
|
|
351 {
|
|
|
352 if (EQ (key, Qtiming))
|
|
|
353 {
|
|
|
354 CHECK_HASH_TABLE (value);
|
|
|
355 create_timing_profile_table ();
|
|
|
356 elisp_maphash_unsafe (set_profiling_info_timing_maphash, value,
|
|
|
357 NULL);
|
|
|
358 }
|
|
|
359 else if (EQ (key, Qcall_count))
|
|
|
360 {
|
|
|
361 Vcall_count_profile_table = Fcopy_hash_table (value);
|
|
|
362 }
|
|
|
363 else
|
|
|
364 invalid_constant ("Unrecognized profiling-info keyword", key);
|
|
|
365 }
|
|
|
366 }
|
|
|
367
|
|
|
368 return Qnil;
|
|
428
|
369 }
|
|
|
370
|
|
|
371 static int
|
|
442
|
372 mark_profiling_info_maphash (const void *void_key,
|
|
428
|
373 void *void_val,
|
|
|
374 void *void_closure)
|
|
|
375 {
|
|
|
376 Lisp_Object key;
|
|
|
377
|
|
826
|
378 key = VOID_TO_LISP (void_key);
|
|
428
|
379 mark_object (key);
|
|
|
380 return 0;
|
|
|
381 }
|
|
|
382
|
|
|
383 void
|
|
|
384 mark_profiling_info (void)
|
|
|
385 {
|
|
|
386 /* This function does not GC */
|
|
|
387 if (big_profile_table)
|
|
|
388 {
|
|
|
389 inside_profiling = 1;
|
|
|
390 maphash (mark_profiling_info_maphash, big_profile_table, 0);
|
|
|
391 inside_profiling = 0;
|
|
|
392 }
|
|
|
393 }
|
|
|
394
|
|
|
395 DEFUN ("profiling-active-p", Fprofiling_active_p, 0, 0, 0, /*
|
|
|
396 Return non-nil if profiling information is currently being recorded.
|
|
|
397 */
|
|
|
398 ())
|
|
|
399 {
|
|
|
400 return profiling_active ? Qt : Qnil;
|
|
|
401 }
|
|
|
402
|
|
|
403 void
|
|
|
404 syms_of_profile (void)
|
|
|
405 {
|
|
|
406 DEFSUBR (Fstart_profiling);
|
|
|
407 DEFSUBR (Fstop_profiling);
|
|
|
408 DEFSUBR (Fget_profiling_info);
|
|
1123
|
409 DEFSUBR (Fset_profiling_info);
|
|
428
|
410 DEFSUBR (Fclear_profiling_info);
|
|
|
411 DEFSUBR (Fprofiling_active_p);
|
|
|
412 }
|
|
|
413
|
|
|
414 void
|
|
|
415 vars_of_profile (void)
|
|
|
416 {
|
|
|
417 DEFVAR_INT ("default-profiling-interval", &default_profiling_interval /*
|
|
|
418 Default CPU time in microseconds between profiling sampling.
|
|
|
419 Used when the argument to `start-profiling' is nil or omitted.
|
|
|
420 Note that the time in question is CPU time (when the program is executing
|
|
1123
|
421 or the kernel is executing on behalf of the program) and not real time, and
|
|
|
422 there is usually a machine-dependent limit on how small this value can be.
|
|
428
|
423 */ );
|
|
|
424 default_profiling_interval = 1000;
|
|
|
425
|
|
1123
|
426 staticpro (&Vcall_count_profile_table);
|
|
428
|
427 Vcall_count_profile_table = Qnil;
|
|
|
428
|
|
|
429 inside_profiling = 0;
|
|
|
430
|
|
771
|
431 QSin_redisplay = build_msg_string ("(in redisplay)");
|
|
428
|
432 staticpro (&QSin_redisplay);
|
|
771
|
433 QSin_garbage_collection = build_msg_string ("(in garbage collection)");
|
|
428
|
434 staticpro (&QSin_garbage_collection);
|
|
771
|
435 QSunknown = build_msg_string ("(unknown)");
|
|
428
|
436 staticpro (&QSunknown);
|
|
|
437 QSprocessing_events_at_top_level =
|
|
771
|
438 build_msg_string ("(processing events at top level)");
|
|
428
|
439 staticpro (&QSprocessing_events_at_top_level);
|
|
1123
|
440
|
|
|
441 DEFSYMBOL (Qtiming);
|
|
|
442 DEFSYMBOL (Qcall_count);
|
|
428
|
443 }
|
