diff options
Diffstat (limited to 'src/profiler.c')
| -rw-r--r-- | src/profiler.c | 232 |
1 files changed, 174 insertions, 58 deletions
diff --git a/src/profiler.c b/src/profiler.c index 877a42cc98e..461aae3e09f 100644 --- a/src/profiler.c +++ b/src/profiler.c | |||
| @@ -18,12 +18,18 @@ You should have received a copy of the GNU General Public License | |||
| 18 | along with GNU Emacs. If not, see <http://www.gnu.org/licenses/>. */ | 18 | along with GNU Emacs. If not, see <http://www.gnu.org/licenses/>. */ |
| 19 | 19 | ||
| 20 | #include <config.h> | 20 | #include <config.h> |
| 21 | #include <stdio.h> | ||
| 22 | #include <limits.h> | ||
| 23 | #include <sys/time.h> | ||
| 24 | #include <signal.h> | ||
| 25 | #include <setjmp.h> | ||
| 26 | #include "lisp.h" | 21 | #include "lisp.h" |
| 22 | #include "syssignal.h" | ||
| 23 | #include "systime.h" | ||
| 24 | |||
| 25 | /* Return A + B, but return the maximum fixnum if the result would overflow. | ||
| 26 | Assume A and B are nonnegative and in fixnum range. */ | ||
| 27 | |||
| 28 | static EMACS_INT | ||
| 29 | saturated_add (EMACS_INT a, EMACS_INT b) | ||
| 30 | { | ||
| 31 | return min (a + b, MOST_POSITIVE_FIXNUM); | ||
| 32 | } | ||
| 27 | 33 | ||
| 28 | /* Logs. */ | 34 | /* Logs. */ |
| 29 | 35 | ||
| @@ -121,14 +127,12 @@ static void evict_lower_half (log_t *log) | |||
| 121 | } | 127 | } |
| 122 | } | 128 | } |
| 123 | 129 | ||
| 124 | /* Record the current backtrace in LOG. BASE is a special name for | 130 | /* Record the current backtrace in LOG. COUNT is the weight of this |
| 125 | describing which the backtrace come from. BASE can be nil. COUNT is | 131 | current backtrace: interrupt counts for CPU, and the allocation |
| 126 | a number how many times the profiler sees the backtrace at the | 132 | size for memory. */ |
| 127 | time. ELAPSED is a elapsed time in millisecond that the backtrace | ||
| 128 | took. */ | ||
| 129 | 133 | ||
| 130 | static void | 134 | static void |
| 131 | record_backtrace (log_t *log, size_t count) | 135 | record_backtrace (log_t *log, EMACS_INT count) |
| 132 | { | 136 | { |
| 133 | struct backtrace *backlist = backtrace_list; | 137 | struct backtrace *backlist = backtrace_list; |
| 134 | Lisp_Object backtrace; | 138 | Lisp_Object backtrace; |
| @@ -148,7 +152,7 @@ record_backtrace (log_t *log, size_t count) | |||
| 148 | /* Copy the backtrace contents into working memory. */ | 152 | /* Copy the backtrace contents into working memory. */ |
| 149 | for (; i < asize && backlist; i++, backlist = backlist->next) | 153 | for (; i < asize && backlist; i++, backlist = backlist->next) |
| 150 | /* FIXME: For closures we should ignore the environment. */ | 154 | /* FIXME: For closures we should ignore the environment. */ |
| 151 | ASET (backtrace, i, *backlist->function); | 155 | ASET (backtrace, i, backlist->function); |
| 152 | 156 | ||
| 153 | /* Make sure that unused space of working memory is filled with nil. */ | 157 | /* Make sure that unused space of working memory is filled with nil. */ |
| 154 | for (; i < asize; i++) | 158 | for (; i < asize; i++) |
| @@ -161,8 +165,11 @@ record_backtrace (log_t *log, size_t count) | |||
| 161 | EMACS_UINT hash; | 165 | EMACS_UINT hash; |
| 162 | ptrdiff_t j = hash_lookup (log, backtrace, &hash); | 166 | ptrdiff_t j = hash_lookup (log, backtrace, &hash); |
| 163 | if (j >= 0) | 167 | if (j >= 0) |
| 164 | set_hash_value_slot (log, j, | 168 | { |
| 165 | make_number (count + XINT (HASH_VALUE (log, j)))); | 169 | EMACS_INT old_val = XINT (HASH_VALUE (log, j)); |
| 170 | EMACS_INT new_val = saturated_add (old_val, count); | ||
| 171 | set_hash_value_slot (log, j, make_number (new_val)); | ||
| 172 | } | ||
| 166 | else | 173 | else |
| 167 | { /* BEWARE! hash_put in general can allocate memory. | 174 | { /* BEWARE! hash_put in general can allocate memory. |
| 168 | But currently it only does that if log->next_free is nil. */ | 175 | But currently it only does that if log->next_free is nil. */ |
| @@ -191,56 +198,153 @@ record_backtrace (log_t *log, size_t count) | |||
| 191 | } | 198 | } |
| 192 | } | 199 | } |
| 193 | 200 | ||
| 194 | /* Sample profiler. */ | 201 | /* Sampling profiler. */ |
| 195 | 202 | ||
| 196 | /* FIXME: Add support for the CPU profiler in W32. */ | 203 | #ifdef PROFILER_CPU_SUPPORT |
| 197 | /* FIXME: the sigprof_handler suffers from race-conditions if the signal | ||
| 198 | is delivered to a thread other than the main Emacs thread. */ | ||
| 199 | 204 | ||
| 200 | #if defined SIGPROF && defined HAVE_SETITIMER | 205 | /* The profiler timer and whether it was properly initialized, if |
| 201 | #define PROFILER_CPU_SUPPORT | 206 | POSIX timers are available. */ |
| 207 | #ifdef HAVE_ITIMERSPEC | ||
| 208 | static timer_t profiler_timer; | ||
| 209 | static bool profiler_timer_ok; | ||
| 210 | #endif | ||
| 202 | 211 | ||
| 203 | /* True if sampling profiler is running. */ | 212 | /* Status of sampling profiler. */ |
| 204 | static bool profiler_cpu_running; | 213 | static enum profiler_cpu_running |
| 214 | { NOT_RUNNING, TIMER_SETTIME_RUNNING, SETITIMER_RUNNING } | ||
| 215 | profiler_cpu_running; | ||
| 205 | 216 | ||
| 217 | /* Hash-table log of CPU profiler. */ | ||
| 206 | static Lisp_Object cpu_log; | 218 | static Lisp_Object cpu_log; |
| 219 | |||
| 207 | /* Separate counter for the time spent in the GC. */ | 220 | /* Separate counter for the time spent in the GC. */ |
| 208 | static EMACS_INT cpu_gc_count; | 221 | static EMACS_INT cpu_gc_count; |
| 209 | 222 | ||
| 210 | /* The current sample interval in millisecond. */ | 223 | /* The current sampling interval in nanoseconds. */ |
| 224 | static EMACS_INT current_sampling_interval; | ||
| 211 | 225 | ||
| 212 | static int current_sample_interval; | 226 | /* Signal handler for sampling profiler. */ |
| 213 | |||
| 214 | /* Signal handler for sample profiler. */ | ||
| 215 | 227 | ||
| 216 | static void | 228 | static void |
| 217 | sigprof_handler (int signal) | 229 | handle_profiler_signal (int signal) |
| 218 | { | 230 | { |
| 219 | eassert (HASH_TABLE_P (cpu_log)); | 231 | if (backtrace_list && EQ (backtrace_list->function, Qautomatic_gc)) |
| 220 | if (backtrace_list && EQ (*backtrace_list->function, Qautomatic_gc)) | ||
| 221 | /* Special case the time-count inside GC because the hash-table | 232 | /* Special case the time-count inside GC because the hash-table |
| 222 | code is not prepared to be used while the GC is running. | 233 | code is not prepared to be used while the GC is running. |
| 223 | More specifically it uses ASIZE at many places where it does | 234 | More specifically it uses ASIZE at many places where it does |
| 224 | not expect the ARRAY_MARK_FLAG to be set. We could try and | 235 | not expect the ARRAY_MARK_FLAG to be set. We could try and |
| 225 | harden the hash-table code, but it doesn't seem worth the | 236 | harden the hash-table code, but it doesn't seem worth the |
| 226 | effort. */ | 237 | effort. */ |
| 227 | cpu_gc_count += current_sample_interval; | 238 | cpu_gc_count = saturated_add (cpu_gc_count, 1); |
| 228 | else | 239 | else |
| 229 | record_backtrace (XHASH_TABLE (cpu_log), current_sample_interval); | 240 | { |
| 241 | Lisp_Object oquit; | ||
| 242 | EMACS_INT count = 1; | ||
| 243 | #ifdef HAVE_ITIMERSPEC | ||
| 244 | if (profiler_timer_ok) | ||
| 245 | { | ||
| 246 | int overruns = timer_getoverrun (profiler_timer); | ||
| 247 | eassert (0 <= overruns); | ||
| 248 | count += overruns; | ||
| 249 | } | ||
| 250 | #endif | ||
| 251 | /* record_backtrace uses hash functions that call Fequal, which | ||
| 252 | uses QUIT, which can call malloc, which can cause disaster in | ||
| 253 | a signal handler. So inhibit QUIT. */ | ||
| 254 | oquit = Vinhibit_quit; | ||
| 255 | Vinhibit_quit = Qt; | ||
| 256 | |||
| 257 | eassert (HASH_TABLE_P (cpu_log)); | ||
| 258 | record_backtrace (XHASH_TABLE (cpu_log), count); | ||
| 259 | |||
| 260 | Vinhibit_quit = oquit; | ||
| 261 | } | ||
| 262 | } | ||
| 263 | |||
| 264 | static void | ||
| 265 | deliver_profiler_signal (int signal) | ||
| 266 | { | ||
| 267 | deliver_process_signal (signal, handle_profiler_signal); | ||
| 268 | } | ||
| 269 | |||
| 270 | static enum profiler_cpu_running | ||
| 271 | setup_cpu_timer (Lisp_Object sampling_interval) | ||
| 272 | { | ||
| 273 | struct sigaction action; | ||
| 274 | struct itimerval timer; | ||
| 275 | struct timespec interval; | ||
| 276 | int billion = 1000000000; | ||
| 277 | |||
| 278 | if (! RANGED_INTEGERP (1, sampling_interval, | ||
| 279 | (TYPE_MAXIMUM (time_t) < EMACS_INT_MAX / billion | ||
| 280 | ? ((EMACS_INT) TYPE_MAXIMUM (time_t) * billion | ||
| 281 | + (billion - 1)) | ||
| 282 | : EMACS_INT_MAX))) | ||
| 283 | return NOT_RUNNING; | ||
| 284 | |||
| 285 | current_sampling_interval = XINT (sampling_interval); | ||
| 286 | interval = make_emacs_time (current_sampling_interval / billion, | ||
| 287 | current_sampling_interval % billion); | ||
| 288 | emacs_sigaction_init (&action, deliver_profiler_signal); | ||
| 289 | sigaction (SIGPROF, &action, 0); | ||
| 290 | |||
| 291 | #ifdef HAVE_ITIMERSPEC | ||
| 292 | if (! profiler_timer_ok) | ||
| 293 | { | ||
| 294 | /* System clocks to try, in decreasing order of desirability. */ | ||
| 295 | static clockid_t const system_clock[] = { | ||
| 296 | #ifdef CLOCK_THREAD_CPUTIME_ID | ||
| 297 | CLOCK_THREAD_CPUTIME_ID, | ||
| 298 | #endif | ||
| 299 | #ifdef CLOCK_PROCESS_CPUTIME_ID | ||
| 300 | CLOCK_PROCESS_CPUTIME_ID, | ||
| 301 | #endif | ||
| 302 | #ifdef CLOCK_MONOTONIC | ||
| 303 | CLOCK_MONOTONIC, | ||
| 304 | #endif | ||
| 305 | CLOCK_REALTIME | ||
| 306 | }; | ||
| 307 | int i; | ||
| 308 | struct sigevent sigev; | ||
| 309 | sigev.sigev_value.sival_ptr = &profiler_timer; | ||
| 310 | sigev.sigev_signo = SIGPROF; | ||
| 311 | sigev.sigev_notify = SIGEV_SIGNAL; | ||
| 312 | |||
| 313 | for (i = 0; i < sizeof system_clock / sizeof *system_clock; i++) | ||
| 314 | if (timer_create (system_clock[i], &sigev, &profiler_timer) == 0) | ||
| 315 | { | ||
| 316 | profiler_timer_ok = 1; | ||
| 317 | break; | ||
| 318 | } | ||
| 319 | } | ||
| 320 | |||
| 321 | if (profiler_timer_ok) | ||
| 322 | { | ||
| 323 | struct itimerspec ispec; | ||
| 324 | ispec.it_value = ispec.it_interval = interval; | ||
| 325 | if (timer_settime (profiler_timer, 0, &ispec, 0) == 0) | ||
| 326 | return TIMER_SETTIME_RUNNING; | ||
| 327 | } | ||
| 328 | #endif | ||
| 329 | |||
| 330 | #ifdef HAVE_SETITIMER | ||
| 331 | timer.it_value = timer.it_interval = make_timeval (interval); | ||
| 332 | if (setitimer (ITIMER_PROF, &timer, 0) == 0) | ||
| 333 | return SETITIMER_RUNNING; | ||
| 334 | #endif | ||
| 335 | |||
| 336 | return NOT_RUNNING; | ||
| 230 | } | 337 | } |
| 231 | 338 | ||
| 232 | DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start, | 339 | DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start, |
| 233 | 1, 1, 0, | 340 | 1, 1, 0, |
| 234 | doc: /* Start or restart the cpu profiler. | 341 | doc: /* Start or restart the cpu profiler. |
| 235 | The cpu profiler will take call-stack samples each SAMPLE-INTERVAL (expressed in milliseconds). | 342 | It takes call-stack samples each SAMPLING-INTERVAL nanoseconds, approximately. |
| 236 | See also `profiler-log-size' and `profiler-max-stack-depth'. */) | 343 | See also `profiler-log-size' and `profiler-max-stack-depth'. */) |
| 237 | (Lisp_Object sample_interval) | 344 | (Lisp_Object sampling_interval) |
| 238 | { | 345 | { |
| 239 | struct sigaction sa; | ||
| 240 | struct itimerval timer; | ||
| 241 | |||
| 242 | if (profiler_cpu_running) | 346 | if (profiler_cpu_running) |
| 243 | error ("Sample profiler is already running"); | 347 | error ("CPU profiler is already running"); |
| 244 | 348 | ||
| 245 | if (NILP (cpu_log)) | 349 | if (NILP (cpu_log)) |
| 246 | { | 350 | { |
| @@ -249,19 +353,9 @@ See also `profiler-log-size' and `profiler-max-stack-depth'. */) | |||
| 249 | profiler_max_stack_depth); | 353 | profiler_max_stack_depth); |
| 250 | } | 354 | } |
| 251 | 355 | ||
| 252 | current_sample_interval = XINT (sample_interval); | 356 | profiler_cpu_running = setup_cpu_timer (sampling_interval); |
| 253 | 357 | if (! profiler_cpu_running) | |
| 254 | sa.sa_handler = sigprof_handler; | 358 | error ("Invalid sampling interval"); |
| 255 | sa.sa_flags = SA_RESTART; | ||
| 256 | sigemptyset (&sa.sa_mask); | ||
| 257 | sigaction (SIGPROF, &sa, 0); | ||
| 258 | |||
| 259 | timer.it_interval.tv_sec = 0; | ||
| 260 | timer.it_interval.tv_usec = current_sample_interval * 1000; | ||
| 261 | timer.it_value = timer.it_interval; | ||
| 262 | setitimer (ITIMER_PROF, &timer, 0); | ||
| 263 | |||
| 264 | profiler_cpu_running = true; | ||
| 265 | 359 | ||
| 266 | return Qt; | 360 | return Qt; |
| 267 | } | 361 | } |
| @@ -272,12 +366,34 @@ DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop, | |||
| 272 | Return non-nil if the profiler was running. */) | 366 | Return non-nil if the profiler was running. */) |
| 273 | (void) | 367 | (void) |
| 274 | { | 368 | { |
| 275 | if (!profiler_cpu_running) | 369 | switch (profiler_cpu_running) |
| 276 | return Qnil; | 370 | { |
| 277 | profiler_cpu_running = false; | 371 | case NOT_RUNNING: |
| 372 | return Qnil; | ||
| 278 | 373 | ||
| 279 | setitimer (ITIMER_PROF, 0, 0); | 374 | #ifdef HAVE_ITIMERSPEC |
| 375 | case TIMER_SETTIME_RUNNING: | ||
| 376 | { | ||
| 377 | struct itimerspec disable; | ||
| 378 | memset (&disable, 0, sizeof disable); | ||
| 379 | timer_settime (profiler_timer, 0, &disable, 0); | ||
| 380 | } | ||
| 381 | break; | ||
| 382 | #endif | ||
| 280 | 383 | ||
| 384 | #ifdef HAVE_SETITIMER | ||
| 385 | case SETITIMER_RUNNING: | ||
| 386 | { | ||
| 387 | struct itimerval disable; | ||
| 388 | memset (&disable, 0, sizeof disable); | ||
| 389 | setitimer (ITIMER_PROF, &disable, 0); | ||
| 390 | } | ||
| 391 | break; | ||
| 392 | #endif | ||
| 393 | } | ||
| 394 | |||
| 395 | signal (SIGPROF, SIG_IGN); | ||
| 396 | profiler_cpu_running = NOT_RUNNING; | ||
| 281 | return Qt; | 397 | return Qt; |
| 282 | } | 398 | } |
| 283 | 399 | ||
| @@ -300,7 +416,7 @@ Before returning, a new log is allocated for future samples. */) | |||
| 300 | (void) | 416 | (void) |
| 301 | { | 417 | { |
| 302 | Lisp_Object result = cpu_log; | 418 | Lisp_Object result = cpu_log; |
| 303 | /* Here we're making the log visible to Elisp , so it's not safe any | 419 | /* Here we're making the log visible to Elisp, so it's not safe any |
| 304 | more for our use afterwards since we can't rely on its special | 420 | more for our use afterwards since we can't rely on its special |
| 305 | pre-allocated keys anymore. So we have to allocate a new one. */ | 421 | pre-allocated keys anymore. So we have to allocate a new one. */ |
| 306 | cpu_log = (profiler_cpu_running | 422 | cpu_log = (profiler_cpu_running |
| @@ -312,7 +428,7 @@ Before returning, a new log is allocated for future samples. */) | |||
| 312 | cpu_gc_count = 0; | 428 | cpu_gc_count = 0; |
| 313 | return result; | 429 | return result; |
| 314 | } | 430 | } |
| 315 | #endif /* not defined PROFILER_CPU_SUPPORT */ | 431 | #endif /* PROFILER_CPU_SUPPORT */ |
| 316 | 432 | ||
| 317 | /* Memory profiler. */ | 433 | /* Memory profiler. */ |
| 318 | 434 | ||
| @@ -392,7 +508,7 @@ void | |||
| 392 | malloc_probe (size_t size) | 508 | malloc_probe (size_t size) |
| 393 | { | 509 | { |
| 394 | eassert (HASH_TABLE_P (memory_log)); | 510 | eassert (HASH_TABLE_P (memory_log)); |
| 395 | record_backtrace (XHASH_TABLE (memory_log), size); | 511 | record_backtrace (XHASH_TABLE (memory_log), min (size, MOST_POSITIVE_FIXNUM)); |
| 396 | } | 512 | } |
| 397 | 513 | ||
| 398 | void | 514 | void |
| @@ -408,7 +524,7 @@ to make room for new entries. */); | |||
| 408 | profiler_log_size = 10000; | 524 | profiler_log_size = 10000; |
| 409 | 525 | ||
| 410 | #ifdef PROFILER_CPU_SUPPORT | 526 | #ifdef PROFILER_CPU_SUPPORT |
| 411 | profiler_cpu_running = false; | 527 | profiler_cpu_running = NOT_RUNNING; |
| 412 | cpu_log = Qnil; | 528 | cpu_log = Qnil; |
| 413 | staticpro (&cpu_log); | 529 | staticpro (&cpu_log); |
| 414 | defsubr (&Sprofiler_cpu_start); | 530 | defsubr (&Sprofiler_cpu_start); |