profiler.c 18 KB
Newer Older
1
/* Profiler implementation.
2

Paul Eggert's avatar
Paul Eggert committed
3
Copyright (C) 2012-2015 Free Software Foundation, Inc.
4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

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 "lisp.h"
22
#include "syssignal.h"
23 24 25 26 27 28 29 30 31 32
#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);
}
33

34
/* Logs.  */
35

36
typedef struct Lisp_Hash_Table log_t;
37

38 39
static struct hash_table_test hashtest_profiler;

40
static Lisp_Object
41 42 43 44 45 46
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.  */
47 48
  Lisp_Object log = make_hash_table (hashtest_profiler,
				     make_number (heap_size),
49 50
				     make_float (DEFAULT_REHASH_SIZE),
				     make_float (DEFAULT_REHASH_THRESHOLD),
51
				     Qnil);
52 53 54 55 56
  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;
57
  while (i > 0)
58 59 60
    set_hash_key_slot (h, --i,
		       Fmake_vector (make_number (max_stack_depth), Qnil));
  return log;
61 62
}

63
/* Evict the least used half of the hash_table.
64

65 66 67
   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).
68

69 70 71 72
   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 :-(
73

74 75 76 77
   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.  */
78

79 80
static EMACS_INT approximate_median (log_t *log,
				     ptrdiff_t start, ptrdiff_t size)
81
{
82 83 84 85 86 87 88 89 90
  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);
91 92
  else
    {
93 94 95 96 97 98 99 100 101
      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)));
102 103 104
    }
}

105
static void evict_lower_half (log_t *log)
106
{
107 108 109
  ptrdiff_t size = ASIZE (log->key_and_value) / 2;
  EMACS_INT median = approximate_median (log, 0, size);
  ptrdiff_t i;
110 111

  for (i = 0; i < size; i++)
112 113 114 115 116 117 118 119 120 121 122 123 124 125 126
    /* 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++)
127
	    ASET (key, j, Qnil);
128 129 130
	}
	set_hash_key_slot (log, i, key);
      }
131 132
}

133
/* Record the current backtrace in LOG.  COUNT is the weight of this
134 135
   current backtrace: interrupt counts for CPU, and the allocation
   size for memory.  */
136

137
static void
138
record_backtrace (log_t *log, EMACS_INT count)
139
{
140
  Lisp_Object backtrace;
141
  ptrdiff_t index;
142

143
  if (!INTEGERP (log->next_free))
144 145
    /* FIXME: transfer the evicted counts to a special entry rather
       than dropping them on the floor.  */
146 147
    evict_lower_half (log);
  index = XINT (log->next_free);
148

149 150
  /* Get a "working memory" vector.  */
  backtrace = HASH_KEY (log, index);
151
  get_backtrace (backtrace);
152

153 154 155 156 157 158 159
  { /* 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)
160 161 162 163 164
      {
	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));
      }
165 166 167 168 169 170 171 172 173 174 175 176
    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
177 178 179 180 181 182 183 184 185 186 187 188
	   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.  */
189 190
      }
  }
191 192
}

193
/* Sampling profiler.  */
194

195 196 197 198
#ifdef PROFILER_CPU_SUPPORT

/* The profiler timer and whether it was properly initialized, if
   POSIX timers are available.  */
199
#ifdef HAVE_ITIMERSPEC
200 201 202
static timer_t profiler_timer;
static bool profiler_timer_ok;
#endif
203

204 205 206 207
/* Status of sampling profiler.  */
static enum profiler_cpu_running
  { NOT_RUNNING, TIMER_SETTIME_RUNNING, SETITIMER_RUNNING }
  profiler_cpu_running;
208

209
/* Hash-table log of CPU profiler.  */
210
static Lisp_Object cpu_log;
211

212 213
/* Separate counter for the time spent in the GC.  */
static EMACS_INT cpu_gc_count;
214

215
/* The current sampling interval in nanoseconds.  */
216
static EMACS_INT current_sampling_interval;
217

218
/* Signal handler for sampling profiler.  */
219

Ken Brown's avatar
Ken Brown committed
220 221 222 223 224 225
/* timer_getoverrun is not implemented on Cygwin, but the following
   seems to be good enough for profiling. */
#ifdef CYGWIN
#define timer_getoverrun(x) 0
#endif

226
static void
227
handle_profiler_signal (int signal)
228
{
229
  if (EQ (backtrace_top_function (), Qautomatic_gc))
230 231 232 233 234 235
    /* 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.  */
236
    cpu_gc_count = saturated_add (cpu_gc_count, 1);
237
  else
238
    {
239
      EMACS_INT count = 1;
240
#ifdef HAVE_ITIMERSPEC
241 242 243
      if (profiler_timer_ok)
	{
	  int overruns = timer_getoverrun (profiler_timer);
244
	  eassert (overruns >= 0);
245 246 247
	  count += overruns;
	}
#endif
248
      eassert (HASH_TABLE_P (cpu_log));
249
      record_backtrace (XHASH_TABLE (cpu_log), count);
250
    }
251 252
}

