|
428
|
1 /* Why the hell is XEmacs so fucking slow?
|
|
1292
|
2 Copyright (C) 1996, 2002, 2003 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"
|
|
1315
|
29 #include "profile.h"
|
|
428
|
30
|
|
|
31 #include "syssignal.h"
|
|
|
32 #include "systime.h"
|
|
|
33
|
|
611
|
34 #ifndef HAVE_SETITIMER
|
|
|
35 #error Sorry charlie. We need a scalpel and all we have is a lawnmower.
|
|
|
36 #endif
|
|
|
37
|
|
1292
|
38 #ifdef WIN32_ANY
|
|
|
39 int mswindows_is_blocking;
|
|
|
40 #endif
|
|
|
41
|
|
|
42 /* Written by Ben Wing.
|
|
|
43
|
|
|
44 We implement our own profiling scheme so that we can determine
|
|
428
|
45 things like which Lisp functions are occupying the most time. Any
|
|
|
46 standard OS-provided profiling works on C functions, which is
|
|
1292
|
47 not always that useful -- and inconvenient, since it requires compiling
|
|
|
48 with profile info and can't be retrieved dynamically, as XEmacs is
|
|
|
49 running.
|
|
428
|
50
|
|
|
51 The basic idea is simple. We set a profiling timer using setitimer
|
|
1292
|
52 (ITIMER_PROF), which generates a SIGPROF every so often. (This runs not
|
|
|
53 in real time but rather when the process is executing or the system is
|
|
1346
|
54 running on behalf of the process -- at least, that is the case under
|
|
|
55 Unix. Under MS Windows and Cygwin, there is no setitimer(), so we
|
|
|
56 simulate it using multimedia timers, which run in real time. To make
|
|
|
57 the results a bit more realistic, we ignore ticks that go off while
|
|
|
58 blocking on an event wait. Note that Cygwin does provide a simulation
|
|
|
59 of setitimer(), but it's in real time anyway, since Windows doesn't
|
|
|
60 provide a way to have process-time timers, and furthermore, it's broken,
|
|
|
61 so we don't use it.) When the signal goes off, we see what we're in, and
|
|
|
62 add 1 to the count associated with that function.
|
|
428
|
63
|
|
1292
|
64 It would be nice to use the Lisp allocation mechanism etc. to keep track
|
|
|
65 of the profiling information (i.e. to use Lisp hash tables), but we
|
|
|
66 can't because that's not safe -- updating the timing information happens
|
|
|
67 inside of a signal handler, so we can't rely on not being in the middle
|
|
|
68 of Lisp allocation, garbage collection, malloc(), etc. Trying to make
|
|
|
69 it work would be much more work than it's worth. Instead we use a basic
|
|
|
70 (non-Lisp) hash table, which will not conflict with garbage collection
|
|
|
71 or anything else as long as it doesn't try to resize itself. Resizing
|
|
|
72 itself, however (which happens as a result of a puthash()), could be
|
|
|
73 deadly. To avoid this, we make sure, at points where it's safe
|
|
|
74 (e.g. profile_record_about_to_call() -- recording the entry into a
|
|
|
75 function call), that the table always has some breathing room in it so
|
|
|
76 that no resizes will occur until at least that many items are added.
|
|
|
77 This is safe because any new item to be added in the sigprof would
|
|
|
78 likely have the profile_record_about_to_call() called just before it,
|
|
|
79 and the breathing room is checked.
|
|
428
|
80
|
|
1292
|
81 In general: any entry that the sigprof handler puts into the table comes
|
|
|
82 from a backtrace frame (except "Processing Events at Top Level", and
|
|
|
83 there's only one of those). Either that backtrace frame was added when
|
|
|
84 profiling was on (in which case profile_record_about_to_call() was
|
|
|
85 called and the breathing space updated), or when it was off -- and in
|
|
|
86 this case, no such frames can have been added since the last time
|
|
|
87 `start-profile' was called, so when `start-profile' is called we make
|
|
|
88 sure there is sufficient breathing room to account for all entries
|
|
|
89 currently on the stack.
|
|
|
90
|
|
|
91 Jan 1998: In addition to timing info, I have added code to remember call
|
|
428
|
92 counts of Lisp funcalls. The profile_increase_call_count()
|
|
|
93 function is called from Ffuncall(), and serves to add data to
|
|
|
94 Vcall_count_profile_table. This mechanism is much simpler and
|
|
|
95 independent of the SIGPROF-driven one. It uses the Lisp allocation
|
|
|
96 mechanism normally, since it is not called from a handler. It may
|
|
|
97 even be useful to provide a way to turn on only one profiling
|
|
1292
|
98 mechanism, but I haven't done so yet. --hniksic
|
|
|
99
|
|
|
100 Dec 2002: Total overhaul of the interface, making it sane and easier to
|
|
|
101 use. --ben
|
|
|
102
|
|
|
103 Feb 2003: Lots of rewriting of the internal code. Add GC-consing-usage,
|
|
|
104 total GC usage, and total timing to the information tracked. Track
|
|
|
105 profiling overhead and allow the ability to have internal sections
|
|
|
106 (e.g. internal-external conversion, byte-char conversion) that are
|
|
|
107 treated like Lisp functions for the purpose of profiling. --ben
|
|
428
|
108
|
|
1292
|
109 BEWARE: If you are modifying this file, be *very* careful. Correctly
|
|
|
110 implementing the "total" values is very tricky due to the possibility of
|
|
|
111 recursion and of functions already on the stack when starting to
|
|
|
112 profile/still on the stack when stopping.
|
|
|
113 */
|
|
|
114
|
|
|
115 /* We use a plain table here because we're recording inside of a signal
|
|
|
116 handler. */
|
|
428
|
117 static struct hash_table *big_profile_table;
|
|
1292
|
118 Lisp_Object Vtotal_timing_profile_table;
|
|
428
|
119 Lisp_Object Vcall_count_profile_table;
|
|
1292
|
120 Lisp_Object Vtotal_gc_usage_profile_table;
|
|
|
121 Lisp_Object Vgc_usage_profile_table;
|
|
|
122
|
|
|
123 extern int lisp_eval_depth;
|
|
|
124
|
|
|
125 extern EMACS_UINT total_consing;
|
|
|
126 static volatile EMACS_UINT total_ticks;
|
|
428
|
127
|
|
458
|
128 Fixnum default_profiling_interval;
|
|
428
|
129
|
|
|
130 int profiling_active;
|
|
|
131
|
|
1292
|
132 static Lisp_Object QSprocessing_events_at_top_level;
|
|
|
133 static Lisp_Object QSunknown, QSprofile_overhead;
|
|
|
134
|
|
|
135 static Lisp_Object Qtiming, Qtotal_timing, Qcall_count;
|
|
|
136 static Lisp_Object Qgc_usage, Qtotal_gc_usage;
|
|
|
137
|
|
|
138 /* This needs to be >= the total number of defined internal sections,
|
|
|
139 plus 1 or 2?? Set it extra big just to be ultra-paranoid. */
|
|
|
140 #define EXTRA_BREATHING_ROOM 100
|
|
428
|
141
|
|
1292
|
142 /* We use profiling_lock to prevent the signal handler from writing to
|
|
|
143 the table while another routine is operating on it. We also set
|
|
|
144 profiling_lock in case the timeout between signal calls is short
|
|
|
145 enough to catch us while we're already in there. */
|
|
|
146 static volatile int profiling_lock;
|
|
428
|
147
|
|
1292
|
148 /* Whether we're in the process of doing *any* profiling-related stuff.
|
|
|
149 Used to indicate amount of time spent profiling. */
|
|
|
150 static int in_profiling;
|
|
|
151
|
|
|
152 #if 0 /* #### for KKCC, eventually */
|
|
1123
|
153
|
|
1292
|
154 static const struct memory_description hentry_description_1[] = {
|
|
|
155 { XD_LISP_OBJECT, offsetof (hentry, key) },
|
|
|
156 { XD_END }
|
|
|
157 };
|
|
|
158
|
|
|
159 static const struct sized_memory_description hentry_description = {
|
|
|
160 sizeof (hentry),
|
|
|
161 hentry_description_1
|
|
|
162 };
|
|
428
|
163
|
|
1292
|
164 static const struct memory_description plain_hash_table_description_1[] = {
|
|
|
165 { XD_ELEMCOUNT, offsetof (struct hash_table, size) },
|
|
|
166 { XD_STRUCT_PTR, offsetof (struct hash_table, harray), XD_INDIRECT (0, 0),
|
|
|
167 &hentry_description },
|
|
|
168 { XD_END }
|
|
|
169 };
|
|
|
170
|
|
|
171 static const struct sized_memory_description plain_hash_table_description = {
|
|
|
172 sizeof (struct hash_table),
|
|
|
173 plain_hash_table_description_1
|
|
|
174 };
|
|
|
175
|
|
|
176 #endif /* 0 */
|
|
1123
|
177
|
|
|
178 static void
|
|
|
179 create_timing_profile_table (void)
|
|
|
180 {
|
|
1292
|
181 /* The hash code can safely be called from a signal handler except when
|
|
|
182 it has to grow the hash table. In this case, it calls realloc(),
|
|
|
183 which is not (in general) re-entrant. The way we deal with this is
|
|
|
184 documented at the top of this file. */
|
|
1123
|
185 if (!big_profile_table)
|
|
1292
|
186 big_profile_table = make_hash_table (2000);
|
|
|
187 }
|
|
|
188
|
|
|
189 static void
|
|
|
190 create_profile_tables (void)
|
|
|
191 {
|
|
|
192 create_timing_profile_table ();
|
|
|
193 if (NILP (Vtotal_timing_profile_table))
|
|
|
194 Vtotal_timing_profile_table =
|
|
|
195 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQ);
|
|
|
196 if (NILP (Vcall_count_profile_table))
|
|
|
197 Vcall_count_profile_table =
|
|
|
198 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQ);
|
|
|
199 if (NILP (Vgc_usage_profile_table))
|
|
|
200 Vgc_usage_profile_table =
|
|
|
201 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQ);
|
|
|
202 if (NILP (Vtotal_gc_usage_profile_table))
|
|
|
203 Vtotal_gc_usage_profile_table =
|
|
|
204 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQ);
|
|
|
205 }
|
|
|
206
|
|
|
207 static Lisp_Object
|
|
|
208 current_profile_function (void)
|
|
|
209 {
|
|
|
210 Lisp_Object fun;
|
|
|
211 struct backtrace *bt = backtrace_list;
|
|
|
212
|
|
|
213 /* 2 because we set in_profiling when we entered the current routine. */
|
|
|
214 if (in_profiling >= 2)
|
|
|
215 return QSprofile_overhead;
|
|
|
216
|
|
|
217 /* Find a function actually being called. Potentially (?) there could be
|
|
|
218 a number of non-calling funs -- calling foo autoloads, which tries to
|
|
|
219 call bar, but requires evalling its args first, which calls baz, ...
|
|
|
220 If profiling was not enabled when the function was called, just treat
|
|
|
221 the function as actually called, because the info about whether we've
|
|
|
222 finished the preamble will not have been recorded. */
|
|
|
223 for (; bt && !bt->function_being_called; bt = bt->next)
|
|
|
224 ;
|
|
|
225
|
|
|
226 if (bt)
|
|
|
227 {
|
|
|
228 fun = *bt->function;
|
|
|
229
|
|
|
230 if (!SYMBOLP (fun)
|
|
|
231 && !COMPILED_FUNCTIONP (fun)
|
|
|
232 && !SUBRP (fun)
|
|
|
233 && !CONSP (fun)
|
|
|
234 && !STRINGP (fun))
|
|
|
235 fun = QSunknown;
|
|
|
236 }
|
|
|
237 else
|
|
|
238 fun = QSprocessing_events_at_top_level;
|
|
|
239 return fun;
|
|
|
240 }
|
|
|
241
|
|
|
242 void
|
|
|
243 profile_record_consing (EMACS_INT size)
|
|
|
244 {
|
|
|
245 Lisp_Object fun;
|
|
|
246 Lisp_Object count;
|
|
|
247
|
|
|
248 in_profiling++;
|
|
|
249 fun = current_profile_function ();
|
|
|
250 count = Fgethash (fun, Vgc_usage_profile_table, Qzero);
|
|
|
251 Fputhash (fun, make_int (size + XINT (count)), Vgc_usage_profile_table);
|
|
|
252 in_profiling--;
|
|
|
253 }
|
|
|
254
|
|
|
255 void
|
|
|
256 profile_record_unconsing (EMACS_INT size)
|
|
|
257 {
|
|
|
258 /* If we don't want to record values less than 0, change this; but then
|
|
|
259 the totals won't be accurate. */
|
|
|
260 profile_record_consing (-size);
|
|
1123
|
261 }
|
|
|
262
|
|
1292
|
263 inline static void
|
|
|
264 profile_sow_backtrace (struct backtrace *bt)
|
|
428
|
265 {
|
|
1292
|
266 bt->current_total_timing_val =
|
|
|
267 XINT (Fgethash (*bt->function, Vtotal_timing_profile_table, Qzero));
|
|
|
268 bt->current_total_gc_usage_val =
|
|
|
269 XINT (Fgethash (*bt->function, Vtotal_gc_usage_profile_table, Qzero));
|
|
|
270 bt->function_being_called = 1;
|
|
|
271 /* Need to think carefully about the exact order of operations here
|
|
|
272 so that we don't end up with totals being less than function-only
|
|
|
273 values; */
|
|
|
274 bt->total_consing_at_start = total_consing;
|
|
|
275 /* Order of operation is tricky here because we want the total function
|
|
|
276 time to be as close as possible to (and absolutely not less than) the
|
|
|
277 function-only time. From the sigprof-handler's perspective, the
|
|
|
278 function is "entered" the moment we finish executing the
|
|
|
279 in_profiling-- statement below, and ends the moment we finish
|
|
|
280 executing the in_profiling++ statement in
|
|
|
281 profile_record_just_called(). By recording the tick value as close as
|
|
|
282 possible to the "in-function" window but not in it, we satisfy the
|
|
|
283 conditions just mentioned. */
|
|
|
284 bt->total_ticks_at_start = total_ticks;
|
|
|
285 }
|
|
428
|
286
|
|
1292
|
287 void
|
|
|
288 profile_record_about_to_call (struct backtrace *bt)
|
|
|
289 {
|
|
|
290 in_profiling++;
|
|
|
291 profiling_lock = 1;
|
|
|
292 /* See comments in create_timing_profile_table(). */
|
|
|
293 pregrow_hash_table_if_necessary (big_profile_table, EXTRA_BREATHING_ROOM);
|
|
|
294 profiling_lock = 0;
|
|
|
295 Fputhash (*bt->function,
|
|
|
296 make_int (1 + XINT (Fgethash (*bt->function,
|
|
|
297 Vcall_count_profile_table,
|
|
|
298 Qzero))),
|
|
|
299 Vcall_count_profile_table);
|
|
|
300 /* This may be set if the function was in its preamble at the time that
|
|
|
301 `start-profiling' was called. If so, we shouldn't reset the values
|
|
|
302 because we may get inconsistent results, since we have already started
|
|
|
303 recording ticks and consing for the function. */
|
|
|
304 if (!bt->function_being_called)
|
|
|
305 profile_sow_backtrace (bt);
|
|
|
306 in_profiling--;
|
|
|
307 }
|
|
428
|
308
|
|
1292
|
309 inline static void
|
|
|
310 profile_reap_backtrace (struct backtrace *bt)
|
|
|
311 {
|
|
|
312 EMACS_UINT ticks;
|
|
|
313 /* The following statement *MUST* come directly after the preceding one!
|
|
|
314 See the comment above. */
|
|
|
315 ticks = total_ticks;
|
|
|
316 /* We need to reset the "in-function" flag here. Otherwise the sigprof
|
|
|
317 handler will record more ticks for the function while the post-amble
|
|
|
318 is executing, and its value will be > our total value. */
|
|
|
319 bt->function_being_called = 0;
|
|
|
320 Fputhash (*bt->function,
|
|
|
321 /* This works even when the total_ticks value has overwrapped.
|
|
|
322 Same for total_consing below. */
|
|
|
323 make_int ((EMACS_INT) (ticks - bt->total_ticks_at_start)
|
|
|
324 + bt->current_total_timing_val),
|
|
|
325 Vtotal_timing_profile_table);
|
|
|
326 Fputhash (*bt->function,
|
|
|
327 make_int ((EMACS_INT)
|
|
|
328 (total_consing - bt->total_consing_at_start)
|
|
|
329 + bt->current_total_gc_usage_val),
|
|
|
330 Vtotal_gc_usage_profile_table);
|
|
|
331 }
|
|
|
332
|
|
|
333 void
|
|
|
334 profile_record_just_called (struct backtrace *bt)
|
|
|
335 {
|
|
|
336 in_profiling++;
|
|
|
337 profile_reap_backtrace (bt);
|
|
|
338 in_profiling--;
|
|
|
339 }
|
|
|
340
|
|
|
341 /* Called when unwinding the catch stack after a throw or signal, to
|
|
|
342 note that we are exiting the function. */
|
|
|
343 void
|
|
|
344 profile_record_unwind (struct backtrace *bt)
|
|
|
345 {
|
|
|
346 /* We may have thrown while still in a function's preamble. */
|
|
|
347 if (bt->function_being_called)
|
|
|
348 profile_record_just_called (bt);
|
|
428
|
349 }
|
|
|
350
|
|
|
351 static SIGTYPE
|
|
|
352 sigprof_handler (int signo)
|
|
|
353 {
|
|
1292
|
354 #ifdef WIN32_ANY
|
|
|
355 /* Windows unfortunately does not have any such thing as setitimer
|
|
|
356 (ITIMER_PROF, ...), which runs in process time. Everything is real
|
|
|
357 time. So to get slightly more reasonable results, ignore completely
|
|
|
358 the times when we're blocking. Same applies, of course, to Cygwin. */
|
|
|
359 if (mswindows_is_blocking)
|
|
|
360 return;
|
|
|
361 #endif
|
|
|
362
|
|
|
363 in_profiling++;
|
|
|
364 total_ticks++;
|
|
|
365
|
|
428
|
366 /* Don't do anything if we are shutting down, or are doing a maphash
|
|
|
367 or clrhash on the table. */
|
|
1292
|
368 if (!profiling_lock && !preparing_for_armageddon)
|
|
428
|
369 {
|
|
1292
|
370 Lisp_Object fun = current_profile_function ();
|
|
428
|
371
|
|
|
372 /* If something below causes an error to be signaled, we'll
|
|
|
373 not correctly reset this flag. But we'll be in worse shape
|
|
|
374 than that anyways, since we'll longjmp back to the last
|
|
|
375 condition case. */
|
|
1292
|
376 profiling_lock = 1;
|
|
428
|
377
|
|
|
378 {
|
|
|
379 long count;
|
|
442
|
380 const void *vval;
|
|
428
|
381
|
|
|
382 if (gethash (LISP_TO_VOID (fun), big_profile_table, &vval))
|
|
|
383 count = (long) vval;
|
|
|
384 else
|
|
|
385 count = 0;
|
|
|
386 count++;
|
|
442
|
387 vval = (const void *) count;
|
|
428
|
388 puthash (LISP_TO_VOID (fun), (void *) vval, big_profile_table);
|
|
|
389 }
|
|
|
390
|
|
1292
|
391 profiling_lock = 0;
|
|
428
|
392 }
|
|
1292
|
393 in_profiling--;
|
|
428
|
394 }
|
|
|
395
|
|
1292
|
396 DEFUN ("start-profiling", Fstart_profiling, 0, 1, "", /*
|
|
428
|
397 Start profiling, with profile queries every MICROSECS.
|
|
|
398 If MICROSECS is nil or omitted, the value of `default-profiling-interval'
|
|
|
399 is used.
|
|
|
400
|
|
1123
|
401 Information on function timings and call counts is currently recorded.
|
|
1292
|
402 You can retrieve the recorded profiling info using `get-profiling-info',
|
|
|
403 or the higher-level function `profile-results'.
|
|
428
|
404
|
|
|
405 Starting and stopping profiling does not clear the currently recorded
|
|
|
406 info. Thus you can start and stop as many times as you want and everything
|
|
1292
|
407 will be properly accumulated. (To clear, use `clear-profiling-info'.)
|
|
428
|
408 */
|
|
|
409 (microsecs))
|
|
|
410 {
|
|
|
411 /* This function can GC */
|
|
|
412 int msecs;
|
|
|
413 struct itimerval foo;
|
|
1292
|
414 int depth;
|
|
428
|
415
|
|
1292
|
416 if (profiling_active)
|
|
|
417 return Qnil;
|
|
|
418 depth = internal_bind_int (&in_profiling, 1 + in_profiling);
|
|
|
419
|
|
|
420 create_profile_tables ();
|
|
|
421 /* See comments at top of file and in create_timing_profile_table().
|
|
|
422 We ensure enough breathing room for all entries currently on the
|
|
|
423 stack. */
|
|
|
424 pregrow_hash_table_if_necessary (big_profile_table,
|
|
|
425 EXTRA_BREATHING_ROOM + lisp_eval_depth);
|
|
428
|
426
|
|
|
427 if (NILP (microsecs))
|
|
|
428 msecs = default_profiling_interval;
|
|
|
429 else
|
|
|
430 {
|
|
|
431 CHECK_NATNUM (microsecs);
|
|
|
432 msecs = XINT (microsecs);
|
|
|
433 }
|
|
|
434 if (msecs <= 0)
|
|
|
435 msecs = 1000;
|
|
|
436
|
|
613
|
437 set_timeout_signal (SIGPROF, sigprof_handler);
|
|
1292
|
438 {
|
|
|
439 struct backtrace *bt = backtrace_list;
|
|
|
440
|
|
|
441 /* When we begin profiling, pretend like we just entered all the
|
|
|
442 functions currently on the stack. When we stop profiling, do the
|
|
|
443 opposite. This ensures consistent values being recorded for both
|
|
|
444 function-only and total in such cases. */
|
|
|
445 for (; bt; bt = bt->next)
|
|
|
446 profile_sow_backtrace (bt);
|
|
|
447 }
|
|
|
448 profiling_active = 1;
|
|
|
449 profiling_lock = 0;
|
|
428
|
450 foo.it_value.tv_sec = 0;
|
|
|
451 foo.it_value.tv_usec = msecs;
|
|
|
452 EMACS_NORMALIZE_TIME (foo.it_value);
|
|
|
453 foo.it_interval = foo.it_value;
|
|
611
|
454 qxe_setitimer (ITIMER_PROF, &foo, 0);
|
|
1292
|
455 unbind_to (depth);
|
|
428
|
456 return Qnil;
|
|
|
457 }
|
|
|
458
|
|
1292
|
459 DEFUN ("stop-profiling", Fstop_profiling, 0, 0, "", /*
|
|
428
|
460 Stop profiling.
|
|
|
461 */
|
|
|
462 ())
|
|
|
463 {
|
|
|
464 /* This function does not GC */
|
|
|
465 struct itimerval foo;
|
|
|
466
|
|
1292
|
467 if (!profiling_active)
|
|
|
468 return Qnil;
|
|
|
469 in_profiling++;
|
|
428
|
470 foo.it_value.tv_sec = 0;
|
|
|
471 foo.it_value.tv_usec = 0;
|
|
|
472 foo.it_interval = foo.it_value;
|
|
611
|
473 qxe_setitimer (ITIMER_PROF, &foo, 0);
|
|
428
|
474 profiling_active = 0;
|
|
1292
|
475 {
|
|
|
476 struct backtrace *bt = backtrace_list;
|
|
|
477
|
|
|
478 for (; bt; bt = bt->next)
|
|
|
479 profile_reap_backtrace (bt);
|
|
|
480 }
|
|
613
|
481 set_timeout_signal (SIGPROF, fatal_error_signal);
|
|
1292
|
482 in_profiling--;
|
|
428
|
483 return Qnil;
|
|
|
484 }
|
|
|
485
|
|
1123
|
486 DEFUN ("clear-profiling-info", Fclear_profiling_info, 0, 0, "", /*
|
|
|
487 Clear out the recorded profiling info.
|
|
|
488 This clears both the internal timing information and the call counts in
|
|
|
489 `call-count-profile-table'.
|
|
|
490 */
|
|
|
491 ())
|
|
|
492 {
|
|
1292
|
493 in_profiling++;
|
|
1123
|
494 /* This function does not GC */
|
|
|
495 if (big_profile_table)
|
|
|
496 {
|
|
1292
|
497 profiling_lock = 1;
|
|
1123
|
498 clrhash (big_profile_table);
|
|
1292
|
499 profiling_lock = 0;
|
|
1123
|
500 }
|
|
1292
|
501 if (!NILP (Vtotal_timing_profile_table))
|
|
|
502 Fclrhash (Vtotal_timing_profile_table);
|
|
1123
|
503 if (!NILP (Vcall_count_profile_table))
|
|
|
504 Fclrhash (Vcall_count_profile_table);
|
|
1292
|
505 if (!NILP (Vgc_usage_profile_table))
|
|
|
506 Fclrhash (Vgc_usage_profile_table);
|
|
|
507 if (!NILP (Vtotal_gc_usage_profile_table))
|
|
|
508 Fclrhash (Vtotal_gc_usage_profile_table);
|
|
|
509 in_profiling--;
|
|
|
510
|
|
1123
|
511 return Qnil;
|
|
|
512 }
|
|
|
513
|
|
428
|
514 struct get_profiling_info_closure
|
|
|
515 {
|
|
1123
|
516 Lisp_Object timing;
|
|
428
|
517 };
|
|
|
518
|
|
|
519 static int
|
|
1123
|
520 get_profiling_info_timing_maphash (const void *void_key,
|
|
|
521 void *void_val,
|
|
|
522 void *void_closure)
|
|
428
|
523 {
|
|
|
524 /* This function does not GC */
|
|
|
525 Lisp_Object key;
|
|
|
526 struct get_profiling_info_closure *closure
|
|
|
527 = (struct get_profiling_info_closure *) void_closure;
|
|
|
528 EMACS_INT val;
|
|
|
529
|
|
826
|
530 key = VOID_TO_LISP (void_key);
|
|
428
|
531 val = (EMACS_INT) void_val;
|
|
|
532
|
|
1123
|
533 Fputhash (key, make_int (val), closure->timing);
|
|
428
|
534 return 0;
|
|
|
535 }
|
|
|
536
|
|
1292
|
537 static Lisp_Object
|
|
|
538 copy_hash_table_or_blank (Lisp_Object table)
|
|
|
539 {
|
|
|
540 return !NILP (table) ? Fcopy_hash_table (table) :
|
|
|
541 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK,
|
|
|
542 HASH_TABLE_EQ);
|
|
|
543 }
|
|
|
544
|
|
428
|
545 DEFUN ("get-profiling-info", Fget_profiling_info, 0, 0, 0, /*
|
|
1123
|
546 Return the currently recorded profiling info.
|
|
|
547 The format is a plist of symbols describing type of info recorded and
|
|
|
548 an associated type-specific entry. Currently, the following info types
|
|
|
549 are recorded
|
|
|
550
|
|
|
551 `timing'
|
|
1292
|
552 A hash table of function descriptions (funcallable objects or strings
|
|
|
553 describing internal processing operations -- redisplay, garbage
|
|
|
554 collection, etc.), along with associated tick counts (the frequency of
|
|
|
555 ticks is controlled by `default-profiling-interval' or the argument to
|
|
|
556 `start-profiling').
|
|
|
557
|
|
|
558 `total-timing'
|
|
|
559 A hash table of function descriptions and associated timing count for
|
|
|
560 the function and all descendants.
|
|
1123
|
561
|
|
|
562 `call-count'
|
|
1292
|
563 A hash table of function descriptions and associated call counts.
|
|
|
564
|
|
|
565 `gc-usage'
|
|
|
566 A hash table of function descriptions and associated amount of consing.
|
|
|
567
|
|
|
568 `total-gc-usage'
|
|
|
569 A hash table of function descriptions and associated amount of consing
|
|
|
570 in the function and all descendants.
|
|
428
|
571 */
|
|
|
572 ())
|
|
|
573 {
|
|
|
574 /* This function does not GC */
|
|
|
575 struct get_profiling_info_closure closure;
|
|
1292
|
576 Lisp_Object retv;
|
|
|
577 int depth = internal_bind_int (&in_profiling, 1 + in_profiling);
|
|
|
578 const void *overhead;
|
|
428
|
579
|
|
1123
|
580 closure.timing =
|
|
|
581 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, HASH_TABLE_EQUAL);
|
|
|
582
|
|
428
|
583 if (big_profile_table)
|
|
|
584 {
|
|
1292
|
585 int count = internal_bind_int ((int *) &profiling_lock, 1);
|
|
1123
|
586 maphash (get_profiling_info_timing_maphash, big_profile_table, &closure);
|
|
1292
|
587
|
|
|
588 /* OK, OK ... the total-timing table is not going to have an entry
|
|
|
589 for profile overhead, and it looks strange for it to come out 0,
|
|
|
590 so make sure it looks reasonable. */
|
|
|
591 if (!gethash (LISP_TO_VOID (QSprofile_overhead), big_profile_table,
|
|
|
592 &overhead))
|
|
|
593 overhead = 0;
|
|
|
594 Fputhash (QSprofile_overhead, make_int ((EMACS_INT) overhead),
|
|
|
595 Vtotal_timing_profile_table);
|
|
|
596
|
|
771
|
597 unbind_to (count);
|
|
428
|
598 }
|
|
1123
|
599
|
|
1292
|
600 retv = nconc2 (list6 (Qtiming, closure.timing, Qtotal_timing,
|
|
|
601 copy_hash_table_or_blank (Vtotal_timing_profile_table),
|
|
|
602 Qcall_count,
|
|
|
603 copy_hash_table_or_blank (Vcall_count_profile_table)),
|
|
|
604 list4 (Qgc_usage,
|
|
|
605 copy_hash_table_or_blank (Vgc_usage_profile_table),
|
|
|
606 Qtotal_gc_usage,
|
|
|
607 copy_hash_table_or_blank (Vtotal_gc_usage_profile_table
|
|
|
608 )));
|
|
|
609 unbind_to (depth);
|
|
|
610 return retv;
|
|
1123
|
611 }
|
|
|
612
|
|
|
613 static int
|
|
|
614 set_profiling_info_timing_maphash (Lisp_Object key,
|
|
|
615 Lisp_Object val,
|
|
|
616 void *void_closure)
|
|
|
617 {
|
|
|
618 /* This function does not GC */
|
|
|
619 if (!INTP (val))
|
|
|
620 invalid_argument_2
|
|
|
621 ("Function timing count is not an integer in given entry",
|
|
|
622 key, val);
|
|
|
623
|
|
|
624 puthash (LISP_TO_VOID (key), (void *) XINT (val), big_profile_table);
|
|
|
625
|
|
|
626 return 0;
|
|
|
627 }
|
|
|
628
|
|
|
629 DEFUN ("set-profiling-info", Fset_profiling_info, 1, 1, 0, /*
|
|
|
630 Set the currently recorded profiling info.
|
|
|
631 INFO should be in the same format returned by `get-profiling-info',
|
|
|
632 as described there.
|
|
|
633 */
|
|
|
634 (info))
|
|
|
635 {
|
|
1292
|
636 int depth;
|
|
1123
|
637 /* This function does not GC */
|
|
|
638 Fclear_profiling_info ();
|
|
|
639
|
|
1292
|
640 depth = internal_bind_int (&in_profiling, 1 + in_profiling);
|
|
1123
|
641 {
|
|
|
642 EXTERNAL_PROPERTY_LIST_LOOP_3 (key, value, info)
|
|
|
643 {
|
|
|
644 if (EQ (key, Qtiming))
|
|
|
645 {
|
|
|
646 CHECK_HASH_TABLE (value);
|
|
|
647 create_timing_profile_table ();
|
|
1292
|
648 profiling_lock = 1;
|
|
1123
|
649 elisp_maphash_unsafe (set_profiling_info_timing_maphash, value,
|
|
|
650 NULL);
|
|
1292
|
651 profiling_lock = 0;
|
|
1123
|
652 }
|
|
|
653 else if (EQ (key, Qcall_count))
|
|
1292
|
654 Vcall_count_profile_table = Fcopy_hash_table (value);
|
|
|
655 else if (EQ (key, Qtotal_timing))
|
|
|
656 Vtotal_timing_profile_table = Fcopy_hash_table (value);
|
|
|
657 else if (EQ (key, Qgc_usage))
|
|
|
658 Vgc_usage_profile_table = Fcopy_hash_table (value);
|
|
|
659 else if (EQ (key, Qtotal_gc_usage))
|
|
|
660 Vtotal_gc_usage_profile_table = Fcopy_hash_table (value);
|
|
1123
|
661 else
|
|
|
662 invalid_constant ("Unrecognized profiling-info keyword", key);
|
|
|
663 }
|
|
|
664 }
|
|
|
665
|
|
1292
|
666 unbind_to (depth);
|
|
1123
|
667 return Qnil;
|
|
428
|
668 }
|
|
|
669
|
|
|
670 static int
|
|
442
|
671 mark_profiling_info_maphash (const void *void_key,
|
|
428
|
672 void *void_val,
|
|
|
673 void *void_closure)
|
|
|
674 {
|
|
1598
|
675 #ifdef USE_KKCC
|
|
|
676 kkcc_gc_stack_push_lisp_object (VOID_TO_LISP (void_key));
|
|
|
677 #else /* NOT USE_KKCC */
|
|
1292
|
678 mark_object (VOID_TO_LISP (void_key));
|
|
1598
|
679 #endif /* NOT USE_KKCC */
|
|
428
|
680 return 0;
|
|
|
681 }
|
|
|
682
|
|
|
683 void
|
|
|
684 mark_profiling_info (void)
|
|
|
685 {
|
|
|
686 /* This function does not GC */
|
|
|
687 if (big_profile_table)
|
|
|
688 {
|
|
1292
|
689 profiling_lock = 1;
|
|
428
|
690 maphash (mark_profiling_info_maphash, big_profile_table, 0);
|
|
1292
|
691 profiling_lock = 0;
|
|
428
|
692 }
|
|
|
693 }
|
|
|
694
|
|
|
695 DEFUN ("profiling-active-p", Fprofiling_active_p, 0, 0, 0, /*
|
|
|
696 Return non-nil if profiling information is currently being recorded.
|
|
|
697 */
|
|
|
698 ())
|
|
|
699 {
|
|
|
700 return profiling_active ? Qt : Qnil;
|
|
|
701 }
|
|
|
702
|
|
|
703 void
|
|
|
704 syms_of_profile (void)
|
|
|
705 {
|
|
|
706 DEFSUBR (Fstart_profiling);
|
|
|
707 DEFSUBR (Fstop_profiling);
|
|
|
708 DEFSUBR (Fget_profiling_info);
|
|
1123
|
709 DEFSUBR (Fset_profiling_info);
|
|
428
|
710 DEFSUBR (Fclear_profiling_info);
|
|
|
711 DEFSUBR (Fprofiling_active_p);
|
|
|
712 }
|
|
|
713
|
|
|
714 void
|
|
|
715 vars_of_profile (void)
|
|
|
716 {
|
|
|
717 DEFVAR_INT ("default-profiling-interval", &default_profiling_interval /*
|
|
|
718 Default CPU time in microseconds between profiling sampling.
|
|
|
719 Used when the argument to `start-profiling' is nil or omitted.
|
|
1346
|
720 Under Unix, the time in question is CPU time (when the program is executing
|
|
|
721 or the kernel is executing on behalf of the program) and not real time.
|
|
|
722 Under MS Windows and Cygwin, the time is real time, but time spent blocking
|
|
|
723 while waiting for an event is ignored, to get more accurate results.
|
|
|
724 Note that there is usually a machine-dependent limit on how small this
|
|
|
725 value can be.
|
|
428
|
726 */ );
|
|
|
727 default_profiling_interval = 1000;
|
|
|
728
|
|
1123
|
729 staticpro (&Vcall_count_profile_table);
|
|
428
|
730 Vcall_count_profile_table = Qnil;
|
|
|
731
|
|
1292
|
732 staticpro (&Vgc_usage_profile_table);
|
|
|
733 Vgc_usage_profile_table = Qnil;
|
|
|
734
|
|
|
735 staticpro (&Vtotal_gc_usage_profile_table);
|
|
|
736 Vtotal_gc_usage_profile_table = Qnil;
|
|
|
737
|
|
|
738 staticpro (&Vtotal_timing_profile_table);
|
|
|
739 Vtotal_timing_profile_table = Qnil;
|
|
428
|
740
|
|
1292
|
741 #if 0
|
|
|
742 /* #### This is supposed to be for KKCC but KKCC doesn't use this stuff
|
|
|
743 currently. */
|
|
|
744 dump_add_root_struct_ptr (&big_profile_table, &plain_hash_table_description);
|
|
|
745 #endif /* 0 */
|
|
|
746
|
|
|
747 profiling_lock = 0;
|
|
|
748
|
|
771
|
749 QSunknown = build_msg_string ("(unknown)");
|
|
428
|
750 staticpro (&QSunknown);
|
|
|
751 QSprocessing_events_at_top_level =
|
|
771
|
752 build_msg_string ("(processing events at top level)");
|
|
428
|
753 staticpro (&QSprocessing_events_at_top_level);
|
|
1292
|
754 QSprofile_overhead = build_msg_string ("(profile overhead)");
|
|
|
755 staticpro (&QSprofile_overhead);
|
|
1123
|
756
|
|
|
757 DEFSYMBOL (Qtiming);
|
|
1292
|
758 DEFSYMBOL (Qtotal_timing);
|
|
1123
|
759 DEFSYMBOL (Qcall_count);
|
|
1292
|
760 DEFSYMBOL (Qgc_usage);
|
|
|
761 DEFSYMBOL (Qtotal_gc_usage);
|
|
428
|
762 }
|
