[Emacs-diffs] /srv/bzr/emacs/trunk r110270: Profiler improvements: more-accurate timers, overflow checks.

[Paul Eggert]

------------------------------------------------------------
revno: 110270
committer: Paul Eggert <address@hidden>
branch nick: trunk
timestamp: Sat 2012-09-29 23:19:33 -0700
message:
  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.
modified:
  src/ChangeLog
  src/profiler.c
  src/sysdep.c
  src/syssignal.h

=== modified file 'src/ChangeLog'
--- a/src/ChangeLog     2012-09-30 01:29:53 +0000
+++ b/src/ChangeLog     2012-09-30 06:19:33 +0000
@@ -1,5 +1,39 @@
 2012-09-30  Paul Eggert  <address@hidden>
 
+       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
        <http://lists.gnu.org/archive/html/emacs-devel/2012-09/msg00796.html>.

=== modified file 'src/profiler.c'
--- a/src/profiler.c    2012-09-29 02:02:34 +0000
+++ b/src/profiler.c    2012-09-30 06:19:33 +0000
@@ -18,13 +18,18 @@
 along with GNU Emacs.  If not, see <http://www.gnu.org/licenses/>.  */
 
 #include <config.h>
-#include <stdio.h>
-#include <limits.h>
-#include <sys/time.h>
-#include <signal.h>
-#include <setjmp.h>
 #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 @@
       }
 }
 
-/* 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 @@
     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 @@
 /* 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
-
-/* True if sampling profiler is running.  */
-static bool profiler_cpu_running;
-
+
+#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
+
+/* 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 @@
        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_process_signal (signal, sigprof_handler_1);
+deliver_profiler_signal (int signal)
+{
+  deliver_process_signal (signal, handle_profiler_signal);
+}
+
+static enum profiler_cpu_running
+setup_cpu_timer (Lisp_Object sample_interval)
+{
+  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 @@
                          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 @@
 Return non-nil if the profiler was running.  */)
   (void)
 {
-  if (!profiler_cpu_running)
-    return Qnil;
-  profiler_cpu_running = false;
-
-  setitimer (ITIMER_PROF, 0, 0);
-
+  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;
+
+    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 @@
   (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 @@
   cpu_gc_count = 0;
   return result;
 }
-#endif /* not defined PROFILER_CPU_SUPPORT */
+#endif /* PROFILER_CPU_SUPPORT */
 
 /* Memory profiler.  */
 
@@ -399,7 +482,7 @@
 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 @@
   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);

=== modified file 'src/sysdep.c'
--- a/src/sysdep.c      2012-09-30 01:29:53 +0000
+++ b/src/sysdep.c      2012-09-30 06:19:33 +0000
@@ -1447,6 +1447,9 @@
 #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 @@
 #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);

=== modified file 'src/syssignal.h'
--- a/src/syssignal.h   2012-09-23 08:44:20 +0000
+++ b/src/syssignal.h   2012-09-30 06:19:33 +0000
@@ -29,6 +29,10 @@
 #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);