profiler.c 13.5 KB
Newer Older
1
/* Profiler implementation.
2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27

Copyright (C) 2012 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 <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"

28
/* Logs.  */
29

30
typedef struct Lisp_Hash_Table log_t;
31 32

static Lisp_Object
33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51
make_log (int heap_size, int max_stack_depth)
{
  /* 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.  */
  Lisp_Object log = make_hash_table (Qequal, make_number (heap_size),
				     make_float (DEFAULT_REHASH_SIZE),
				     make_float (DEFAULT_REHASH_THRESHOLD),
				     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
     with the vectors we'll put in them.  */
  int i = ASIZE (h->key_and_value) / 2;
  while (0 < i)
    set_hash_key_slot (h, --i,
		       Fmake_vector (make_number (max_stack_depth), Qnil));
  return log;
52 53
}

54
/* Evict the least used half of the hash_table.
55

56 57 58
   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).
59

60 61 62 63
   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 :-(
64

65 66 67 68
   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.  */
69

70 71
static EMACS_INT approximate_median (log_t *log,
				     ptrdiff_t start, ptrdiff_t size)
72
{
73 74 75 76 77 78 79 80 81
  eassert (size > 0);
  if (size < 2)
    return XINT (HASH_VALUE (log, start));
  if (size < 3)
    /* Not an actual median, but better for our application than
       choosing either of the two numbers.  */
    return ((XINT (HASH_VALUE (log, start))
	     + XINT (HASH_VALUE (log, start + 1)))
	    / 2);
82 83
  else
    {
84 85 86 87 88 89 90 91 92
      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)));
93 94 95
    }
}

96
static void evict_lower_half (log_t *log)
97
{
98 99 100
  ptrdiff_t size = ASIZE (log->key_and_value) / 2;
  EMACS_INT median = approximate_median (log, 0, size);
  ptrdiff_t i;
101 102

  for (i = 0; i < size; i++)
103 104 105 106 107 108 109 110 111 112 113 114 115 116 117
    /* Evict not only values smaller but also values equal to the median,
       so as to make sure we evict something no matter what.  */
    if (XINT (HASH_VALUE (log, i)) <= median)
      {
	Lisp_Object key = HASH_KEY (log, i);
	{ /* FIXME: we could make this more efficient.  */
	  Lisp_Object tmp;
	  XSET_HASH_TABLE (tmp, log); /* FIXME: Use make_lisp_ptr.  */
	  Fremhash (key, tmp);
	}
	eassert (EQ (log->next_free, make_number (i)));
	{
	  int j;
	  eassert (VECTORP (key));
	  for (j = 0; j < ASIZE (key); j++)
118
	    ASET (key, j, Qnil);
119 120 121
	}
	set_hash_key_slot (log, i, key);
      }
122 123
}

124 125 126 127 128 129
/* 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.  */

130
static void
131
record_backtrace (log_t *log, size_t count)
132 133
{
  struct backtrace *backlist = backtrace_list;
134 135 136
  Lisp_Object backtrace;
  ptrdiff_t index, i = 0;
  ptrdiff_t asize;
137

138
  if (!INTEGERP (log->next_free))
139 140
    /* FIXME: transfer the evicted counts to a special entry rather
       than dropping them on the floor.  */
141 142
    evict_lower_half (log);
  index = XINT (log->next_free);
143

144 145 146
  /* Get a "working memory" vector.  */
  backtrace = HASH_KEY (log, index);
  asize = ASIZE (backtrace);
Tomohiro Matsuyama's avatar
Tomohiro Matsuyama committed
147

148
  /* Copy the backtrace contents into working memory.  */
149
  for (; i < asize && backlist; i++, backlist = backlist->next)
150
    /* FIXME: For closures we should ignore the environment.  */
151
    ASET (backtrace, i, *backlist->function);
152

153 154 155
  /* Make sure that unused space of working memory is filled with nil.  */
  for (; i < asize; i++)
    ASET (backtrace, i, Qnil);
156

157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177
  { /* 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.  */
    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))));
    else
      { /* BEWARE!  hash_put in general can allocate memory.
	   But currently it only does that if log->next_free is nil.  */
	int j;
	eassert (!NILP (log->next_free));
	j = hash_put (log, backtrace, make_number (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
178 179 180 181 182 183 184 185 186 187 188 189
	   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.  */
190 191
      }
  }
192 193
}

194
/* Sample profiler.  */
195

196 197 198
#if defined SIGPROF && defined HAVE_SETITIMER
#define PROFILER_CPU_SUPPORT

199 200 201
/* True if sampling profiler is running.  */
static bool profiler_cpu_running;

202 203 204
static Lisp_Object cpu_log;
/* Separate counter for the time spent in the GC.  */
static EMACS_INT cpu_gc_count;
205 206 207

/* The current sample interval in millisecond.  */

208 209
static int current_sample_interval;

