Count overruns when profiling; change units to ns.

* lisp/profiler.el (profiler-sampling-interval): Change units
from ms to ns, multiplying the default by 1000000 so that
it remains 1 ms.
(profiler-report-cpu-line-format): Give enough room for
the maximum counters on 64-bit hosts.
(profiler-report-render-calltree-1): Call them "CPU samples",
not "Time (ms)", since they are not milliseconds now (and
never really were).
* src/profiler.c (handle_profiler_signal): Count sampling intervals, not ms.
Give extra weight to samples after overruns, to attempt to count
the time more accurately.
(setup_cpu_timer): Change sampling interval units from ms to ns, since
the underlying primitives nominally do ns.
(Fprofiler_cpu_start): Document the change.  Mention that
the sampling intervals are only approximate.

diff --git a/lisp/ChangeLog b/lisp/ChangeLog
index 0a305ee..1527307 100644 (file)
--- a/lisp/ChangeLog
+++ b/lisp/ChangeLog
@@ -1,3 +1,15 @@
+2012-10-02  Paul Eggert  <eggert@cs.ucla.edu>
+
+       Change sampling interval units from ms to ns.
+       * profiler.el (profiler-sampling-interval): Change units
+       from ms to ns, multiplying the default by 1000000 so that
+       it remains 1 ms.
+       (profiler-report-cpu-line-format): Give enough room for
+       the maximum counters on 64-bit hosts.
+       (profiler-report-render-calltree-1): Call them "CPU samples",
+       not "Time (ms)", since they are not milliseconds now (and
+       never really were).
+
 2012-10-02  Sergio Durigan Junior  <sergiodj@riseup.net>  (tiny change)
 
        * net/eudcb-bbdb.el (eudc-bbdb-format-record-as-result): Fix

diff --git a/lisp/profiler.el b/lisp/profiler.el
index 55e706e..efa23e7 100644 (file)
--- a/lisp/profiler.el
+++ b/lisp/profiler.el
@@ -33,8 +33,8 @@
 
 (defconst profiler-version "24.3")
 
-(defcustom profiler-sampling-interval 1
-  "Default sampling interval in millisecond."
+(defcustom profiler-sampling-interval 1000000
+  "Default sampling interval in nanoseconds."
   :type 'integer
   :group 'profiler)
 
@@ -323,8 +323,8 @@ function name of a function itself."
   :group 'profiler)
 
 (defvar profiler-report-cpu-line-format
-  '((60 left)
-    (14 right ((9 right)
+  '((50 left)
+    (24 right ((19 right)
               (5 right)))))
 
 (defvar profiler-report-memory-line-format
@@ -551,7 +551,7 @@ otherwise collapse."
            (cpu
             (profiler-report-header-line-format
              profiler-report-cpu-line-format
-             "Function" (list "Time (ms)" "%")))
+             "Function" (list "CPU samples" "%")))
            (memory
             (profiler-report-header-line-format
              profiler-report-memory-line-format

diff --git a/src/ChangeLog b/src/ChangeLog
index a199a7b..a7b35a8 100644 (file)
--- a/src/ChangeLog
+++ b/src/ChangeLog
@@ -1,3 +1,14 @@
+2012-10-02  Paul Eggert  <eggert@cs.ucla.edu>
+
+       Count overruns when profiling; change units to ns.
+       * profiler.c (handle_profiler_signal): Count sampling intervals, not ms.
+       Give extra weight to samples after overruns, to attempt to count
+       the time more accurately.
+       (setup_cpu_timer): Change sampling interval units from ms to ns, since
+       the underlying primitives nominally do ns.
+       (Fprofiler_cpu_start): Document the change.  Mention that
+       the sampling intervals are only approximate.
+
 2012-10-02  Stefan Monnier  <monnier@iro.umontreal.ca>
 
        * frame.c (Fmake_terminal_frame): Prefer safer CONSP over !NILP.

diff --git a/src/profiler.c b/src/profiler.c
index 2f082ed..3282b8b 100644 (file)
--- a/src/profiler.c
+++ b/src/profiler.c
@@ -128,8 +128,8 @@ static void evict_lower_half (log_t *log)
 }
 
 /* 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.  */
+   current backtrace: interrupt counts for CPU, and the allocation
+   size for memory.  */
 
 static void
 record_backtrace (log_t *log, EMACS_INT count)
@@ -220,7 +220,7 @@ static Lisp_Object cpu_log;
 /* Separate counter for the time spent in the GC.  */
 static EMACS_INT cpu_gc_count;
 
-/* The current sampling interval in milliseconds.  */
+/* The current sampling interval in nanoseconds.  */
 static EMACS_INT current_sampling_interval;
 
 /* Signal handler for sampling profiler.  */
@@ -235,11 +235,20 @@ handle_profiler_signal (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 = saturated_add (cpu_gc_count, current_sampling_interval);
+    cpu_gc_count = saturated_add (cpu_gc_count, 1);
   else
     {
+      EMACS_INT count = 1;
+#ifdef HAVE_TIMER_SETTIME
+      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), current_sampling_interval);
+      record_backtrace (XHASH_TABLE (cpu_log), count);
     }
 }
 
@@ -255,16 +264,18 @@ 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 / 1000
-                         ? (EMACS_INT) TYPE_MAXIMUM (time_t) * 1000 + 999
+                        (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 / 1000,
-                             current_sampling_interval % 1000 * 1000000);
+  interval = make_emacs_time (current_sampling_interval / billion,
+                             current_sampling_interval % billion);
   emacs_sigaction_init (&action, deliver_profiler_signal);
   sigaction (SIGPROF, &action, 0);
 
@@ -315,7 +326,7 @@ setup_cpu_timer (Lisp_Object sampling_interval)
 DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start,
        1, 1, 0,
        doc: /* Start or restart the cpu profiler.
-It takes call-stack samples each SAMPLING-INTERVAL milliseconds.
+It takes call-stack samples each SAMPLING-INTERVAL nanoseconds, approximately.
 See also `profiler-log-size' and `profiler-max-stack-depth'.  */)
   (Lisp_Object sampling_interval)
 {