Mercurial > hg > xemacs-beta
annotate src/profile.c @ 5287:cd167465bf69
More permission consistency.
| author | Stephen J. Turnbull <stephen@xemacs.org> |
|---|---|
| date | Mon, 14 Jun 2010 15:03:08 +0900 |
| parents | 71ee43b8a74d |
| children | c096d8051f89 308d34e9f07d |
| 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 { | |
| 368 CHECK_NATNUM (microsecs); | |
| 369 msecs = XINT (microsecs); | |
| 370 } | |
| 371 if (msecs <= 0) | |
| 372 msecs = 1000; | |
| 373 | |
| 613 | 374 set_timeout_signal (SIGPROF, sigprof_handler); |
| 1292 | 375 { |
| 376 struct backtrace *bt = backtrace_list; | |
| 377 | |
| 378 /* When we begin profiling, pretend like we just entered all the | |
| 379 functions currently on the stack. When we stop profiling, do the | |
| 380 opposite. This ensures consistent values being recorded for both | |
| 381 function-only and total in such cases. */ | |
| 382 for (; bt; bt = bt->next) | |
| 383 profile_sow_backtrace (bt); | |
| 384 } | |
| 385 profiling_active = 1; | |
| 386 profiling_lock = 0; | |
| 428 | 387 foo.it_value.tv_sec = 0; |
| 388 foo.it_value.tv_usec = msecs; | |
| 389 EMACS_NORMALIZE_TIME (foo.it_value); | |
| 390 foo.it_interval = foo.it_value; | |
| 611 | 391 qxe_setitimer (ITIMER_PROF, &foo, 0); |
| 1292 | 392 unbind_to (depth); |
| 428 | 393 return Qnil; |
| 394 } | |
| 395 | |
| 1292 | 396 DEFUN ("stop-profiling", Fstop_profiling, 0, 0, "", /* |
| 428 | 397 Stop profiling. |
| 398 */ | |
| 399 ()) | |
| 400 { | |
| 401 /* This function does not GC */ | |
| 402 struct itimerval foo; | |
| 403 | |
| 1292 | 404 if (!profiling_active) |
| 405 return Qnil; | |
| 406 in_profiling++; | |
| 428 | 407 foo.it_value.tv_sec = 0; |
| 408 foo.it_value.tv_usec = 0; | |
| 409 foo.it_interval = foo.it_value; | |
| 611 | 410 qxe_setitimer (ITIMER_PROF, &foo, 0); |
| 428 | 411 profiling_active = 0; |
| 1292 | 412 { |
| 413 struct backtrace *bt = backtrace_list; | |
| 414 | |
| 415 for (; bt; bt = bt->next) | |
| 416 profile_reap_backtrace (bt); | |
| 417 } | |
| 613 | 418 set_timeout_signal (SIGPROF, fatal_error_signal); |
| 1292 | 419 in_profiling--; |
| 428 | 420 return Qnil; |
| 421 } | |
| 422 | |
| 1123 | 423 DEFUN ("clear-profiling-info", Fclear_profiling_info, 0, 0, "", /* |
| 424 Clear out the recorded profiling info. | |
| 425 This clears both the internal timing information and the call counts in | |
| 426 `call-count-profile-table'. | |
| 427 */ | |
| 428 ()) | |
| 429 { | |
| 1292 | 430 in_profiling++; |
| 1123 | 431 /* This function does not GC */ |
| 432 if (big_profile_table) | |
| 433 { | |
| 1292 | 434 profiling_lock = 1; |
| 1123 | 435 clrhash (big_profile_table); |
| 1292 | 436 profiling_lock = 0; |
| 1123 | 437 } |
| 1292 | 438 if (!NILP (Vtotal_timing_profile_table)) |
| 439 Fclrhash (Vtotal_timing_profile_table); | |
| 1123 | 440 if (!NILP (Vcall_count_profile_table)) |
| 441 Fclrhash (Vcall_count_profile_table); | |
| 1292 | 442 if (!NILP (Vgc_usage_profile_table)) |
| 443 Fclrhash (Vgc_usage_profile_table); | |
| 444 if (!NILP (Vtotal_gc_usage_profile_table)) | |
| 445 Fclrhash (Vtotal_gc_usage_profile_table); | |
| 446 in_profiling--; | |
| 447 | |
| 1123 | 448 return Qnil; |
| 449 } | |
| 450 | |
| 428 | 451 struct get_profiling_info_closure |
| 452 { | |
| 1123 | 453 Lisp_Object timing; |
| 428 | 454 }; |
| 455 | |
| 456 static int | |
| 1123 | 457 get_profiling_info_timing_maphash (const void *void_key, |
| 458 void *void_val, | |
| 459 void *void_closure) | |
| 428 | 460 { |
| 461 /* This function does not GC */ | |
| 462 Lisp_Object key; | |
| 463 struct get_profiling_info_closure *closure | |
| 464 = (struct get_profiling_info_closure *) void_closure; | |
| 465 EMACS_INT val; | |
| 466 | |
| 5013 | 467 key = GET_LISP_FROM_VOID (void_key); |
| 428 | 468 val = (EMACS_INT) void_val; |
| 469 | |
| 1123 | 470 Fputhash (key, make_int (val), closure->timing); |
| 428 | 471 return 0; |
| 472 } | |
| 473 | |
| 1292 | 474 static Lisp_Object |
| 475 copy_hash_table_or_blank (Lisp_Object table) | |
| 476 { | |
| 477 return !NILP (table) ? Fcopy_hash_table (table) : | |
| 478 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
|
479 Qeq); |
| 1292 | 480 } |
| 481 | |
| 428 | 482 DEFUN ("get-profiling-info", Fget_profiling_info, 0, 0, 0, /* |
| 1123 | 483 Return the currently recorded profiling info. |
| 484 The format is a plist of symbols describing type of info recorded and | |
| 485 an associated type-specific entry. Currently, the following info types | |
| 486 are recorded | |
| 487 | |
| 488 `timing' | |
| 1292 | 489 A hash table of function descriptions (funcallable objects or strings |
| 490 describing internal processing operations -- redisplay, garbage | |
| 491 collection, etc.), along with associated tick counts (the frequency of | |
| 492 ticks is controlled by `default-profiling-interval' or the argument to | |
| 493 `start-profiling'). | |
| 494 | |
| 495 `total-timing' | |
| 496 A hash table of function descriptions and associated timing count for | |
| 497 the function and all descendants. | |
| 1123 | 498 |
| 499 `call-count' | |
| 1292 | 500 A hash table of function descriptions and associated call counts. |
| 501 | |
| 502 `gc-usage' | |
| 503 A hash table of function descriptions and associated amount of consing. | |
| 504 | |
| 505 `total-gc-usage' | |
| 506 A hash table of function descriptions and associated amount of consing | |
| 507 in the function and all descendants. | |
| 428 | 508 */ |
| 509 ()) | |
| 510 { | |
| 511 /* This function does not GC */ | |
| 512 struct get_profiling_info_closure closure; | |
| 1292 | 513 Lisp_Object retv; |
| 514 int depth = internal_bind_int (&in_profiling, 1 + in_profiling); | |
| 515 const void *overhead; | |
| 428 | 516 |
| 1123 | 517 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
|
518 make_lisp_hash_table (100, HASH_TABLE_NON_WEAK, Qequal); |
| 1123 | 519 |
| 428 | 520 if (big_profile_table) |
| 521 { | |
| 1292 | 522 int count = internal_bind_int ((int *) &profiling_lock, 1); |
| 1123 | 523 maphash (get_profiling_info_timing_maphash, big_profile_table, &closure); |
| 1292 | 524 |
| 525 /* OK, OK ... the total-timing table is not going to have an entry | |
| 526 for profile overhead, and it looks strange for it to come out 0, | |
| 527 so make sure it looks reasonable. */ | |
| 5013 | 528 if (!gethash (STORE_LISP_IN_VOID (QSprofile_overhead), big_profile_table, |
| 1292 | 529 &overhead)) |
| 530 overhead = 0; | |
| 531 Fputhash (QSprofile_overhead, make_int ((EMACS_INT) overhead), | |
| 532 Vtotal_timing_profile_table); | |
| 533 | |
| 771 | 534 unbind_to (count); |
| 428 | 535 } |
| 1123 | 536 |
| 1292 | 537 retv = nconc2 (list6 (Qtiming, closure.timing, Qtotal_timing, |
| 538 copy_hash_table_or_blank (Vtotal_timing_profile_table), | |
| 539 Qcall_count, | |
| 540 copy_hash_table_or_blank (Vcall_count_profile_table)), | |
| 541 list4 (Qgc_usage, | |
| 542 copy_hash_table_or_blank (Vgc_usage_profile_table), | |
| 543 Qtotal_gc_usage, | |
| 544 copy_hash_table_or_blank (Vtotal_gc_usage_profile_table | |
| 545 ))); | |
| 546 unbind_to (depth); | |
| 547 return retv; | |
| 1123 | 548 } |
| 549 | |
| 550 static int | |
| 551 set_profiling_info_timing_maphash (Lisp_Object key, | |
| 552 Lisp_Object val, | |
| 2286 | 553 void *UNUSED (void_closure)) |
| 1123 | 554 { |
| 555 /* This function does not GC */ | |
| 556 if (!INTP (val)) | |
| 557 invalid_argument_2 | |
| 558 ("Function timing count is not an integer in given entry", | |
| 559 key, val); | |
| 560 | |
| 5013 | 561 puthash (STORE_LISP_IN_VOID (key), (void *) XINT (val), big_profile_table); |
| 1123 | 562 |
| 563 return 0; | |
| 564 } | |
| 565 | |
| 566 DEFUN ("set-profiling-info", Fset_profiling_info, 1, 1, 0, /* | |
| 567 Set the currently recorded profiling info. | |
| 568 INFO should be in the same format returned by `get-profiling-info', | |
| 569 as described there. | |
| 570 */ | |
| 571 (info)) | |
| 572 { | |
| 1292 | 573 int depth; |
| 1123 | 574 /* This function does not GC */ |
| 575 Fclear_profiling_info (); | |
| 576 | |
| 1292 | 577 depth = internal_bind_int (&in_profiling, 1 + in_profiling); |
| 1123 | 578 { |
| 579 EXTERNAL_PROPERTY_LIST_LOOP_3 (key, value, info) | |
| 580 { | |
| 581 if (EQ (key, Qtiming)) | |
| 582 { | |
| 583 CHECK_HASH_TABLE (value); | |
| 584 create_timing_profile_table (); | |
| 1292 | 585 profiling_lock = 1; |
| 1123 | 586 elisp_maphash_unsafe (set_profiling_info_timing_maphash, value, |
| 587 NULL); | |
| 1292 | 588 profiling_lock = 0; |
| 1123 | 589 } |
| 590 else if (EQ (key, Qcall_count)) | |
| 1292 | 591 Vcall_count_profile_table = Fcopy_hash_table (value); |
| 592 else if (EQ (key, Qtotal_timing)) | |
| 593 Vtotal_timing_profile_table = Fcopy_hash_table (value); | |
| 594 else if (EQ (key, Qgc_usage)) | |
| 595 Vgc_usage_profile_table = Fcopy_hash_table (value); | |
| 596 else if (EQ (key, Qtotal_gc_usage)) | |
| 597 Vtotal_gc_usage_profile_table = Fcopy_hash_table (value); | |
| 1123 | 598 else |
| 599 invalid_constant ("Unrecognized profiling-info keyword", key); | |
| 600 } | |
| 601 } | |
| 602 | |
| 1292 | 603 unbind_to (depth); |
| 1123 | 604 return Qnil; |
| 428 | 605 } |
| 606 | |
| 607 static int | |
| 442 | 608 mark_profiling_info_maphash (const void *void_key, |
| 2286 | 609 void *UNUSED (void_val), |
| 610 void *UNUSED (void_closure)) | |
| 428 | 611 { |
| 1598 | 612 #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
|
613 kkcc_gc_stack_push_lisp_object_0 (GET_LISP_FROM_VOID (void_key)); |
| 1598 | 614 #else /* NOT USE_KKCC */ |
| 5013 | 615 mark_object (GET_LISP_FROM_VOID (void_key)); |
| 1598 | 616 #endif /* NOT USE_KKCC */ |
| 428 | 617 return 0; |
| 618 } | |
| 619 | |
| 620 void | |
| 621 mark_profiling_info (void) | |
| 622 { | |
| 623 /* This function does not GC */ | |
| 624 if (big_profile_table) | |
| 625 { | |
| 1292 | 626 profiling_lock = 1; |
| 428 | 627 maphash (mark_profiling_info_maphash, big_profile_table, 0); |
| 1292 | 628 profiling_lock = 0; |
| 428 | 629 } |
| 630 } | |
| 631 | |
| 632 DEFUN ("profiling-active-p", Fprofiling_active_p, 0, 0, 0, /* | |
| 633 Return non-nil if profiling information is currently being recorded. | |
| 634 */ | |
| 635 ()) | |
| 636 { | |
| 637 return profiling_active ? Qt : Qnil; | |
| 638 } | |
| 639 | |
| 640 void | |
| 641 syms_of_profile (void) | |
| 642 { | |
| 643 DEFSUBR (Fstart_profiling); | |
| 644 DEFSUBR (Fstop_profiling); | |
| 645 DEFSUBR (Fget_profiling_info); | |
| 1123 | 646 DEFSUBR (Fset_profiling_info); |
| 428 | 647 DEFSUBR (Fclear_profiling_info); |
| 648 DEFSUBR (Fprofiling_active_p); | |
| 649 } | |
| 650 | |
| 651 void | |
| 652 vars_of_profile (void) | |
| 653 { | |
| 654 DEFVAR_INT ("default-profiling-interval", &default_profiling_interval /* | |
| 655 Default CPU time in microseconds between profiling sampling. | |
| 656 Used when the argument to `start-profiling' is nil or omitted. | |
| 1346 | 657 Under Unix, the time in question is CPU time (when the program is executing |
| 658 or the kernel is executing on behalf of the program) and not real time. | |
| 659 Under MS Windows and Cygwin, the time is real time, but time spent blocking | |
| 660 while waiting for an event is ignored, to get more accurate results. | |
| 661 Note that there is usually a machine-dependent limit on how small this | |
| 662 value can be. | |
| 428 | 663 */ ); |
| 664 default_profiling_interval = 1000; | |
| 665 | |
| 1123 | 666 staticpro (&Vcall_count_profile_table); |
| 428 | 667 Vcall_count_profile_table = Qnil; |
| 668 | |
| 1292 | 669 staticpro (&Vgc_usage_profile_table); |
| 670 Vgc_usage_profile_table = Qnil; | |
| 671 | |
| 672 staticpro (&Vtotal_gc_usage_profile_table); | |
| 673 Vtotal_gc_usage_profile_table = Qnil; | |
| 674 | |
| 675 staticpro (&Vtotal_timing_profile_table); | |
| 676 Vtotal_timing_profile_table = Qnil; | |
| 428 | 677 |
| 1292 | 678 #if 0 |
| 679 /* #### This is supposed to be for KKCC but KKCC doesn't use this stuff | |
| 680 currently. */ | |
| 2367 | 681 dump_add_root_block_ptr (&big_profile_table, &plain_hash_table_description); |
| 1292 | 682 #endif /* 0 */ |
| 683 | |
| 684 profiling_lock = 0; | |
| 685 | |
| 2514 | 686 #ifdef DEBUG_XEMACS |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
687 QSin_temp_spot_1 = build_defer_string ("(in temp spot 1)"); |
| 2514 | 688 staticpro (&QSin_temp_spot_1); |
| 689 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
690 QSin_temp_spot_2 = build_defer_string ("(in temp spot 2)"); |
| 2514 | 691 staticpro (&QSin_temp_spot_2); |
| 692 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
693 QSin_temp_spot_3 = build_defer_string ("(in temp spot 3)"); |
| 2514 | 694 staticpro (&QSin_temp_spot_3); |
| 695 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
696 QSin_temp_spot_4 = build_defer_string ("(in temp spot 4)"); |
| 2514 | 697 staticpro (&QSin_temp_spot_4); |
| 698 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
699 QSin_temp_spot_5 = build_defer_string ("(in temp spot 5)"); |
| 2514 | 700 staticpro (&QSin_temp_spot_5); |
| 701 #endif /* DEBUG_XEMACS */ | |
| 702 | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
703 QSunknown = build_defer_string ("(unknown)"); |
| 428 | 704 staticpro (&QSunknown); |
| 705 QSprocessing_events_at_top_level = | |
|
4952
19a72041c5ed
Mule-izing, various fixes related to char * arguments
Ben Wing <ben@xemacs.org>
parents:
2645
diff
changeset
|
706 build_defer_string ("(processing events at top level)"); |
| 428 | 707 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
|
708 QSprofile_overhead = build_defer_string ("(profile overhead)"); |
| 1292 | 709 staticpro (&QSprofile_overhead); |
| 1123 | 710 |
| 711 DEFSYMBOL (Qtiming); | |
| 1292 | 712 DEFSYMBOL (Qtotal_timing); |
| 1123 | 713 DEFSYMBOL (Qcall_count); |
| 1292 | 714 DEFSYMBOL (Qgc_usage); |
| 715 DEFSYMBOL (Qtotal_gc_usage); | |
| 428 | 716 } |