210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228
/* 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);
}

DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start,
229
       1, 1, 0,
230 231 232
       doc: /* Start or restart the cpu profiler.
The cpu profiler will take call-stack samples each SAMPLE-INTERVAL (expressed in milliseconds).
See also `profiler-log-size' and `profiler-max-stack-depth'.  */)
233 234 235 236 237
  (Lisp_Object sample_interval)
{
  struct sigaction sa;
  struct itimerval timer;

238
  if (profiler_cpu_running)
239 240
    error ("Sample profiler is already running");

241 242 243
  if (NILP (cpu_log))
    {
      cpu_gc_count = 0;
244
      cpu_log = make_log (profiler_log_size,
245 246
			  profiler_max_stack_depth);
    }
247 248 249 250 251 252 253 254 255 256 257 258 259

  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);

260
  profiler_cpu_running = 1;
261 262 263 264

  return Qt;
}

265
DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop,
266
       0, 0, 0,
267
       doc: /* Stop the cpu profiler.  The profiler log is not affected.  */)
268 269
  (void)
{
270
  if (!profiler_cpu_running)
271
    error ("Sample profiler is not running");
272
  profiler_cpu_running = 0;
273 274 275 276 277 278

  setitimer (ITIMER_PROF, 0, 0);

  return Qt;
}

279 280
DEFUN ("profiler-cpu-running-p",
       Fprofiler_cpu_running_p, Sprofiler_cpu_running_p,
281
       0, 0, 0,
282
       doc: /* Return non-nil iff cpu profiler is running.  */)
283 284
  (void)
{
285
  return profiler_cpu_running ? Qt : Qnil;
286 287
}

288
DEFUN ("profiler-cpu-log", Fprofiler_cpu_log, Sprofiler_cpu_log,
289
       0, 0, 0,
290 291 292 293 294
       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.  */)
295 296
  (void)
{
297 298 299 300
  Lisp_Object result = cpu_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.  */
301 302
  cpu_log = (profiler_cpu_running
	     ? make_log (profiler_log_size, profiler_max_stack_depth)
303 304 305 306 307
	     : Qnil);
  Fputhash (Fmake_vector (make_number (1), Qautomatic_gc),
	    make_number (cpu_gc_count),
	    result);
  cpu_gc_count = 0;
308 309
  return result;
}
310
#endif	/* not defined PROFILER_CPU_SUPPORT */
311

312
/* Memory profiler.  */
313

314 315 316
/* True if memory profiler is running.  */
bool profiler_memory_running;

317
static Lisp_Object memory_log;
318

319
DEFUN ("profiler-memory-start", Fprofiler_memory_start, Sprofiler_memory_start,
320
       0, 0, 0,
321 322 323 324 325
       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'.  */)
326 327
  (void)
{
328
  if (profiler_memory_running)
329 330
    error ("Memory profiler is already running");

331
  if (NILP (memory_log))
332
    memory_log = make_log (profiler_log_size,
333 334
			   profiler_max_stack_depth);

335
  profiler_memory_running = 1;
336 337 338 339

  return Qt;
}

340 341
DEFUN ("profiler-memory-stop",
       Fprofiler_memory_stop, Sprofiler_memory_stop,
342
       0, 0, 0,
343
       doc: /* Stop the memory profiler.  The profiler log is not affected.  */)
344 345
  (void)
{
346
  if (!profiler_memory_running)
347
    error ("Memory profiler is not running");
348
  profiler_memory_running = 0;
349 350 351 352

  return Qt;
}

353 354
DEFUN ("profiler-memory-running-p",
       Fprofiler_memory_running_p, Sprofiler_memory_running_p,
355
       0, 0, 0,
356
       doc: /* Return non-nil if memory profiler is running.  */)
357 358
  (void)
{
359
  return profiler_memory_running ? Qt : Qnil;
360 361
}

362 363
DEFUN ("profiler-memory-log",
       Fprofiler_memory_log, Sprofiler_memory_log,
364
       0, 0, 0,
365 366 367 368 369
       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.  */)
370 371
  (void)
{
372 373 374 375
  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.  */
376 377
  memory_log = (profiler_memory_running
		? make_log (profiler_log_size, profiler_max_stack_depth)
378
		: Qnil);
379 380 381 382
  return result;
}


383
/* Signals and probes.  */
384

385
/* Record that the current backtrace allocated SIZE bytes.  */
386 387 388
void
malloc_probe (size_t size)
{
389 390
  eassert (HASH_TABLE_P (memory_log));
  record_backtrace (XHASH_TABLE (memory_log), size);
391 392 393 394 395 396
}

void
syms_of_profiler (void)
{
  DEFVAR_INT ("profiler-max-stack-depth", profiler_max_stack_depth,
397
	      doc: /* Number of elements from the call-stack recorded in the log.  */);
398
  profiler_max_stack_depth = 16;
399 400 401 402 403
  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;
404

405 406 407
#ifdef PROFILER_CPU_SUPPORT
  cpu_log = Qnil;
  staticpro (&cpu_log);
408 409 410 411
  defsubr (&Sprofiler_cpu_start);
  defsubr (&Sprofiler_cpu_stop);
  defsubr (&Sprofiler_cpu_running_p);
  defsubr (&Sprofiler_cpu_log);
412 413 414
#endif
  memory_log = Qnil;
  staticpro (&memory_log);
415 416 417 418
  defsubr (&Sprofiler_memory_start);
  defsubr (&Sprofiler_memory_stop);
  defsubr (&Sprofiler_memory_running_p);
  defsubr (&Sprofiler_memory_log);
419
}