253
static void
254 255 256 257 258
deliver_profiler_signal (int signal)
{
  deliver_process_signal (signal, handle_profiler_signal);
}

259
static int
260
setup_cpu_timer (Lisp_Object sampling_interval)
261
{
262 263 264
  struct sigaction action;
  struct itimerval timer;
  struct timespec interval;
265
  int billion = 1000000000;
266

267
  if (! RANGED_INTEGERP (1, sampling_interval,
268 269 270
			 (TYPE_MAXIMUM (time_t) < EMACS_INT_MAX / billion
			  ? ((EMACS_INT) TYPE_MAXIMUM (time_t) * billion
			     + (billion - 1))
271
			  : EMACS_INT_MAX)))
272
    return -1;
273

274
  current_sampling_interval = XINT (sampling_interval);
275 276
  interval = make_timespec (current_sampling_interval / billion,
			    current_sampling_interval % billion);
277 278 279
  emacs_sigaction_init (&action, deliver_profiler_signal);
  sigaction (SIGPROF, &action, 0);

280
#ifdef HAVE_ITIMERSPEC
281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301
  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;

302
      for (i = 0; i < ARRAYELTS (system_clock); i++)
303 304 305 306 307 308 309 310 311 312 313
	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;
314 315
      if (timer_settime (profiler_timer, 0, &ispec, 0) == 0)
	return TIMER_SETTIME_RUNNING;
316 317 318
    }
#endif

319
#ifdef HAVE_SETITIMER
320
  timer.it_value = timer.it_interval = make_timeval (interval);
321 322 323 324 325
  if (setitimer (ITIMER_PROF, &timer, 0) == 0)
    return SETITIMER_RUNNING;
#endif

  return NOT_RUNNING;
326 327
}

328
DEFUN ("profiler-cpu-start", Fprofiler_cpu_start, Sprofiler_cpu_start,
329
       1, 1, 0,
330
       doc: /* Start or restart the cpu profiler.
331
It takes call-stack samples each SAMPLING-INTERVAL nanoseconds, approximately.
332
See also `profiler-log-size' and `profiler-max-stack-depth'.  */)
333
  (Lisp_Object sampling_interval)
334
{
335
  if (profiler_cpu_running)
336
    error ("CPU profiler is already running");
337

338 339 340
  if (NILP (cpu_log))
    {
      cpu_gc_count = 0;
341
      cpu_log = make_log (profiler_log_size,
342 343
			  profiler_max_stack_depth);
    }
344

345 346 347 348 349 350 351 352 353 354 355 356
  int status = setup_cpu_timer (sampling_interval);
  if (status == -1)
    {
      profiler_cpu_running = NOT_RUNNING;
      error ("Invalid sampling interval");
    }
  else
    {
      profiler_cpu_running = status;
      if (! profiler_cpu_running)
	error ("Unable to start profiler timer");
    }
357 358 359 360

  return Qt;
}

361
DEFUN ("profiler-cpu-stop", Fprofiler_cpu_stop, Sprofiler_cpu_stop,
362
       0, 0, 0,
363 364
       doc: /* Stop the cpu profiler.  The profiler log is not affected.
Return non-nil if the profiler was running.  */)
365 366
  (void)
{
367 368 369 370 371
  switch (profiler_cpu_running)
    {
    case NOT_RUNNING:
      return Qnil;

372
#ifdef HAVE_ITIMERSPEC
373 374 375 376 377 378 379
    case TIMER_SETTIME_RUNNING:
      {
	struct itimerspec disable;
	memset (&disable, 0, sizeof disable);
	timer_settime (profiler_timer, 0, &disable, 0);
      }
      break;
380
#endif
381

382
#ifdef HAVE_SETITIMER
383 384 385 386 387 388 389
    case SETITIMER_RUNNING:
      {
	struct itimerval disable;
	memset (&disable, 0, sizeof disable);
	setitimer (ITIMER_PROF, &disable, 0);
      }
      break;
390
#endif
391
    }
392

393 394
  signal (SIGPROF, SIG_IGN);
  profiler_cpu_running = NOT_RUNNING;
395 396 397
  return Qt;
}

398 399
DEFUN ("profiler-cpu-running-p",
       Fprofiler_cpu_running_p, Sprofiler_cpu_running_p,
400
       0, 0, 0,
Glenn Morris's avatar
Glenn Morris committed
401
       doc: /* Return non-nil if cpu profiler is running.  */)
402 403
  (void)
{
404
  return profiler_cpu_running ? Qt : Qnil;
405 406
}

407
DEFUN ("profiler-cpu-log", Fprofiler_cpu_log, Sprofiler_cpu_log,
408
       0, 0, 0,
409 410 411 412 413
       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.  */)
