Merge from emacs-24; up to 2012-12-06T01:39:03Z!monnier@iro.umontreal.ca
[bpt/emacs.git] / src / profiler.c
index 1c4fa0f..f6503cf 100644 (file)
@@ -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,17 +18,26 @@ You should have received a copy of the GNU General Public License
 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.  */
 
 typedef struct Lisp_Hash_Table log_t;
 
+static Lisp_Object Qprofiler_backtrace_equal;
+static struct hash_table_test hashtest_profiler;
+
 static Lisp_Object
 make_log (int heap_size, int max_stack_depth)
 {
@@ -36,10 +45,11 @@ make_log (int heap_size, int max_stack_depth)
      a special way.  This is OK as long as the object is not exposed
      to Elisp, i.e. until it is returned by *-profiler-log, after which
      it can't be used any more.  */
-  Lisp_Object log = make_hash_table (Qequal, make_number (heap_size),
+  Lisp_Object log = make_hash_table (hashtest_profiler,
+                                    make_number (heap_size),
                                     make_float (DEFAULT_REHASH_SIZE),
                                     make_float (DEFAULT_REHASH_THRESHOLD),
-                                    Qnil, Qnil, Qnil);
+                                    Qnil);
   struct Lisp_Hash_Table *h = XHASH_TABLE (log);
 
   /* What is special about our hash-tables is that the keys are pre-filled
@@ -121,14 +131,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 +144,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 +155,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 +169,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 +186,160 @@ 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.  */
       }
   }
 }
 \f
-/* Sample profiler.  */
+/* Sampling profiler.  */
 
-#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_ITIMERSPEC
+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 sampling interval in nanoseconds.  */
+static EMACS_INT current_sampling_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);
+    {
+      EMACS_INT count = 1;
+#ifdef HAVE_ITIMERSPEC
+      if (profiler_timer_ok)
+       {
+         int overruns = timer_getoverrun (profiler_timer);
+         eassert (0 <= overruns);
+         count += overruns;
+       }
+#endif
+      eassert (HASH_TABLE_P (cpu_log));
+      record_backtrace (XHASH_TABLE (cpu_log), count);
+    }
+}
+
+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 +348,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 +411,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 +423,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 */
 \f
 /* Memory profiler.  */
 
@@ -318,7 +448,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 +456,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 +503,67 @@ 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));
+}
+
+DEFUN ("function-equal", Ffunction_equal, Sfunction_equal, 2, 2, 0,
+       doc: /* Return non-nil if F1 and F2 come from the same source.
+Used to determine if different closures are just different instances of
+the same lambda expression, or are really unrelated function.  */)
+     (Lisp_Object f1, Lisp_Object f2)
+{
+  bool res;
+  if (EQ (f1, f2))
+    res = true;
+  else if (COMPILEDP (f1) && COMPILEDP (f2))
+    res = EQ (AREF (f1, COMPILED_BYTECODE), AREF (f2, COMPILED_BYTECODE));
+  else if (CONSP (f1) && CONSP (f2) && CONSP (XCDR (f1)) && CONSP (XCDR (f2))
+          && EQ (Qclosure, XCAR (f1))
+          && EQ (Qclosure, XCAR (f2)))
+    res = EQ (XCDR (XCDR (f1)), XCDR (XCDR (f2)));
+  else
+    res = false;
+  return res ? Qt : Qnil;
+}
+
+static bool
+cmpfn_profiler (struct hash_table_test *t,
+               Lisp_Object bt1, Lisp_Object bt2)
+{
+  if (VECTORP (bt1) && VECTORP (bt2))
+    {
+      ptrdiff_t i, l = ASIZE (bt1);
+      if (l != ASIZE (bt2))
+       return false;
+      for (i = 0; i < l; i++)
+       if (NILP (Ffunction_equal (AREF (bt1, i), AREF (bt2, i))))
+         return false;
+      return true;
+    }
+  else
+    return EQ (bt1, bt2);
+}
+
+static EMACS_UINT
+hashfn_profiler (struct hash_table_test *ht, Lisp_Object bt)
+{
+  if (VECTORP (bt))
+    {
+      EMACS_UINT hash = 0;
+      ptrdiff_t i, l = ASIZE (bt);
+      for (i = 0; i < l; i++)
+       {
+         Lisp_Object f = AREF (bt, i);
+         EMACS_UINT hash1
+           = (COMPILEDP (f) ? XHASH (AREF (f, COMPILED_BYTECODE))
+              : (CONSP (f) && CONSP (XCDR (f)) && EQ (Qclosure, XCAR (f)))
+              ? XHASH (XCDR (XCDR (f))) : XHASH (f));
+         hash = sxhash_combine (hash, hash1);
+       }
+      return (hash & INTMASK);
+    }
+  else
+    return XHASH (bt);
 }
 
 void
@@ -388,7 +578,18 @@ If the log gets full, some of the least-seen call-stacks will be evicted
 to make room for new entries.  */);
   profiler_log_size = 10000;
 
+  DEFSYM (Qprofiler_backtrace_equal, "profiler-backtrace-equal");
+  {
+    struct hash_table_test test
+      = { Qprofiler_backtrace_equal, Qnil, Qnil,
+         cmpfn_profiler, hashfn_profiler };
+    hashtest_profiler = test;
+  }
+
+  defsubr (&Sfunction_equal);
+
 #ifdef PROFILER_CPU_SUPPORT
+  profiler_cpu_running = NOT_RUNNING;
   cpu_log = Qnil;
   staticpro (&cpu_log);
   defsubr (&Sprofiler_cpu_start);
@@ -396,6 +597,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);