X-Git-Url: https://code.delx.au/gnu-emacs/blobdiff_plain/6521894d1aa5a1017dd6f3f55b5e7c11dde5d004..c0c2eb8295bb99b6ac0bbf8c1e06b60220074a5b:/src/profiler.c diff --git a/src/profiler.c b/src/profiler.c index 1c4fa0fa21..b9035c3421 100644 --- a/src/profiler.c +++ b/src/profiler.c @@ -1,6 +1,6 @@ /* Profiler implementation. -Copyright (C) 2012 Free Software Foundation, Inc. +Copyright (C) 2012-2013 Free Software Foundation, Inc. This file is part of GNU Emacs. @@ -18,12 +18,18 @@ You should have received a copy of the GNU General Public License along with GNU Emacs. If not, see . */ #include -#include -#include -#include -#include -#include #include "lisp.h" +#include "syssignal.h" +#include "systime.h" + +/* Return A + B, but return the maximum fixnum if the result would overflow. + Assume A and B are nonnegative and in fixnum range. */ + +static EMACS_INT +saturated_add (EMACS_INT a, EMACS_INT b) +{ + return min (a + b, MOST_POSITIVE_FIXNUM); +} /* Logs. */ @@ -121,14 +127,12 @@ static void evict_lower_half (log_t *log) } } -/* Record the current backtrace in LOG. BASE is a special name for - describing which the backtrace come from. BASE can be nil. COUNT is - a number how many times the profiler sees the backtrace at the - time. ELAPSED is a elapsed time in millisecond that the backtrace - took. */ +/* Record the current backtrace in LOG. COUNT is the weight of this + current backtrace: interrupt counts for CPU, and the allocation + size for memory. */ static void -record_backtrace (log_t *log, size_t count) +record_backtrace (log_t *log, EMACS_INT count) { struct backtrace *backlist = backtrace_list; Lisp_Object backtrace; @@ -136,6 +140,8 @@ record_backtrace (log_t *log, size_t count) ptrdiff_t asize; if (!INTEGERP (log->next_free)) + /* FIXME: transfer the evicted counts to a special entry rather + than dropping them on the floor. */ evict_lower_half (log); index = XINT (log->next_free); @@ -145,7 +151,8 @@ record_backtrace (log_t *log, size_t count) /* Copy the backtrace contents into working memory. */ for (; i < asize && backlist; i++, backlist = backlist->next) - ASET (backtrace, i, *backlist->function); + /* FIXME: For closures we should ignore the environment. */ + ASET (backtrace, i, backlist->function); /* Make sure that unused space of working memory is filled with nil. */ for (; i < asize; i++) @@ -158,8 +165,11 @@ record_backtrace (log_t *log, size_t count) EMACS_UINT hash; ptrdiff_t j = hash_lookup (log, backtrace, &hash); if (j >= 0) - set_hash_value_slot (log, j, - make_number (count + XINT (HASH_VALUE (log, j)))); + { + EMACS_INT old_val = XINT (HASH_VALUE (log, j)); + EMACS_INT new_val = saturated_add (old_val, count); + set_hash_value_slot (log, j, make_number (new_val)); + } else { /* BEWARE! hash_put in general can allocate memory. But currently it only does that if log->next_free is nil. */ @@ -172,57 +182,173 @@ record_backtrace (log_t *log, size_t count) /* FIXME: If the hash-table is almost full, we should set some global flag so that some Elisp code can offload its - data elsewhere, so as to avoid the eviction code. */ + data elsewhere, so as to avoid the eviction code. + There are 2 ways to do that, AFAICT: + - Set a flag checked in QUIT, such that QUIT can then call + Fprofiler_cpu_log and stash the full log for later use. + - Set a flag check in post-gc-hook, so that Elisp code can call + profiler-cpu-log. That gives us more flexibility since that + Elisp code can then do all kinds of fun stuff like write + the log to disk. Or turn it right away into a call tree. + Of course, using Elisp is generally preferable, but it may + take longer until we get a chance to run the Elisp code, so + there's more risk that the table will get full before we + get there. */ } } } -/* Sample profiler. */ +/* Sampling profiler. */ -#if defined SIGPROF && defined HAVE_SETITIMER -#define PROFILER_CPU_SUPPORT +#ifdef PROFILER_CPU_SUPPORT -/* True if sampling profiler is running. */ -static bool profiler_cpu_running; +/* The profiler timer and whether it was properly initialized, if + POSIX timers are available. */ +#ifdef HAVE_ITIMERSPEC +static timer_t profiler_timer; +static bool profiler_timer_ok; +#endif + +/* Status of sampling profiler. */ +static enum profiler_cpu_running + { NOT_RUNNING, TIMER_SETTIME_RUNNING, SETITIMER_RUNNING } + profiler_cpu_running; +/* Hash-table log of CPU profiler. */ static Lisp_Object cpu_log; + /* Separate counter for the time spent in the GC. */ static EMACS_INT cpu_gc_count; -/* The current sample interval in millisecond. */ +/* The current sampling interval in nanoseconds. */ +static EMACS_INT current_sampling_interval; -static int current_sample_interval; - -/* Signal handler for sample profiler. */ +/* Signal handler for sampling profiler. */ static void -sigprof_handler (int signal, siginfo_t *info, void *ctx) +handle_profiler_signal (int signal) { - eassert (HASH_TABLE_P (cpu_log)); - if (backtrace_list && EQ (*backtrace_list->function, Qautomatic_gc)) + if (backtrace_list && EQ (backtrace_list->function, Qautomatic_gc)) /* Special case the time-count inside GC because the hash-table code is not prepared to be used while the GC is running. More specifically it uses ASIZE at many places where it does not expect the ARRAY_MARK_FLAG to be set. We could try and harden the hash-table code, but it doesn't seem worth the effort. */ - cpu_gc_count += current_sample_interval; + cpu_gc_count = saturated_add (cpu_gc_count, 1); else - record_backtrace (XHASH_TABLE (cpu_log), current_sample_interval); + { + Lisp_Object oquit; + bool saved_pending_signals; + EMACS_INT count = 1; +#ifdef HAVE_ITIMERSPEC + if (profiler_timer_ok) + { + int overruns = timer_getoverrun (profiler_timer); + eassert (0 <= overruns); + count += overruns; + } +#endif + /* record_backtrace uses hash functions that call Fequal, which + uses QUIT, which can call malloc, which can cause disaster in + a signal handler. So inhibit QUIT. */ + oquit = Vinhibit_quit; + saved_pending_signals = pending_signals; + Vinhibit_quit = Qt; + pending_signals = 0; + + eassert (HASH_TABLE_P (cpu_log)); + record_backtrace (XHASH_TABLE (cpu_log), count); + + Vinhibit_quit = oquit; + pending_signals = saved_pending_signals; + } +} + +static void +deliver_profiler_signal (int signal) +{ + deliver_process_signal (signal, handle_profiler_signal); +} + +static enum profiler_cpu_running +setup_cpu_timer (Lisp_Object sampling_interval) +{ + struct sigaction action; + struct itimerval timer; + struct timespec interval; + int billion = 1000000000; + + if (! RANGED_INTEGERP (1, sampling_interval, + (TYPE_MAXIMUM (time_t) < EMACS_INT_MAX / billion + ? ((EMACS_INT) TYPE_MAXIMUM (time_t) * billion + + (billion - 1)) + : EMACS_INT_MAX))) + return NOT_RUNNING; + + current_sampling_interval = XINT (sampling_interval); + interval = make_emacs_time (current_sampling_interval / billion, + current_sampling_interval % billion); + emacs_sigaction_init (&action, deliver_profiler_signal); + sigaction (SIGPROF, &action, 0); + +#ifdef HAVE_ITIMERSPEC + if (! profiler_timer_ok) + { + /* System clocks to try, in decreasing order of desirability. */ + static clockid_t const system_clock[] = { +#ifdef CLOCK_THREAD_CPUTIME_ID + CLOCK_THREAD_CPUTIME_ID, +#endif +#ifdef CLOCK_PROCESS_CPUTIME_ID + CLOCK_PROCESS_CPUTIME_ID, +#endif +#ifdef CLOCK_MONOTONIC + CLOCK_MONOTONIC, +#endif + CLOCK_REALTIME + }; + int i; + struct sigevent sigev; + sigev.sigev_value.sival_ptr = &profiler_timer; + sigev.sigev_signo = SIGPROF; + sigev.sigev_notify = SIGEV_SIGNAL; + + for (i = 0; i < sizeof system_clock / sizeof *system_clock; i++) + if (timer_create (system_clock[i], &sigev, &profiler_timer) == 0) + { + profiler_timer_ok = 1; + break; + } + } + + if (profiler_timer_ok) + { + struct itimerspec ispec; + ispec.it_value = ispec.it_interval = interval; + if (timer_settime (profiler_timer, 0, &ispec, 0) == 0) + return TIMER_SETTIME_RUNNING; + } +#endif + +#ifdef HAVE_SETITIMER + timer.it_value = timer.it_interval = make_timeval (interval); + if (setitimer (ITIMER_PROF, &timer, 0) == 0) + return SETITIMER_RUNNING; +#endif + + return NOT_RUNNING; } DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start, 1, 1, 0, doc: /* Start or restart the cpu profiler. -The cpu profiler will take call-stack samples each SAMPLE-INTERVAL (expressed in milliseconds). +It takes call-stack samples each SAMPLING-INTERVAL nanoseconds, approximately. See also `profiler-log-size' and `profiler-max-stack-depth'. */) - (Lisp_Object sample_interval) + (Lisp_Object sampling_interval) { - struct sigaction sa; - struct itimerval timer; - if (profiler_cpu_running) - error ("Sample profiler is already running"); + error ("CPU profiler is already running"); if (NILP (cpu_log)) { @@ -231,34 +357,47 @@ See also `profiler-log-size' and `profiler-max-stack-depth'. */) profiler_max_stack_depth); } - current_sample_interval = XINT (sample_interval); - - sa.sa_sigaction = sigprof_handler; - sa.sa_flags = SA_RESTART | SA_SIGINFO; - sigemptyset (&sa.sa_mask); - sigaction (SIGPROF, &sa, 0); - - timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = current_sample_interval * 1000; - timer.it_value = timer.it_interval; - setitimer (ITIMER_PROF, &timer, 0); - - profiler_cpu_running = 1; + profiler_cpu_running = setup_cpu_timer (sampling_interval); + if (! profiler_cpu_running) + error ("Invalid sampling interval"); return Qt; } DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop, 0, 0, 0, - doc: /* Stop the cpu profiler. The profiler log is not affected. */) + doc: /* Stop the cpu profiler. The profiler log is not affected. +Return non-nil if the profiler was running. */) (void) { - if (!profiler_cpu_running) - error ("Sample profiler is not running"); - profiler_cpu_running = 0; + switch (profiler_cpu_running) + { + case NOT_RUNNING: + return Qnil; - setitimer (ITIMER_PROF, 0, 0); +#ifdef HAVE_ITIMERSPEC + case TIMER_SETTIME_RUNNING: + { + struct itimerspec disable; + memset (&disable, 0, sizeof disable); + timer_settime (profiler_timer, 0, &disable, 0); + } + break; +#endif +#ifdef HAVE_SETITIMER + case SETITIMER_RUNNING: + { + struct itimerval disable; + memset (&disable, 0, sizeof disable); + setitimer (ITIMER_PROF, &disable, 0); + } + break; +#endif + } + + signal (SIGPROF, SIG_IGN); + profiler_cpu_running = NOT_RUNNING; return Qt; } @@ -281,7 +420,7 @@ Before returning, a new log is allocated for future samples. */) (void) { Lisp_Object result = cpu_log; - /* Here we're making the log visible to Elisp , so it's not safe any + /* Here we're making the log visible to Elisp, so it's not safe any more for our use afterwards since we can't rely on its special pre-allocated keys anymore. So we have to allocate a new one. */ cpu_log = (profiler_cpu_running @@ -293,7 +432,7 @@ Before returning, a new log is allocated for future samples. */) cpu_gc_count = 0; return result; } -#endif /* not defined PROFILER_CPU_SUPPORT */ +#endif /* PROFILER_CPU_SUPPORT */ /* Memory profiler. */ @@ -318,7 +457,7 @@ See also `profiler-log-size' and `profiler-max-stack-depth'. */) memory_log = make_log (profiler_log_size, profiler_max_stack_depth); - profiler_memory_running = 1; + profiler_memory_running = true; return Qt; } @@ -326,13 +465,13 @@ See also `profiler-log-size' and `profiler-max-stack-depth'. */) DEFUN ("profiler-memory-stop", Fprofiler_memory_stop, Sprofiler_memory_stop, 0, 0, 0, - doc: /* Stop the memory profiler. The profiler log is not affected. */) + doc: /* Stop the memory profiler. The profiler log is not affected. +Return non-nil if the profiler was running. */) (void) { if (!profiler_memory_running) - error ("Memory profiler is not running"); - profiler_memory_running = 0; - + return Qnil; + profiler_memory_running = false; return Qt; } @@ -373,7 +512,7 @@ void malloc_probe (size_t size) { eassert (HASH_TABLE_P (memory_log)); - record_backtrace (XHASH_TABLE (memory_log), size); + record_backtrace (XHASH_TABLE (memory_log), min (size, MOST_POSITIVE_FIXNUM)); } void @@ -389,6 +528,7 @@ to make room for new entries. */); profiler_log_size = 10000; #ifdef PROFILER_CPU_SUPPORT + profiler_cpu_running = NOT_RUNNING; cpu_log = Qnil; staticpro (&cpu_log); defsubr (&Sprofiler_cpu_start); @@ -396,6 +536,7 @@ to make room for new entries. */); defsubr (&Sprofiler_cpu_running_p); defsubr (&Sprofiler_cpu_log); #endif + profiler_memory_running = false; memory_log = Qnil; staticpro (&memory_log); defsubr (&Sprofiler_memory_start);