From: Paul Eggert Date: Sun, 30 Sep 2012 06:19:33 +0000 (-0700) Subject: Profiler improvements: more-accurate timers, overflow checks. X-Git-Tag: emacs-24.2.90~244^2~13 X-Git-Url: http://git.eshelyaron.com/gitweb/?a=commitdiff_plain;h=d89460ed93e67852a95a597a7a1a7983e8828fb9;p=emacs.git Profiler improvements: more-accurate timers, overflow checks. * profiler.c: Don't include stdio.h, limits.h, sys/time.h, signal.h, setjmp.h. Include systime.h instead. (saturated_add): New function. (record_backtrace, current_sample_interval): Use EMACS_INT, not size_t. (record_backtrace, handle_profiler_signal): Saturate on fixnum overflow. (profiler_timer, profiler_timer_ok) [HAVE_TIMER_SETTIME]: New static vars. (enum profiler_cpu_running): New enumn. (profiler_cpu_running): Now of that enum type, not bool. All uses changed to store the new value. (handle_profiler_signal): Rename from sigprof_handler_1, for consistency with other handlers. Do not check whether cpu_log is a hash-table if garbage collecting, since it doesn't matter in that case. (deliver_profiler_signal): Rename from sigprof_handler, for consistency with other handlers. (setup_cpu_timer): New function, with much of what used to be in Fprofiler_cpu_start. Check for out-of-range argument. Prefer timer_settime if available, and prefer thread cputime clocks, then process cputime clocks, then monotonic clocks, to the old realtime clock. Use make_timeval to round more-correctly when falling back to setitimer. (Fprofiler_cpu_start): Use it. (Fprofiler_cpu_stop): Prefer timer_settime if available. Don't assume that passing NULL as the 2nd argument of setitimer is the same as passing a pointer to all-zero storage. Ignore SIGPROF afterwards. (malloc_probe): Saturate at MOST_POSITIVE_FIXNUM. * sysdep.c (emacs_sigaction_init): Also mask out SIGPROF in non-fatal signal handlers. Ignore SIGPROF on startup. * syssignal.h (PROFILER_CPU_SUPPORT): Define this macro here, not in profiler.c, since sysdep.c now uses it. --- diff --git a/src/ChangeLog b/src/ChangeLog index fd4319eb4b0..97f955e7136 100644 --- a/src/ChangeLog +++ b/src/ChangeLog @@ -1,5 +1,39 @@ 2012-09-30 Paul Eggert + Profiler improvements: more-accurate timers, overflow checks. + * profiler.c: Don't include stdio.h, limits.h, sys/time.h, + signal.h, setjmp.h. Include systime.h instead. + (saturated_add): New function. + (record_backtrace, current_sample_interval): Use EMACS_INT, not size_t. + (record_backtrace, handle_profiler_signal): Saturate on fixnum overflow. + (profiler_timer, profiler_timer_ok) [HAVE_TIMER_SETTIME]: + New static vars. + (enum profiler_cpu_running): New enumn. + (profiler_cpu_running): Now of that enum type, not bool. + All uses changed to store the new value. + (handle_profiler_signal): Rename from sigprof_handler_1, + for consistency with other handlers. Do not check whether + cpu_log is a hash-table if garbage collecting, since it + doesn't matter in that case. + (deliver_profiler_signal): Rename from sigprof_handler, + for consistency with other handlers. + (setup_cpu_timer): New function, with much of what used to be in + Fprofiler_cpu_start. Check for out-of-range argument. + Prefer timer_settime if available, and prefer + thread cputime clocks, then process cputime clocks, then + monotonic clocks, to the old realtime clock. Use make_timeval + to round more-correctly when falling back to setitimer. + (Fprofiler_cpu_start): Use it. + (Fprofiler_cpu_stop): Prefer timer_settime if available. + Don't assume that passing NULL as the 2nd argument of setitimer + is the same as passing a pointer to all-zero storage. + Ignore SIGPROF afterwards. + (malloc_probe): Saturate at MOST_POSITIVE_FIXNUM. + * sysdep.c (emacs_sigaction_init): Also mask out SIGPROF in + non-fatal signal handlers. Ignore SIGPROF on startup. + * syssignal.h (PROFILER_CPU_SUPPORT): Define this macro here, not + in profiler.c, since sysdep.c now uses it. + * sysdep.c (handle_fatal_signal): Bump backtrace size to 40. Suggested by Eli Zaretskii in . diff --git a/src/profiler.c b/src/profiler.c index 44a12fc159c..489c68b7291 100644 --- a/src/profiler.c +++ b/src/profiler.c @@ -18,13 +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. */ @@ -122,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: milliseconds for CPU counts, and the allocation + size for memory logs. */ 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; @@ -162,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. */ @@ -195,29 +201,35 @@ record_backtrace (log_t *log, size_t count) /* Sample profiler. */ /* FIXME: Add support for the CPU profiler in W32. */ -/* FIXME: the sigprof_handler suffers from race-conditions if the signal - is delivered to a thread other than the main Emacs thread. */ -#if defined SIGPROF && defined HAVE_SETITIMER -#define PROFILER_CPU_SUPPORT +#ifdef PROFILER_CPU_SUPPORT + +/* The profiler timer and whether it was properly initialized, if + POSIX timers are available. */ +#ifdef HAVE_TIMER_SETTIME +static timer_t profiler_timer; +static bool profiler_timer_ok; +#endif -/* True if sampling profiler is running. */ -static bool profiler_cpu_running; +/* 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. */ - -static int current_sample_interval; +/* The current sample interval in milliseconds. */ +static EMACS_INT current_sample_interval; /* Signal handler for sample profiler. */ static void -sigprof_handler_1 (int signal) +handle_profiler_signal (int signal) { - eassert (HASH_TABLE_P (cpu_log)); 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. @@ -225,27 +237,90 @@ sigprof_handler_1 (int signal) 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, current_sample_interval); else - record_backtrace (XHASH_TABLE (cpu_log), current_sample_interval); + { + eassert (HASH_TABLE_P (cpu_log)); + record_backtrace (XHASH_TABLE (cpu_log), current_sample_interval); + } } static void -sigprof_handler (int signal) +deliver_profiler_signal (int signal) +{ + deliver_process_signal (signal, handle_profiler_signal); +} + +static enum profiler_cpu_running +setup_cpu_timer (Lisp_Object sample_interval) { - deliver_process_signal (signal, sigprof_handler_1); + struct sigaction action; + struct itimerval timer; + struct timespec interval; + + if (! RANGED_INTEGERP (1, sample_interval, + (TYPE_MAXIMUM (time_t) < EMACS_INT_MAX / 1000 + ? (EMACS_INT) TYPE_MAXIMUM (time_t) * 1000 + 999 + : EMACS_INT_MAX))) + return NOT_RUNNING; + + current_sample_interval = XINT (sample_interval); + interval = make_emacs_time (current_sample_interval / 1000, + current_sample_interval % 1000 * 1000000); + emacs_sigaction_init (&action, deliver_profiler_signal); + sigaction (SIGPROF, &action, 0); + +#ifdef HAVE_TIMER_SETTIME + 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; + timer_settime (profiler_timer, 0, &ispec, 0); + return TIMER_SETTIME_RUNNING; + } +#endif + + timer.it_value = timer.it_interval = make_timeval (interval); + setitimer (ITIMER_PROF, &timer, 0); + return SETITIMER_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 SAMPLE-INTERVAL milliseconds. See also `profiler-log-size' and `profiler-max-stack-depth'. */) (Lisp_Object sample_interval) { - struct sigaction sa; - struct itimerval timer; - if (profiler_cpu_running) error ("Sample profiler is already running"); @@ -256,19 +331,9 @@ See also `profiler-log-size' and `profiler-max-stack-depth'. */) profiler_max_stack_depth); } - current_sample_interval = XINT (sample_interval); - - sa.sa_handler = sigprof_handler; - sa.sa_flags = SA_RESTART; - 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 = true; + profiler_cpu_running = setup_cpu_timer (sample_interval); + if (! profiler_cpu_running) + error ("Invalid sample interval"); return Qt; } @@ -279,12 +344,30 @@ DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop, Return non-nil if the profiler was running. */) (void) { - if (!profiler_cpu_running) - return Qnil; - profiler_cpu_running = false; + switch (profiler_cpu_running) + { + case NOT_RUNNING: + return Qnil; + + case TIMER_SETTIME_RUNNING: + { + struct itimerspec disable; + memset (&disable, 0, sizeof disable); + timer_settime (profiler_timer, 0, &disable, 0); + } + break; - setitimer (ITIMER_PROF, 0, 0); + case SETITIMER_RUNNING: + { + struct itimerval disable; + memset (&disable, 0, sizeof disable); + setitimer (ITIMER_PROF, &disable, 0); + } + break; + } + signal (SIGPROF, SIG_IGN); + profiler_cpu_running = NOT_RUNNING; return Qt; } @@ -307,7 +390,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 @@ -319,7 +402,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. */ @@ -399,7 +482,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 @@ -415,7 +498,7 @@ to make room for new entries. */); profiler_log_size = 10000; #ifdef PROFILER_CPU_SUPPORT - profiler_cpu_running = false; + profiler_cpu_running = NOT_RUNNING; cpu_log = Qnil; staticpro (&cpu_log); defsubr (&Sprofiler_cpu_start); diff --git a/src/sysdep.c b/src/sysdep.c index 4deb022fb90..b7141011d05 100644 --- a/src/sysdep.c +++ b/src/sysdep.c @@ -1447,6 +1447,9 @@ emacs_sigaction_init (struct sigaction *action, signal_handler_t handler) #ifdef SIGDANGER sigaddset (&action->sa_mask, SIGDANGER); #endif +#ifdef PROFILER_CPU_SUPPORT + sigaddset (&action->sa_mask, SIGPROF); +#endif #ifdef SIGWINCH sigaddset (&action->sa_mask, SIGWINCH); #endif @@ -1837,7 +1840,7 @@ init_signals (bool dumping) #endif sigaction (SIGTERM, &process_fatal_action, 0); #ifdef SIGPROF - sigaction (SIGPROF, &process_fatal_action, 0); + signal (SIGPROF, SIG_IGN); #endif #ifdef SIGVTALRM sigaction (SIGVTALRM, &process_fatal_action, 0); diff --git a/src/syssignal.h b/src/syssignal.h index 5c0edaa591d..0bc856769ba 100644 --- a/src/syssignal.h +++ b/src/syssignal.h @@ -29,6 +29,10 @@ extern void init_signals (bool); #define FORWARD_SIGNAL_TO_MAIN_THREAD #endif +#if defined SIGPROF && (defined HAVE_TIMER_SETTIME || defined HAVE_SETITIMER) +# define PROFILER_CPU_SUPPORT +#endif + extern sigset_t empty_mask; typedef void (*signal_handler_t) (int);