/* Profiler implementation. Copyright (C) 2012-2023 Free Software Foundation, Inc. This file is part of GNU Emacs. GNU Emacs is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, either version 3 of the License, or (at your option) any later version. GNU Emacs is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with GNU Emacs. If not, see . */ #include #include "lisp.h" #include "syssignal.h" #include "systime.h" #include "pdumper.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 cmpfn_profiler (Lisp_Object, Lisp_Object, struct Lisp_Hash_Table *); static Lisp_Object hashfn_profiler (Lisp_Object, struct Lisp_Hash_Table *); static const struct hash_table_test hashtest_profiler = { LISPSYM_INITIALLY (Qprofiler_backtrace_equal), LISPSYM_INITIALLY (Qnil) /* user_hash_function */, LISPSYM_INITIALLY (Qnil) /* user_cmp_function */, cmpfn_profiler, hashfn_profiler, }; struct profiler_log { Lisp_Object log; EMACS_INT gc_count; /* Samples taken during GC. */ EMACS_INT discarded; /* Samples evicted during table overflow. */ }; static struct profiler_log make_log (void) { /* We use a standard Elisp hash-table object, but we use it in 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. */ EMACS_INT heap_size = clip_to_bounds (0, profiler_log_size, MOST_POSITIVE_FIXNUM); ptrdiff_t max_stack_depth = clip_to_bounds (0, profiler_max_stack_depth, PTRDIFF_MAX);; struct profiler_log log = { make_hash_table (hashtest_profiler, heap_size, DEFAULT_REHASH_SIZE, DEFAULT_REHASH_THRESHOLD, Qnil, false), 0, 0 }; struct Lisp_Hash_Table *h = XHASH_TABLE (log.log); /* What is special about our hash-tables is that the values are pre-filled with the vectors we'll use as keys. */ ptrdiff_t i = ASIZE (h->key_and_value) >> 1; while (i > 0) set_hash_value_slot (h, --i, make_nil_vector (max_stack_depth)); return log; } /* Evict the least used half of the hash_table. When the table is full, we have to evict someone. The easiest and most efficient is to evict the value we're about to add (i.e. once the table is full, stop sampling). We could also pick the element with the lowest count and evict it, but finding it is O(N) and for that amount of work we get very little in return: for the next sample, this latest sample will have count==1 and will hence be a prime candidate for eviction :-( So instead, we take O(N) time to eliminate more or less half of the entries (the half with the lowest counts). So we get an amortized cost of O(1) and we get O(N) time for a new entry to grow larger than the other least counts before a new round of eviction. */ static EMACS_INT approximate_median (log_t *log, ptrdiff_t start, ptrdiff_t size) { eassert (size > 0); if (size < 2) return XFIXNUM (HASH_VALUE (log, start)); if (size < 3) /* Not an actual median, but better for our application than choosing either of the two numbers. */ return ((XFIXNUM (HASH_VALUE (log, start)) + XFIXNUM (HASH_VALUE (log, start + 1))) / 2); else { ptrdiff_t newsize = size / 3; ptrdiff_t start2 = start + newsize; EMACS_INT i1 = approximate_median (log, start, newsize); EMACS_INT i2 = approximate_median (log, start2, newsize); EMACS_INT i3 = approximate_median (log, start2 + newsize, size - 2 * newsize); return (i1 < i2 ? (i2 < i3 ? i2 : (i1 < i3 ? i3 : i1)) : (i1 < i3 ? i1 : (i2 < i3 ? i3 : i2))); } } static void evict_lower_half (struct profiler_log *plog) { log_t *log = XHASH_TABLE (plog->log); ptrdiff_t size = ASIZE (log->key_and_value) / 2; EMACS_INT median = approximate_median (log, 0, size); for (ptrdiff_t i = 0; i < size; i++) /* Evict not only values smaller but also values equal to the median, so as to make sure we evict something no matter what. */ if (XFIXNUM (HASH_VALUE (log, i)) <= median) { Lisp_Object key = HASH_KEY (log, i); EMACS_INT count = XFIXNUM (HASH_VALUE (log, i)); plog->discarded = saturated_add (plog->discarded, count); { /* FIXME: we could make this more efficient. */ Lisp_Object tmp; XSET_HASH_TABLE (tmp, log); /* FIXME: Use make_lisp_ptr. */ Fremhash (key, tmp); } eassert (BASE_EQ (Qunbound, HASH_KEY (log, i))); eassert (log->next_free == i); eassert (VECTORP (key)); for (ptrdiff_t j = 0; j < ASIZE (key); j++) ASET (key, j, Qnil); set_hash_value_slot (log, i, key); } } /* 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 (struct profiler_log *plog, EMACS_INT count) { eassert (HASH_TABLE_P (plog->log)); log_t *log = XHASH_TABLE (plog->log); if (log->next_free < 0) evict_lower_half (plog); ptrdiff_t index = log->next_free; /* Get a "working memory" vector. */ Lisp_Object backtrace = HASH_VALUE (log, index); eassert (BASE_EQ (Qunbound, HASH_KEY (log, index))); get_backtrace (backtrace); { /* We basically do a `gethash+puthash' here, except that we have to be careful to avoid memory allocation since we're in a signal handler, and we optimize the code to try and avoid computing the hash+lookup twice. See fns.c:Fputhash for reference. */ Lisp_Object hash; ptrdiff_t j = hash_lookup (log, backtrace, &hash); if (j >= 0) { EMACS_INT old_val = XFIXNUM (HASH_VALUE (log, j)); EMACS_INT new_val = saturated_add (old_val, count); set_hash_value_slot (log, j, make_fixnum (new_val)); } else { /* BEWARE! hash_put in general can allocate memory. But currently it only does that if log->next_free is -1. */ eassert (0 <= log->next_free); ptrdiff_t j = hash_put (log, backtrace, make_fixnum (count), hash); /* Let's make sure we've put `backtrace' right where it already was to start with. */ eassert (index == j); /* 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. There are 2 ways to do that, AFAICT: - Set a flag checked in maybe_quit, such that maybe_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. */ } } } /* 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 /* Status of sampling profiler. */ static enum profiler_cpu_running { NOT_RUNNING, #ifdef HAVE_ITIMERSPEC TIMER_SETTIME_RUNNING, #endif SETITIMER_RUNNING } profiler_cpu_running; /* Hash-table log of CPU profiler. */ static struct profiler_log cpu; /* Hash-table log of Memory profiler. */ static struct profiler_log memory; /* The current sampling interval in nanoseconds. */ static EMACS_INT current_sampling_interval; /* Signal handler for sampling profiler. */ static void add_sample (struct profiler_log *plog, EMACS_INT count) { if (EQ (backtrace_top_function (), QAutomatic_GC)) /* bug#60237 */ /* 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. */ plog->gc_count = saturated_add (plog->gc_count, count); else record_backtrace (plog, count); } static void handle_profiler_signal (int signal) { EMACS_INT count = 1; #if defined HAVE_ITIMERSPEC && defined HAVE_TIMER_GETOVERRUN if (profiler_timer_ok) { int overruns = timer_getoverrun (profiler_timer); eassert (overruns >= 0); count += overruns; } #endif add_sample (&cpu, count); } static void deliver_profiler_signal (int signal) { deliver_process_signal (signal, handle_profiler_signal); } static int setup_cpu_timer (Lisp_Object sampling_interval) { int billion = 1000000000; if (! RANGED_FIXNUMP (1, sampling_interval, (TYPE_MAXIMUM (time_t) < EMACS_INT_MAX / billion ? ((EMACS_INT) TYPE_MAXIMUM (time_t) * billion + (billion - 1)) : EMACS_INT_MAX))) return -1; current_sampling_interval = XFIXNUM (sampling_interval); struct timespec interval = make_timespec (current_sampling_interval / billion, current_sampling_interval % billion); struct sigaction action; 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 }; struct sigevent sigev; sigev.sigev_value.sival_ptr = &profiler_timer; sigev.sigev_signo = SIGPROF; sigev.sigev_notify = SIGEV_SIGNAL; for (int i = 0; i < ARRAYELTS (system_clock); i++) if (timer_create (system_clock[i], &sigev, &profiler_timer) == 0) { profiler_timer_ok = true; 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 struct itimerval timer; 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 = make_log (); int status = setup_cpu_timer (sampling_interval); if (status < 0) { profiler_cpu_running = NOT_RUNNING; error ("Invalid sampling interval"); } else { profiler_cpu_running = status; if (! profiler_cpu_running) error ("Unable to start profiler timer"); } 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. Return non-nil if the profiler was running. */) (void) { switch (profiler_cpu_running) { case NOT_RUNNING: return Qnil; #ifdef HAVE_ITIMERSPEC case TIMER_SETTIME_RUNNING: { struct itimerspec disable = { 0, }; timer_settime (profiler_timer, 0, &disable, 0); } break; #endif #ifdef HAVE_SETITIMER case SETITIMER_RUNNING: { struct itimerval disable = { 0, }; setitimer (ITIMER_PROF, &disable, 0); } break; #endif } signal (SIGPROF, SIG_IGN); profiler_cpu_running = NOT_RUNNING; return Qt; } DEFUN ("profiler-cpu-running-p", Fprofiler_cpu_running_p, Sprofiler_cpu_running_p, 0, 0, 0, doc: /* Return non-nil if cpu profiler is running. */) (void) { return profiler_cpu_running ? Qt : Qnil; } static Lisp_Object export_log (struct profiler_log *log) { Lisp_Object result = log->log; if (log->gc_count) Fputhash (CALLN (Fvector, QAutomatic_GC, Qnil), make_fixnum (log->gc_count), result); if (log->discarded) Fputhash (CALLN (Fvector, QDiscarded_Samples, Qnil), make_fixnum (log->discarded), result); /* 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. */ if (profiler_cpu_running) *log = make_log (); return result; } DEFUN ("profiler-cpu-log", Fprofiler_cpu_log, Sprofiler_cpu_log, 0, 0, 0, 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) { return (export_log (&cpu)); } #endif /* PROFILER_CPU_SUPPORT */ /* Memory profiler. */ /* True if memory profiler is running. */ bool profiler_memory_running; DEFUN ("profiler-memory-start", Fprofiler_memory_start, Sprofiler_memory_start, 0, 0, 0, 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 (profiler_memory_running) error ("Memory profiler is already running"); if (NILP (memory.log)) memory = make_log (); profiler_memory_running = true; return Qt; } DEFUN ("profiler-memory-stop", Fprofiler_memory_stop, Sprofiler_memory_stop, 0, 0, 0, doc: /* Stop the memory profiler. The profiler log is not affected. Return non-nil if the profiler was running. */) (void) { if (!profiler_memory_running) return Qnil; profiler_memory_running = false; return Qt; } DEFUN ("profiler-memory-running-p", Fprofiler_memory_running_p, Sprofiler_memory_running_p, 0, 0, 0, doc: /* Return non-nil if memory profiler is running. */) (void) { return profiler_memory_running ? Qt : Qnil; } DEFUN ("profiler-memory-log", Fprofiler_memory_log, Sprofiler_memory_log, 0, 0, 0, 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) { return (export_log (&memory)); } /* Signals and probes. */ /* Record that the current backtrace allocated SIZE bytes. */ void malloc_probe (size_t size) { add_sample (&memory, 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 Lisp_Object cmpfn_profiler (Lisp_Object bt1, Lisp_Object bt2, struct Lisp_Hash_Table *h) { if (EQ (bt1, bt2)) return Qt; else if (VECTORP (bt1) && VECTORP (bt2)) { ptrdiff_t l = ASIZE (bt1); if (l != ASIZE (bt2)) return Qnil; for (ptrdiff_t i = 0; i < l; i++) if (NILP (Ffunction_equal (AREF (bt1, i), AREF (bt2, i)))) return Qnil; return Qt; } else return Qnil; } static Lisp_Object hashfn_profiler (Lisp_Object bt, struct Lisp_Hash_Table *h) { EMACS_UINT hash; if (VECTORP (bt)) { hash = 0; ptrdiff_t l = ASIZE (bt); for (ptrdiff_t 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); } } else hash = XHASH (bt); return make_ufixnum (SXHASH_REDUCE (hash)); } static void syms_of_profiler_for_pdumper (void); void syms_of_profiler (void) { DEFVAR_INT ("profiler-max-stack-depth", profiler_max_stack_depth, doc: /* Number of elements from the call-stack recorded in the log. */); profiler_max_stack_depth = 16; 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; DEFSYM (Qprofiler_backtrace_equal, "profiler-backtrace-equal"); DEFSYM (QDiscarded_Samples, "Discarded Samples"); defsubr (&Sfunction_equal); #ifdef PROFILER_CPU_SUPPORT profiler_cpu_running = NOT_RUNNING; cpu.log = Qnil; staticpro (&cpu.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 (&Sprofiler_memory_start); defsubr (&Sprofiler_memory_stop); defsubr (&Sprofiler_memory_running_p); defsubr (&Sprofiler_memory_log); pdumper_do_now_and_after_load (syms_of_profiler_for_pdumper); } static void syms_of_profiler_for_pdumper (void) { if (dumped_with_pdumper_p ()) { #ifdef PROFILER_CPU_SUPPORT cpu.log = Qnil; #endif memory.log = Qnil; } else { #ifdef PROFILER_CPU_SUPPORT eassert (NILP (cpu.log)); #endif eassert (NILP (memory.log)); } }