Mercurial > hg > xemacs-beta
annotate src/profile.c @ 5345:db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
2011-01-23 Aidan Kehoe <kehoea@parhasard.net>
* file-coding.c (complex_vars_of_file_coding):
* intl-win32.c (complex_vars_of_intl_win32):
* profile.c (Fget_profiling_info):
* unicode.c (complex_vars_of_unicode):
Replace various awkward calls to nconc2 () with list6 () with
analogous calls to Ben's relatively-recently introduced listu (),
constructing a list from an arbitrary number of C arguments.
| author | Aidan Kehoe <kehoea@parhasard.net> |
|---|---|
| date | Sun, 23 Jan 2011 12:47:02 +0000 |
| parents | c096d8051f89 |
| children | 0af042a0c116 |
| rev | line source |
|---|---|
| 428 | 1 /* Why the hell is XEmacs so fucking slow? |
|
5169
6c6d78781d59
cleanup of code related to xfree(), better KKCC backtrace capabilities, document XD_INLINE_LISP_OBJECT_BLOCK_PTR, fix some memory leaks, other code cleanup
Ben Wing <ben@xemacs.org>
parents:
5038
diff
changeset
|
2 Copyright (C) 1996, 2002, 2003, 2004, 2010 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" | |
|
5169
6c6d78781d59
cleanup of code related to xfree(), better KKCC backtrace capabilities, document XD_INLINE_LISP_OBJECT_BLOCK_PTR, fix some memory leaks, other code cleanup
Ben Wing <ben@xemacs.org>
parents:
5038
diff
changeset
|
28 #include "gc.h" |
| 428 | 29 #include "hash.h" |
| 1315 | 30 #include "profile.h" |
| 428 | 31 |
| 32 #include "syssignal.h" | |
| 33 #include "systime.h" | |
| 34 | |
| 611 | 35 #ifndef HAVE_SETITIMER |
| 36 #error Sorry charlie. We need a scalpel and all we have is a lawnmower. | |
| 37 #endif | |
| 38 | |
| 1292 | 39 #ifdef WIN32_ANY |
| 40 int mswindows_is_blocking; | |
| 41 #endif | |
| 42 | |
| 2367 | 43 /* Written by Ben Wing. */ |
| 428 | 44 |
| 2367 | 45 /* |
| 428 | 46 |
| 2367 | 47 Documented in |
| 428 | 48 |
| 2367 | 49 (Info-goto-node "(internals)Profiling") |
| 1292 | 50 */ |
| 51 | |
| 52 /* We use a plain table here because we're recording inside of a signal | |
| 53 handler. */ | |
| 428 | 54 static struct hash_table *big_profile_table; |
| 1292 | 55 Lisp_Object Vtotal_timing_profile_table; |
| 428 | 56 Lisp_Object Vcall_count_profile_table; |
| 1292 | 57 Lisp_Object Vtotal_gc_usage_profile_table; |
| 58 Lisp_Object Vgc_usage_profile_table; | |
| 59 | |
| 60 extern int lisp_eval_depth; | |
| 61 | |
| 62 extern EMACS_UINT total_consing; | |
| 63 static volatile EMACS_UINT total_ticks; | |
| 428 | 64 |
| 458 | 65 Fixnum default_profiling_interval; |
| 428 | 66 |
| 67 int profiling_active; | |
| 68 | |
| 1292 | 69 static Lisp_Object QSprocessing_events_at_top_level; |
| 70 static Lisp_Object QSunknown, QSprofile_overhead; | |
| 71 | |
| 2514 | 72 #ifdef DEBUG_XEMACS |
| 73 /* For temporary profiling */ | |
| 74 Lisp_Object QSin_temp_spot_1; | |
| 75 Lisp_Object QSin_temp_spot_2; | |
| 76 Lisp_Object QSin_temp_spot_3; | |
| 77 Lisp_Object QSin_temp_spot_4; | |
| 78 Lisp_Object QSin_temp_spot_5; | |
| 79 #endif /* DEBUG_XEMACS */ | |
| 80 | |
| 1292 | 81 static Lisp_Object Qtiming, Qtotal_timing, Qcall_count; |
| 82 static Lisp_Object Qgc_usage, Qtotal_gc_usage; | |
| 83 | |
| 84 /* This needs to be >= the total number of defined internal sections, | |
| 85 plus 1 or 2?? Set it extra big just to be ultra-paranoid. */ | |
| 86 #define EXTRA_BREATHING_ROOM 100 | |
| 428 | 87 |
| 1292 | 88 /* We use profiling_lock to prevent the signal handler from writing to |
| 89 the table while another routine is operating on it. We also set | |
| 90 profiling_lock in case the timeout between signal calls is short | |
| 91 enough to catch us while we're already in there. */ | |
| 92 static volatile int profiling_lock; | |
| 428 | 93 |
| 1292 | 94 /* Whether we're in the process of doing *any* profiling-related stuff. |
| 95 Used to indicate amount of time spent profiling. */ | |
| 96 static int in_profiling; | |
| 97 | |
| 98 #if 0 /* #### for KKCC, eventually */ | |
| 1123 | 99 |
| 1292 | 100 static const struct memory_description hentry_description_1[] = { |
| 101 { XD_LISP_OBJECT, offsetof (hentry, key) }, | |
| 102 { XD_END } | |
| 103 }; | |
| 104 | |
| 105 static const struct sized_memory_description hentry_description = { | |
| 106 sizeof (hentry), | |
| 107 hentry_description_1 | |
| 108 }; | |
| 428 | 109 |
| 1292 | 110 static const struct memory_description plain_hash_table_description_1[] = { |
| 111 { XD_ELEMCOUNT, offsetof (struct hash_table, size) }, | |
| 2367 | 112 { XD_BLOCK_PTR, offsetof (struct hash_table, harray), XD_INDIRECT (0, 0), |
| 2551 | 113 { &hentry_description } }, |
| 1292 | 114 { XD_END } |
| 115 }; | |
| 116 | |
| 117 static const struct sized_memory_description plain_hash_table_description = { | |
| 118 sizeof (struct hash_table), | |
| 119 plain_hash_table_description_1 | |
| 120 }; | |
| 121 | |
| 122 #endif /* 0 */ | |
| 1123 | 123 |
| 124 static void | |
| 125 create_timing_profile_table (void) | |
| 126 { | |
| 1292 | 127 /* The hash code can safely be called from a signal handler except when |
| 128 it has to grow the hash table. In this case, it calls realloc(), | |
| 5038 | 129 which is not (in general) reentrant. The way we deal with this is |
| 1292 | 130 documented at the top of this file. */ |
| 1123 | 131 if (!big_profile_table) |
| 1292 | 132 big_profile_table = make_hash_table (2000); |
| 133 } | |
| 134 | |
| 135 static void | |
| 136 create_profile_tables (void) | |
| 137 { | |
| 138 create_timing_profile_table (); | |
| 139 if (NILP (Vtotal_timing_profile_table)) | |
| 140 Vtotal_timing_profile_table = | |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
141 make_lisp_hash_table (1000, HASH_TABLE_NON_WEAK, Qeq); |
| 1292 | 142 if (NILP (Vcall_count_profile_table)) |
| 143 Vcall_count_profile_table = | |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
144 make_lisp_hash_table (1000, HASH_TABLE_NON_WEAK, Qeq); |
| 1292 | 145 if (NILP (Vgc_usage_profile_table)) |
| 146 Vgc_usage_profile_table = | |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
147 make_lisp_hash_table (1000, HASH_TABLE_NON_WEAK, Qeq); |
| 1292 | 148 if (NILP (Vtotal_gc_usage_profile_table)) |
| 149 Vtotal_gc_usage_profile_table = | |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
150 make_lisp_hash_table (1000, HASH_TABLE_NON_WEAK, Qeq); |
| 1292 | 151 } |
| 152 | |
| 153 static Lisp_Object | |
| 154 current_profile_function (void) | |
| 155 { | |
| 156 Lisp_Object fun; | |
| 157 struct backtrace *bt = backtrace_list; | |
| 158 | |
| 159 /* 2 because we set in_profiling when we entered the current routine. */ | |
| 160 if (in_profiling >= 2) | |
| 161 return QSprofile_overhead; | |
| 162 | |
| 163 /* Find a function actually being called. Potentially (?) there could be | |
| 164 a number of non-calling funs -- calling foo autoloads, which tries to | |
| 165 call bar, but requires evalling its args first, which calls baz, ... | |
| 166 If profiling was not enabled when the function was called, just treat | |
| 167 the function as actually called, because the info about whether we've | |
| 168 finished the preamble will not have been recorded. */ | |
| 169 for (; bt && !bt->function_being_called; bt = bt->next) | |
| 170 ; | |
| 171 | |
| 172 if (bt) | |
| 173 { | |
| 174 fun = *bt->function; | |
| 175 | |
| 176 if (!SYMBOLP (fun) | |
| 177 && !COMPILED_FUNCTIONP (fun) | |
| 178 && !SUBRP (fun) | |
| 179 && !CONSP (fun) | |
| 180 && !STRINGP (fun)) | |
| 181 fun = QSunknown; | |
| 182 } | |
| 183 else | |
| 184 fun = QSprocessing_events_at_top_level; | |
| 185 return fun; | |
| 186 } | |
| 187 | |
| 188 void | |
| 189 profile_record_consing (EMACS_INT size) | |
| 190 { | |
| 191 in_profiling++; | |
| 2421 | 192 inchash_eq (current_profile_function (), Vgc_usage_profile_table, size); |
| 1292 | 193 in_profiling--; |
| 194 } | |
| 195 | |
| 196 void | |
| 197 profile_record_unconsing (EMACS_INT size) | |
| 198 { | |
| 199 /* If we don't want to record values less than 0, change this; but then | |
| 200 the totals won't be accurate. */ | |
| 201 profile_record_consing (-size); | |
| 1123 | 202 } |
| 203 | |
| 1292 | 204 inline static void |
| 205 profile_sow_backtrace (struct backtrace *bt) | |
| 428 | 206 { |
| 1292 | 207 bt->current_total_timing_val = |
| 208 XINT (Fgethash (*bt->function, Vtotal_timing_profile_table, Qzero)); | |
| 209 bt->current_total_gc_usage_val = | |
| 210 XINT (Fgethash (*bt->function, Vtotal_gc_usage_profile_table, Qzero)); | |
| 211 bt->function_being_called = 1; | |
| 212 /* Need to think carefully about the exact order of operations here | |
| 213 so that we don't end up with totals being less than function-only | |
| 214 values; */ | |
| 215 bt->total_consing_at_start = total_consing; | |
| 216 /* Order of operation is tricky here because we want the total function | |
| 217 time to be as close as possible to (and absolutely not less than) the | |
| 218 function-only time. From the sigprof-handler's perspective, the | |
| 219 function is "entered" the moment we finish executing the | |
| 220 in_profiling-- statement below, and ends the moment we finish | |
| 221 executing the in_profiling++ statement in | |
| 222 profile_record_just_called(). By recording the tick value as close as | |
| 223 possible to the "in-function" window but not in it, we satisfy the | |
| 224 conditions just mentioned. */ | |
| 225 bt->total_ticks_at_start = total_ticks; | |
| 226 } | |
| 428 | 227 |
| 1292 | 228 void |
| 229 profile_record_about_to_call (struct backtrace *bt) | |
| 230 { | |
| 231 in_profiling++; | |
| 232 profiling_lock = 1; | |
| 233 /* See comments in create_timing_profile_table(). */ | |
| 234 pregrow_hash_table_if_necessary (big_profile_table, EXTRA_BREATHING_ROOM); | |
| 235 profiling_lock = 0; | |
| 2421 | 236 inchash_eq (*bt->function, Vcall_count_profile_table, 1); |
| 1292 | 237 /* This may be set if the function was in its preamble at the time that |
| 238 `start-profiling' was called. If so, we shouldn't reset the values | |
| 239 because we may get inconsistent results, since we have already started | |
| 240 recording ticks and consing for the function. */ | |
| 241 if (!bt->function_being_called) | |
| 242 profile_sow_backtrace (bt); | |
| 243 in_profiling--; | |
| 244 } | |
| 428 | 245 |
| 1292 | 246 inline static void |
| 247 profile_reap_backtrace (struct backtrace *bt) | |
| 248 { | |
| 249 EMACS_UINT ticks; | |
| 250 /* The following statement *MUST* come directly after the preceding one! | |
| 251 See the comment above. */ | |
| 252 ticks = total_ticks; | |
| 253 /* We need to reset the "in-function" flag here. Otherwise the sigprof | |
| 254 handler will record more ticks for the function while the post-amble | |
| 255 is executing, and its value will be > our total value. */ | |
| 256 bt->function_being_called = 0; | |
| 257 Fputhash (*bt->function, | |
| 258 /* This works even when the total_ticks value has overwrapped. | |
| 259 Same for total_consing below. */ | |
| 260 make_int ((EMACS_INT) (ticks - bt->total_ticks_at_start) | |
| 261 + bt->current_total_timing_val), | |
| 262 Vtotal_timing_profile_table); | |
| 263 Fputhash (*bt->function, | |
| 264 make_int ((EMACS_INT) | |
| 265 (total_consing - bt->total_consing_at_start) | |
| 266 + bt->current_total_gc_usage_val), | |
| 267 Vtotal_gc_usage_profile_table); | |
| 268 } | |
| 269 | |
| 270 void | |
| 271 profile_record_just_called (struct backtrace *bt) | |
| 272 { | |
| 273 in_profiling++; | |
| 274 profile_reap_backtrace (bt); | |
| 275 in_profiling--; | |
| 276 } | |
| 277 | |
| 278 /* Called when unwinding the catch stack after a throw or signal, to | |
| 279 note that we are exiting the function. */ | |
| 280 void | |
| 281 profile_record_unwind (struct backtrace *bt) | |
| 282 { | |
| 283 /* We may have thrown while still in a function's preamble. */ | |
| 284 if (bt->function_being_called) | |
| 285 profile_record_just_called (bt); | |
| 428 | 286 } |
| 287 | |
| 288 static SIGTYPE | |
| 2286 | 289 sigprof_handler (int UNUSED (signo)) |
| 428 | 290 { |
| 1292 | 291 #ifdef WIN32_ANY |
| 292 /* Windows unfortunately does not have any such thing as setitimer | |
| 293 (ITIMER_PROF, ...), which runs in process time. Everything is real | |
| 294 time. So to get slightly more reasonable results, ignore completely | |
| 295 the times when we're blocking. Same applies, of course, to Cygwin. */ | |
| 296 if (mswindows_is_blocking) | |
| 297 return; | |
| 298 #endif | |
| 299 | |
| 300 in_profiling++; | |
| 301 total_ticks++; | |
| 302 | |
| 428 | 303 /* Don't do anything if we are shutting down, or are doing a maphash |
| 304 or clrhash on the table. */ | |
| 1292 | 305 if (!profiling_lock && !preparing_for_armageddon) |
| 428 | 306 { |
| 1292 | 307 Lisp_Object fun = current_profile_function (); |
| 428 | 308 |
| 309 /* If something below causes an error to be signaled, we'll | |
| 310 not correctly reset this flag. But we'll be in worse shape | |
| 311 than that anyways, since we'll longjmp back to the last | |
| 312 condition case. */ | |
| 1292 | 313 profiling_lock = 1; |
| 428 | 314 |
| 315 { | |
| 316 long count; | |
| 442 | 317 const void *vval; |
| 428 | 318 |
| 5013 | 319 if (gethash (STORE_LISP_IN_VOID (fun), big_profile_table, &vval)) |
| 428 | 320 count = (long) vval; |
| 321 else | |
| 322 count = 0; | |
| 323 count++; | |
| 442 | 324 vval = (const void *) count; |
| 5013 | 325 puthash (STORE_LISP_IN_VOID (fun), (void *) vval, big_profile_table); |
| 428 | 326 } |
| 327 | |
| 1292 | 328 profiling_lock = 0; |
| 428 | 329 } |
| 1292 | 330 in_profiling--; |
| 428 | 331 } |
| 332 | |
| 1292 | 333 DEFUN ("start-profiling", Fstart_profiling, 0, 1, "", /* |
| 428 | 334 Start profiling, with profile queries every MICROSECS. |
| 335 If MICROSECS is nil or omitted, the value of `default-profiling-interval' | |
| 336 is used. | |
| 337 | |
| 1123 | 338 Information on function timings and call counts is currently recorded. |
| 1292 | 339 You can retrieve the recorded profiling info using `get-profiling-info', |
| 340 or the higher-level function `profile-results'. | |
| 428 | 341 |
| 342 Starting and stopping profiling does not clear the currently recorded | |
| 343 info. Thus you can start and stop as many times as you want and everything | |
| 1292 | 344 will be properly accumulated. (To clear, use `clear-profiling-info'.) |
| 428 | 345 */ |
| 346 (microsecs)) | |
| 347 { | |
| 348 /* This function can GC */ | |
| 349 int msecs; | |
| 350 struct itimerval foo; | |
| 1292 | 351 int depth; |
| 428 | 352 |
| 1292 | 353 if (profiling_active) |
| 354 return Qnil; | |
| 355 depth = internal_bind_int (&in_profiling, 1 + in_profiling); | |
| 356 | |
| 357 create_profile_tables (); | |
| 358 /* See comments at top of file and in create_timing_profile_table(). | |
| 359 We ensure enough breathing room for all entries currently on the | |
| 360 stack. */ | |
| 361 pregrow_hash_table_if_necessary (big_profile_table, | |
| 362 EXTRA_BREATHING_ROOM + lisp_eval_depth); | |
| 428 | 363 |
| 364 if (NILP (microsecs)) | |
| 365 msecs = default_profiling_interval; | |
| 366 else | |
| 367 { | |
|
5307
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
368 #ifdef HAVE_BIGNUM |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
369 check_integer_range (microsecs, make_int (1000), make_integer (INT_MAX)); |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
370 msecs = |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
371 BIGNUMP (microsecs) ? bignum_to_int (XBIGNUM_DATA (microsecs)) : |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
372 XINT (microsecs); |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
373 #else |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
374 check_integer_range (microsecs, make_int (1000), |
|
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
375 make_integer (EMACS_INT_MAX)); |
| 428 | 376 msecs = XINT (microsecs); |
|
5307
c096d8051f89
Have NATNUMP give t for positive bignums; check limits appropriately.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5191
diff
changeset
|
377 #endif |
| 428 | 378 } |
| 379 if (msecs <= 0) | |
| 380 msecs = 1000; | |
| 381 | |
| 613 | 382 set_timeout_signal (SIGPROF, sigprof_handler); |
| 1292 | 383 { |
| 384 struct backtrace *bt = backtrace_list; | |
| 385 | |
| 386 /* When we begin profiling, pretend like we just entered all the | |
| 387 functions currently on the stack. When we stop profiling, do the | |
| 388 opposite. This ensures consistent values being recorded for both | |
| 389 function-only and total in such cases. */ | |
| 390 for (; bt; bt = bt->next) | |
| 391 profile_sow_backtrace (bt); | |
| 392 } | |
| 393 profiling_active = 1; | |
| 394 profiling_lock = 0; | |
| 428 | 395 foo.it_value.tv_sec = 0; |
| 396 foo.it_value.tv_usec = msecs; | |
| 397 EMACS_NORMALIZE_TIME (foo.it_value); | |
| 398 foo.it_interval = foo.it_value; | |
| 611 | 399 qxe_setitimer (ITIMER_PROF, &foo, 0); |
| 1292 | 400 unbind_to (depth); |
| 428 | 401 return Qnil; |
| 402 } | |
| 403 | |
| 1292 | 404 DEFUN ("stop-profiling", Fstop_profiling, 0, 0, "", /* |
| 428 | 405 Stop profiling. |
| 406 */ | |
| 407 ()) | |
| 408 { | |
| 409 /* This function does not GC */ | |
| 410 struct itimerval foo; | |
| 411 | |
| 1292 | 412 if (!profiling_active) |
| 413 return Qnil; | |
| 414 in_profiling++; | |
| 428 | 415 foo.it_value.tv_sec = 0; |
| 416 foo.it_value.tv_usec = 0; | |
| 417 foo.it_interval = foo.it_value; | |
| 611 | 418 qxe_setitimer (ITIMER_PROF, &foo, 0); |
| 428 | 419 profiling_active = 0; |
| 1292 | 420 { |
| 421 struct backtrace *bt = backtrace_list; | |
| 422 | |
| 423 for (; bt; bt = bt->next) | |
| 424 profile_reap_backtrace (bt); | |
| 425 } | |
| 613 | 426 set_timeout_signal (SIGPROF, fatal_error_signal); |
| 1292 | 427 in_profiling--; |
| 428 | 428 return Qnil; |
| 429 } | |
| 430 | |
| 1123 | 431 DEFUN ("clear-profiling-info", Fclear_profiling_info, 0, 0, "", /* |
| 432 Clear out the recorded profiling info. | |
| 433 This clears both the internal timing information and the call counts in | |
| 434 `call-count-profile-table'. | |
| 435 */ | |
| 436 ()) | |
| 437 { | |
| 1292 | 438 in_profiling++; |
| 1123 | 439 /* This function does not GC */ |
| 440 if (big_profile_table) | |
| 441 { | |
| 1292 | 442 profiling_lock = 1; |
| 1123 | 443 clrhash (big_profile_table); |
| 1292 | 444 profiling_lock = 0; |
| 1123 | 445 } |
| 1292 | 446 if (!NILP (Vtotal_timing_profile_table)) |
| 447 Fclrhash (Vtotal_timing_profile_table); | |
| 1123 | 448 if (!NILP (Vcall_count_profile_table)) |
| 449 Fclrhash (Vcall_count_profile_table); | |
| 1292 | 450 if (!NILP (Vgc_usage_profile_table)) |
| 451 Fclrhash (Vgc_usage_profile_table); | |
| 452 if (!NILP (Vtotal_gc_usage_profile_table)) | |
| 453 Fclrhash (Vtotal_gc_usage_profile_table); | |
| 454 in_profiling--; | |
| 455 | |
| 1123 | 456 return Qnil; |
| 457 } | |
| 458 | |
| 428 | 459 struct get_profiling_info_closure |
| 460 { | |
| 1123 | 461 Lisp_Object timing; |
| 428 | 462 }; |
| 463 | |
| 464 static int | |
| 1123 | 465 get_profiling_info_timing_maphash (const void *void_key, |
| 466 void *void_val, | |
| 467 void *void_closure) | |
| 428 | 468 { |
| 469 /* This function does not GC */ | |
| 470 Lisp_Object key; | |
| 471 struct get_profiling_info_closure *closure | |
| 472 = (struct get_profiling_info_closure *) void_closure; | |
| 473 EMACS_INT val; | |
| 474 | |
| 5013 | 475 key = GET_LISP_FROM_VOID (void_key); |
| 428 | 476 val = (EMACS_INT) void_val; |
| 477 | |
| 1123 | 478 Fputhash (key, make_int (val), closure->timing); |
| 428 | 479 return 0; |
| 480 } | |
| 481 | |
| 1292 | 482 static Lisp_Object |
| 483 copy_hash_table_or_blank (Lisp_Object table) | |
| 484 { | |
| 485 return !NILP (table) ? Fcopy_hash_table (table) : | |
| 486 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, | |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
487 Qeq); |
| 1292 | 488 } |
| 489 | |
| 428 | 490 DEFUN ("get-profiling-info", Fget_profiling_info, 0, 0, 0, /* |
| 1123 | 491 Return the currently recorded profiling info. |
| 492 The format is a plist of symbols describing type of info recorded and | |
| 493 an associated type-specific entry. Currently, the following info types | |
| 494 are recorded | |
| 495 | |
| 496 `timing' | |
| 1292 | 497 A hash table of function descriptions (funcallable objects or strings |
| 498 describing internal processing operations -- redisplay, garbage | |
| 499 collection, etc.), along with associated tick counts (the frequency of | |
| 500 ticks is controlled by `default-profiling-interval' or the argument to | |
| 501 `start-profiling'). | |
| 502 | |
| 503 `total-timing' | |
| 504 A hash table of function descriptions and associated timing count for | |
| 505 the function and all descendants. | |
| 1123 | 506 |
| 507 `call-count' | |
| 1292 | 508 A hash table of function descriptions and associated call counts. |
| 509 | |
| 510 `gc-usage' | |
| 511 A hash table of function descriptions and associated amount of consing. | |
| 512 | |
| 513 `total-gc-usage' | |
| 514 A hash table of function descriptions and associated amount of consing | |
| 515 in the function and all descendants. | |
| 428 | 516 */ |
| 517 ()) | |
| 518 { | |
| 519 /* This function does not GC */ | |
| 520 struct get_profiling_info_closure closure; | |
| 1292 | 521 Lisp_Object retv; |
| 522 int depth = internal_bind_int (&in_profiling, 1 + in_profiling); | |
| 523 const void *overhead; | |
| 428 | 524 |
| 1123 | 525 closure.timing = |
|
5191
71ee43b8a74d
Add #'equalp as a hash test by default; add #'define-hash-table-test, GNU API
Aidan Kehoe <kehoea@parhasard.net>
parents:
5169
diff
changeset
|
526 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, Qequal); |
| 1123 | 527 |
| 428 | 528 if (big_profile_table) |
| 529 { | |
| 1292 | 530 int count = internal_bind_int ((int *) &profiling_lock, 1); |
| 1123 | 531 maphash (get_profiling_info_timing_maphash, big_profile_table, &closure); |
| 1292 | 532 |
| 533 /* OK, OK ... the total-timing table is not going to have an entry | |
| 534 for profile overhead, and it looks strange for it to come out 0, | |
| 535 so make sure it looks reasonable. */ | |
| 5013 | 536 if (!gethash (STORE_LISP_IN_VOID (QSprofile_overhead), big_profile_table, |
| 1292 | 537 &overhead)) |
| 538 overhead = 0; | |
| 539 Fputhash (QSprofile_overhead, make_int ((EMACS_INT) overhead), | |
| 540 Vtotal_timing_profile_table); | |
| 541 | |
| 771 | 542 unbind_to (count); |
| 428 | 543 } |
| 1123 | 544 |
|
5345
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
545 retv = listu (Qtiming, closure.timing, |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
546 Qtotal_timing, |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
547 copy_hash_table_or_blank (Vtotal_timing_profile_table), |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
548 Qcall_count, |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
549 copy_hash_table_or_blank (Vcall_count_profile_table), |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
550 Qgc_usage, |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
551 copy_hash_table_or_blank (Vgc_usage_profile_table), |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
552 Qtotal_gc_usage, |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
553 copy_hash_table_or_blank (Vtotal_gc_usage_profile_table), |
|
db326b8fe982
Use Ben's recently-introduced listu (), where appropriate.
Aidan Kehoe <kehoea@parhasard.net>
parents:
5307
diff
changeset
|
554 Qunbound); |
| 1292 | 555 unbind_to (depth); |
| 556 return retv; | |
| 1123 | 557 } |
| 558 | |
| 559 static int | |
| 560 set_profiling_info_timing_maphash (Lisp_Object key, | |
| 561 Lisp_Object val, | |
| 2286 | 562 void *UNUSED (void_closure)) |
| 1123 | 563 { |
| 564 /* This function does not GC */ | |
| 565 if (!INTP (val)) | |
| 566 invalid_argument_2 | |
| 567 ("Function timing count is not an integer in given entry", | |
| 568 key, val); | |
| 569 | |
| 5013 | 570 puthash (STORE_LISP_IN_VOID (key), (void *) XINT (val), big_profile_table); |
| 1123 | 571 |
| 572 return 0; | |
| 573 } | |
| 574 | |
| 575 DEFUN ("set-profiling-info", Fset_profiling_info, 1, 1, 0, /* | |
| 576 Set the currently recorded profiling info. | |
| 577 INFO should be in the same format returned by `get-profiling-info', | |
| 578 as described there. | |
| 579 */ | |
| 580 (info)) | |
| 581 { | |
| 1292 | 582 int depth; |
| 1123 | 583 /* This function does not GC */ |
| 584 Fclear_profiling_info (); | |
| 585 | |
| 1292 | 586 depth = internal_bind_int (&in_profiling, 1 + in_profiling); |
| 1123 | 587 { |
| 588 EXTERNAL_PROPERTY_LIST_LOOP_3 (key, value, info) | |
| 589 { | |
| 590 if (EQ (key, Qtiming)) | |
| 591 { | |
| 592 CHECK_HASH_TABLE (value); | |
| 593 create_timing_profile_table (); | |
| 1292 | 594 profiling_lock = 1; |
| 1123 | 595 elisp_maphash_unsafe (set_profiling_info_timing_maphash, value, |
| 596 NULL); | |
| 1292 | 597 profiling_lock = 0; |
| 1123 | 598 } |
| 599 else if (EQ (key, Qcall_count)) | |
| 1292 | 600 Vcall_count_profile_table = Fcopy_hash_table (value); |
| 601 else if (EQ (key, Qtotal_timing)) | |
| 602 Vtotal_timing_profile_table = Fcopy_hash_table (value); | |
| 603 else if (EQ (key, Qgc_usage)) | |
| 604 Vgc_usage_profile_table = Fcopy_hash_table (value); | |
| 605 else if (EQ (key, Qtotal_gc_usage)) | |
| 606 Vtotal_gc_usage_profile_table = Fcopy_hash_table (value); | |
| 1123 | 607 else |
| 608 invalid_constant ("Unrecognized profiling-info keyword", key); | |
| 609 } | |
| 610 } | |
| 611 | |
| 1292 | 612 unbind_to (depth); |
| 1123 | 613 return Qnil; |
| 428 | 614 } |
| 615 | |
| 616 static int | |
| 442 | 617 mark_profiling_info_maphash (const void *void_key, |
| 2286 | 618 void *UNUSED (void_val), |
| 619 void *UNUSED (void_closure)) | |
| 428 | 620 { |
| 1598 | 621 #ifdef USE_KKCC |
|
5169
6c6d78781d59
cleanup of code related to xfree(), better KKCC backtrace capabilities, document XD_INLINE_LISP_OBJECT_BLOCK_PTR, fix some memory leaks, other code cleanup
Ben Wing <ben@xemacs.org>
parents:
5038
diff
changeset
|
622 kkcc_gc_stack_push_lisp_object_0 (GET_LISP_FROM_VOID (void_key)); |
| 1598 | 623 #else /* NOT USE_KKCC */ |
| 5013 | 624 mark_object (GET_LISP_FROM_VOID (void_key)); |
| 1598 | 625 #endif /* NOT USE_KKCC */ |
| 428 | 626 return 0; |
| 627 } | |
| 628 | |
| 629 void | |
| 630 mark_profiling_info (void) | |
| 631 { | |
| 632 /* This function does not GC */ | |
| 633 if (big_profile_table) | |
| 634 { | |
| 1292 | 635 profiling_lock = 1; |
| 428 | 636 maphash (mark_profiling_info_maphash, big_profile_table, 0); |
| 1292 | 637 profiling_lock = 0; |
| 428 | 638 } |
| 639 } | |
| 640 | |
| 641 DEFUN ("profiling-active-p", Fprofiling_active_p, 0, 0, 0, /* | |
| 642 Return non-nil if profiling information is currently being recorded. | |
| 643 */ | |
| 644 ()) | |
| 645 { | |
| 646 return profiling_active ? Qt : Qnil; | |
| 647 } | |
| 648 | |
| 649 void | |
| 650 syms_of_profile (void) | |
| 651 { | |
| 652 DEFSUBR (Fstart_profiling); | |
| 653 DEFSUBR (Fstop_profiling); | |
| 654 DEFSUBR (Fget_profiling_info); | |
| 1123 | 655 DEFSUBR (Fset_profiling_info); |
| 428 | 656 DEFSUBR (Fclear_profiling_info); |
| 657 DEFSUBR (Fprofiling_active_p); | |
| 658 } | |
| 659 | |
| 660 void | |
| 661 vars_of_profile (void) | |
| 662 { | |
| 663 DEFVAR_INT ("default-profiling-interval", &default_profiling_interval /* | |
| 664 Default CPU time in microseconds between profiling sampling. | |
| 665 Used when the argument to `start-profiling' is nil or omitted. | |
| 1346 | 666 Under Unix, the time in question is CPU time (when the program is executing |
| 667 or the kernel is executing on behalf of the program) and not real time. | |
| 668 Under MS Windows and Cygwin, the time is real time, but time spent blocking | |
| 669 while waiting for an event is ignored, to get more accurate results. | |
| 670 Note that there is usually a machine-dependent limit on how small this | |
| 671 value can be. | |
| 428 | 672 */ ); |
| 673 default_profiling_interval = 1000; | |
| 674 | |
| 1123 | 675 staticpro (&Vcall_count_profile_table); |
| 428 | 676 Vcall_count_profile_table = Qnil; |
| 677 | |
| 1292 | 678 staticpro (&Vgc_usage_profile_table); |
| 679 Vgc_usage_profile_table = Qnil; | |
| 680 | |
| 681 staticpro (&Vtotal_gc_usage_profile_table); | |
| 682 Vtotal_gc_usage_profile_table = Qnil; | |
| 683 | |
| 684 staticpro (&Vtotal_timing_profile_table); | |
| 685 Vtotal_timing_profile_table = Qnil; | |
| 428 | 686 |
| 1292 | 687 #if 0 |
| 688 /* #### This is supposed to be for KKCC but KKCC doesn't use this stuff | |
| 689 currently. */ | |
| 2367 | 690 dump_add_root_block_ptr (&big_profile_table, &plain_hash_table_description); |
| 1292 | 691 #endif /* 0 */ |
| 692 | |
| 693 profiling_lock = 0; | |
| 694 | |
| 2514 | 695 #ifdef DEBUG_XEMACS |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
696 QSin_temp_spot_1 = build_defer_string ("(in temp spot 1)"); |
| 2514 | 697 staticpro (&QSin_temp_spot_1); |
| 698 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
699 QSin_temp_spot_2 = build_defer_string ("(in temp spot 2)"); |
| 2514 | 700 staticpro (&QSin_temp_spot_2); |
| 701 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
702 QSin_temp_spot_3 = build_defer_string ("(in temp spot 3)"); |
| 2514 | 703 staticpro (&QSin_temp_spot_3); |
| 704 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
705 QSin_temp_spot_4 = build_defer_string ("(in temp spot 4)"); |
| 2514 | 706 staticpro (&QSin_temp_spot_4); |
| 707 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
708 QSin_temp_spot_5 = build_defer_string ("(in temp spot 5)"); |
| 2514 | 709 staticpro (&QSin_temp_spot_5); |
| 710 #endif /* DEBUG_XEMACS */ | |
| 711 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
712 QSunknown = build_defer_string ("(unknown)"); |
| 428 | 713 staticpro (&QSunknown); |
| 714 QSprocessing_events_at_top_level = | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
715 build_defer_string ("(processing events at top level)"); |
| 428 | 716 staticpro (&QSprocessing_events_at_top_level); |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
717 QSprofile_overhead = build_defer_string ("(profile overhead)"); |
| 1292 | 718 staticpro (&QSprofile_overhead); |
| 1123 | 719 |
| 720 DEFSYMBOL (Qtiming); | |
| 1292 | 721 DEFSYMBOL (Qtotal_timing); |
| 1123 | 722 DEFSYMBOL (Qcall_count); |
| 1292 | 723 DEFSYMBOL (Qgc_usage); |
| 724 DEFSYMBOL (Qtotal_gc_usage); | |
| 428 | 725 } |