414 415
  (void)
{
416
  Lisp_Object result = cpu_log;
417
  /* Here we're making the log visible to Elisp, so it's not safe any
418 419
     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.  */
420 421
  cpu_log = (profiler_cpu_running
	     ? make_log (profiler_log_size, profiler_max_stack_depth)
422 423 424 425 426
	     : Qnil);
  Fputhash (Fmake_vector (make_number (1), Qautomatic_gc),
	    make_number (cpu_gc_count),
	    result);
  cpu_gc_count = 0;
427 428
  return result;
}
429
#endif /* PROFILER_CPU_SUPPORT */
430

431
/* Memory profiler.  */
432

433 434 435
/* True if memory profiler is running.  */
bool profiler_memory_running;

436
static Lisp_Object memory_log;
437

438
DEFUN ("profiler-memory-start", Fprofiler_memory_start, Sprofiler_memory_start,
439
       0, 0, 0,
440 441 442 443 444
       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'.  */)
445 446
  (void)
{
447
  if (profiler_memory_running)
448 449
    error ("Memory profiler is already running");

450
  if (NILP (memory_log))
451
    memory_log = make_log (profiler_log_size,
452 453
			   profiler_max_stack_depth);

454
  profiler_memory_running = true;
455 456 457 458

  return Qt;
}

459 460
DEFUN ("profiler-memory-stop",
       Fprofiler_memory_stop, Sprofiler_memory_stop,
461
       0, 0, 0,
462 463
       doc: /* Stop the memory profiler.  The profiler log is not affected.
Return non-nil if the profiler was running.  */)
464 465
  (void)
{
466
  if (!profiler_memory_running)
467 468
    return Qnil;
  profiler_memory_running = false;
469 470 471
  return Qt;
}

472 473
DEFUN ("profiler-memory-running-p",
       Fprofiler_memory_running_p, Sprofiler_memory_running_p,
474
       0, 0, 0,
475
       doc: /* Return non-nil if memory profiler is running.  */)
476 477
  (void)
{
478
  return profiler_memory_running ? Qt : Qnil;
479 480
}

481 482
DEFUN ("profiler-memory-log",
       Fprofiler_memory_log, Sprofiler_memory_log,
483
       0, 0, 0,
484 485 486 487 488
       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.  */)
489 490
  (void)
{
491 492 493 494
  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.  */
495 496
  memory_log = (profiler_memory_running
		? make_log (profiler_log_size, profiler_max_stack_depth)
497
		: Qnil);
498 499 500 501
  return result;
}


502
/* Signals and probes.  */
503

504
/* Record that the current backtrace allocated SIZE bytes.  */
505 506 507
void
malloc_probe (size_t size)
{
508
  eassert (HASH_TABLE_P (memory_log));
509
  record_backtrace (XHASH_TABLE (memory_log), min (size, MOST_POSITIVE_FIXNUM));
510 511
}

512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560
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
561
	    = (COMPILEDP (f) ? XHASH (AREF (f, COMPILED_BYTECODE))
562
	       : (CONSP (f) && CONSP (XCDR (f)) && EQ (Qclosure, XCAR (f)))
563
	       ? XHASH (XCDR (XCDR (f))) : XHASH (f));
564
	  hash = sxhash_combine (hash, hash1);
565
	}
Paul Eggert's avatar
Paul Eggert committed
566
      return SXHASH_REDUCE (hash);
567 568
    }
  else
569
    return XHASH (bt);
570 571
}

572 573 574 575
void
syms_of_profiler (void)
{
  DEFVAR_INT ("profiler-max-stack-depth", profiler_max_stack_depth,
576
	      doc: /* Number of elements from the call-stack recorded in the log.  */);
577
  profiler_max_stack_depth = 16;
578 579 580 581 582
  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;
583

584
  DEFSYM (Qprofiler_backtrace_equal, "profiler-backtrace-equal");
Paul Eggert's avatar
Paul Eggert committed
585 586 587 588 589 590

  hashtest_profiler.name = Qprofiler_backtrace_equal;
  hashtest_profiler.user_hash_function = Qnil;
  hashtest_profiler.user_cmp_function = Qnil;
  hashtest_profiler.cmpfn = cmpfn_profiler;
  hashtest_profiler.hashfn = hashfn_profiler;
591 592 593

  defsubr (&Sfunction_equal);

594
#ifdef PROFILER_CPU_SUPPORT
595
  profiler_cpu_running = NOT_RUNNING;
596 597
  cpu_log = Qnil;
  staticpro (&cpu_log);
598 599 600 601
  defsubr (&Sprofiler_cpu_start);
  defsubr (&Sprofiler_cpu_stop);
  defsubr (&Sprofiler_cpu_running_p);
  defsubr (&Sprofiler_cpu_log);
602
#endif
603
  profiler_memory_running = false;
604 605
  memory_log = Qnil;
  staticpro (&memory_log);
606 607 608 609
  defsubr (&Sprofiler_memory_start);
  defsubr (&Sprofiler_memory_stop);
  defsubr (&Sprofiler_memory_running_p);
  defsubr (&Sprofiler_memory_log);
610
}