/* Profiler implementation.
-Copyright (C) 2012 Free Software Foundation, Inc.
+Copyright (C) 2012-2013 Free Software Foundation, Inc.
This file is part of GNU Emacs.
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"
-/* True if sampling profiler is running. */
+/* Return A + B, but return the maximum fixnum if the result would overflow.
+ Assume A and B are nonnegative and in fixnum range. */
-bool sample_profiler_running;
-
-/* True if memory profiler is running. */
-
-bool memory_profiler_running;
-
-static void sigprof_handler (int, siginfo_t *, void *);
+static EMACS_INT
+saturated_add (EMACS_INT a, EMACS_INT b)
+{
+ return min (a + b, MOST_POSITIVE_FIXNUM);
+}
-\f
/* Logs. */
typedef struct Lisp_Hash_Table log_t;
}
}
-/* 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;
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);
/* 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++)
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. */
/* 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. */
+
+#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
-#if defined SIGPROF && defined HAVE_SETITIMER
-#define PROFILER_CPU_SUPPORT
+/* 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 sampling profiler. */
-DEFUN ("sample-profiler-start", Fsample_profiler_start, Ssample_profiler_start,
- 1, 1, 0,
- doc: /* Start or restart sample profiler. Sample profiler will
-take samples each SAMPLE-INTERVAL in millisecond. See also
-`profiler-slot-heap-size' and `profiler-max-stack-depth'. */)
- (Lisp_Object sample_interval)
+static void
+handle_profiler_signal (int signal)
+{
+ 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 = saturated_add (cpu_gc_count, 1);
+ else
+ {
+ 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 sa;
+ 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 (sample_profiler_running)
- error ("Sample profiler is already running");
+ 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.
+It takes call-stack samples each SAMPLING-INTERVAL nanoseconds, approximately.
+See also `profiler-log-size' and `profiler-max-stack-depth'. */)
+ (Lisp_Object sampling_interval)
+{
+ if (profiler_cpu_running)
+ error ("CPU profiler is already running");
if (NILP (cpu_log))
{
cpu_gc_count = 0;
- cpu_log = make_log (profiler_slot_heap_size,
+ cpu_log = make_log (profiler_log_size,
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);
-
- sample_profiler_running = 1;
+ profiler_cpu_running = setup_cpu_timer (sampling_interval);
+ if (! profiler_cpu_running)
+ error ("Invalid sampling interval");
return Qt;
}
-DEFUN ("sample-profiler-stop", Fsample_profiler_stop, Ssample_profiler_stop,
+DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop,
0, 0, 0,
- doc: /* Stop sample profiler. Profiler log will be kept. */)
+ doc: /* Stop the cpu profiler. The profiler log is not affected.
+Return non-nil if the profiler was running. */)
(void)
{
- if (!sample_profiler_running)
- error ("Sample profiler is not running");
- sample_profiler_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;
}
-DEFUN ("sample-profiler-running-p",
- Fsample_profiler_running_p, Ssample_profiler_running_p,
+DEFUN ("profiler-cpu-running-p",
+ Fprofiler_cpu_running_p, Sprofiler_cpu_running_p,
0, 0, 0,
- doc: /* Return t if sample profiler is running. */)
+ doc: /* Return non-nil iff cpu profiler is running. */)
(void)
{
- return sample_profiler_running ? Qt : Qnil;
+ return profiler_cpu_running ? Qt : Qnil;
}
-DEFUN ("sample-profiler-log",
- Fsample_profiler_log, Ssample_profiler_log,
+DEFUN ("profiler-cpu-log", Fprofiler_cpu_log, Sprofiler_cpu_log,
0, 0, 0,
- doc: /* Return sample profiler log. The data is a list of
-(sample nil TIMESTAMP SLOTS), where TIMESTAMP is a timestamp when the
-log is collected and SLOTS is a list of slots. */)
+ doc: /* Return the current cpu profiler log.
+The log is a hash-table mapping backtraces to counters which represent
+the amount of time spent at those points. Every backtrace is a vector
+of functions, where the last few elements may be nil.
+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 = (sample_profiler_running
- ? make_log (profiler_slot_heap_size, profiler_max_stack_depth)
+ cpu_log = (profiler_cpu_running
+ ? make_log (profiler_log_size, profiler_max_stack_depth)
: Qnil);
Fputhash (Fmake_vector (make_number (1), Qautomatic_gc),
make_number (cpu_gc_count),
cpu_gc_count = 0;
return result;
}
-#endif
+#endif /* PROFILER_CPU_SUPPORT */
\f
/* Memory profiler. */
+/* True if memory profiler is running. */
+bool profiler_memory_running;
+
static Lisp_Object memory_log;
-DEFUN ("memory-profiler-start", Fmemory_profiler_start, Smemory_profiler_start,
+DEFUN ("profiler-memory-start", Fprofiler_memory_start, Sprofiler_memory_start,
0, 0, 0,
- doc: /* Start/restart memory profiler. See also
-`profiler-slot-heap-size' and `profiler-max-stack-depth'. */)
+ doc: /* Start/restart the memory profiler.
+The memory profiler will take samples of the call-stack whenever a new
+allocation takes place. Note that most small allocations only trigger
+the profiler occasionally.
+See also `profiler-log-size' and `profiler-max-stack-depth'. */)
(void)
{
- if (memory_profiler_running)
+ if (profiler_memory_running)
error ("Memory profiler is already running");
if (NILP (memory_log))
- memory_log = make_log (profiler_slot_heap_size,
+ memory_log = make_log (profiler_log_size,
profiler_max_stack_depth);
- memory_profiler_running = 1;
+ profiler_memory_running = true;
return Qt;
}
-DEFUN ("memory-profiler-stop",
- Fmemory_profiler_stop, Smemory_profiler_stop,
+DEFUN ("profiler-memory-stop",
+ Fprofiler_memory_stop, Sprofiler_memory_stop,
0, 0, 0,
- doc: /* Stop memory profiler. Profiler log will be kept. */)
+ doc: /* Stop the memory profiler. The profiler log is not affected.
+Return non-nil if the profiler was running. */)
(void)
{
- if (!memory_profiler_running)
- error ("Memory profiler is not running");
- memory_profiler_running = 0;
-
+ if (!profiler_memory_running)
+ return Qnil;
+ profiler_memory_running = false;
return Qt;
}
-DEFUN ("memory-profiler-running-p",
- Fmemory_profiler_running_p, Smemory_profiler_running_p,
+DEFUN ("profiler-memory-running-p",
+ Fprofiler_memory_running_p, Sprofiler_memory_running_p,
0, 0, 0,
- doc: /* Return t if memory profiler is running. */)
+ doc: /* Return non-nil if memory profiler is running. */)
(void)
{
- return memory_profiler_running ? Qt : Qnil;
+ return profiler_memory_running ? Qt : Qnil;
}
-DEFUN ("memory-profiler-log",
- Fmemory_profiler_log, Smemory_profiler_log,
+DEFUN ("profiler-memory-log",
+ Fprofiler_memory_log, Sprofiler_memory_log,
0, 0, 0,
- doc: /* Return memory profiler log. The data is a list of
-(memory nil TIMESTAMP SLOTS), where TIMESTAMP is a timestamp when the
-log is collected and SLOTS is a list of slots. */)
+ doc: /* Return the current memory profiler log.
+The log is a hash-table mapping backtraces to counters which represent
+the amount of memory allocated at those points. Every backtrace is a vector
+of functions, where the last few elements may be nil.
+Before returning, a new log is allocated for future samples. */)
(void)
{
Lisp_Object result = memory_log;
/* 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. */
- memory_log = (memory_profiler_running
- ? make_log (profiler_slot_heap_size, profiler_max_stack_depth)
+ memory_log = (profiler_memory_running
+ ? make_log (profiler_log_size, profiler_max_stack_depth)
: Qnil);
return result;
}
\f
/* Signals and probes. */
-/* Signal handler for sample profiler. */
-
-static void
-sigprof_handler (int signal, siginfo_t *info, void *ctx)
-{
- 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.
- 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;
- else
- record_backtrace (XHASH_TABLE (cpu_log), current_sample_interval);
-}
-
/* Record that the current backtrace allocated SIZE bytes. */
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
syms_of_profiler (void)
{
DEFVAR_INT ("profiler-max-stack-depth", profiler_max_stack_depth,
- doc: /* FIXME */);
+ doc: /* Number of elements from the call-stack recorded in the log. */);
profiler_max_stack_depth = 16;
- DEFVAR_INT ("profiler-slot-heap-size", profiler_slot_heap_size,
- doc: /* FIXME */);
- profiler_slot_heap_size = 10000;
+ DEFVAR_INT ("profiler-log-size", profiler_log_size,
+ doc: /* Number of distinct call-stacks that can be recorded in a profiler log.
+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;
- /* FIXME: Rename things to start with "profiler-", to use "cpu" instead of
- "sample", and to make them sound like they're internal or something. */
#ifdef PROFILER_CPU_SUPPORT
+ profiler_cpu_running = NOT_RUNNING;
cpu_log = Qnil;
staticpro (&cpu_log);
- defsubr (&Ssample_profiler_start);
- defsubr (&Ssample_profiler_stop);
- defsubr (&Ssample_profiler_running_p);
- defsubr (&Ssample_profiler_log);
+ defsubr (&Sprofiler_cpu_start);
+ defsubr (&Sprofiler_cpu_stop);
+ defsubr (&Sprofiler_cpu_running_p);
+ defsubr (&Sprofiler_cpu_log);
#endif
+ profiler_memory_running = false;
memory_log = Qnil;
staticpro (&memory_log);
- defsubr (&Smemory_profiler_start);
- defsubr (&Smemory_profiler_stop);
- defsubr (&Smemory_profiler_running_p);
- defsubr (&Smemory_profiler_log);
+ defsubr (&Sprofiler_memory_start);
+ defsubr (&Sprofiler_memory_stop);
+ defsubr (&Sprofiler_memory_running_p);
+ defsubr (&Sprofiler_memory_log);
}