libgo/runtime/cpuprof.goc

   1 // Copyright 2011 The Go Authors.  All rights reserved.
   2 // Use of this source code is governed by a BSD-style
   3 // license that can be found in the LICENSE file.
   4
   5 // CPU profiling.
   6 // Based on algorithms and data structures used in
   7 // http://code.google.com/p/google-perftools/.
   8 //
   9 // The main difference between this code and the google-perftools
  10 // code is that this code is written to allow copying the profile data
  11 // to an arbitrary io.Writer, while the google-perftools code always
  12 // writes to an operating system file.
  13 //
  14 // The signal handler for the profiling clock tick adds a new stack trace
  15 // to a hash table tracking counts for recent traces.  Most clock ticks
  16 // hit in the cache.  In the event of a cache miss, an entry must be
  17 // evicted from the hash table, copied to a log that will eventually be
  18 // written as profile data.  The google-perftools code flushed the
  19 // log itself during the signal handler.  This code cannot do that, because
  20 // the io.Writer might block or need system calls or locks that are not
  21 // safe to use from within the signal handler.  Instead, we split the log
  22 // into two halves and let the signal handler fill one half while a goroutine
  23 // is writing out the other half.  When the signal handler fills its half, it
  24 // offers to swap with the goroutine.  If the writer is not done with its half,
  25 // we lose the stack trace for this clock tick (and record that loss).
  26 // The goroutine interacts with the signal handler by calling getprofile() to
  27 // get the next log piece to write, implicitly handing back the last log
  28 // piece it obtained.
  29 //
  30 // The state of this dance between the signal handler and the goroutine
  31 // is encoded in the Profile.handoff field.  If handoff == 0, then the goroutine
  32 // is not using either log half and is waiting (or will soon be waiting) for
  33 // a new piece by calling notesleep(&p->wait).  If the signal handler
  34 // changes handoff from 0 to non-zero, it must call notewakeup(&p->wait)
  35 // to wake the goroutine.  The value indicates the number of entries in the
  36 // log half being handed off.  The goroutine leaves the non-zero value in
  37 // place until it has finished processing the log half and then flips the number
  38 // back to zero.  Setting the high bit in handoff means that the profiling is over,
  39 // and the goroutine is now in charge of flushing the data left in the hash table
  40 // to the log and returning that data.
  41 //
  42 // The handoff field is manipulated using atomic operations.
  43 // For the most part, the manipulation of handoff is orderly: if handoff == 0
  44 // then the signal handler owns it and can change it to non-zero.
  45 // If handoff != 0 then the goroutine owns it and can change it to zero.
  46 // If that were the end of the story then we would not need to manipulate
  47 // handoff using atomic operations.  The operations are needed, however,
  48 // in order to let the log closer set the high bit to indicate "EOF" safely
  49 // in the situation when normally the goroutine "owns" handoff.
  50
  51 package runtime
  52 #include "runtime.h"
  53 #include "arch.h"
  54 #include "malloc.h"
  55
  56 #include "array.h"
  57 typedef struct __go_open_array Slice;
  58 #define array __values
  59 #define len __count
  60 #define cap __capacity
  61
  62 enum
  63 {
  64         HashSize = 1<<10,
  65         LogSize = 1<<17,
  66         Assoc = 4,
  67         MaxStack = 64,
  68 };
  69
  70 typedef struct Profile Profile;
  71 typedef struct Bucket Bucket;
  72 typedef struct Entry Entry;
  73
  74 struct Entry {
  75         uintptr count;
  76         uintptr depth;
  77         uintptr stack[MaxStack];
  78 };
  79
  80 struct Bucket {
  81         Entry entry[Assoc];
  82 };
  83
  84 struct Profile {
  85         bool on;                // profiling is on
  86         Note wait;              // goroutine waits here
  87         uintptr count;          // tick count
  88         uintptr evicts;         // eviction count
  89         uintptr lost;           // lost ticks that need to be logged
  90         uintptr totallost;      // total lost ticks
  91
  92         // Active recent stack traces.
  93         Bucket hash[HashSize];
  94
  95         // Log of traces evicted from hash.
  96         // Signal handler has filled log[toggle][:nlog].
  97         // Goroutine is writing log[1-toggle][:handoff].
  98         uintptr log[2][LogSize/2];
  99         uintptr nlog;
 100         int32 toggle;
 101         uint32 handoff;
 102
 103         // Writer state.
 104         // Writer maintains its own toggle to avoid races
 105         // looking at signal handler's toggle.
 106         uint32 wtoggle;
 107         bool wholding;  // holding & need to release a log half
 108         bool flushing;  // flushing hash table - profile is over
 109         bool eod_sent;  // special end-of-data record sent; => flushing
 110 };
 111
 112 static Lock lk;
 113 static Profile *prof;
 114
 115 static void tick(uintptr*, int32);
 116 static void add(Profile*, uintptr*, int32);
 117 static bool evict(Profile*, Entry*);
 118 static bool flushlog(Profile*);
 119
 120 static uintptr eod[3] = {0, 1, 0};
 121
 122 // LostProfileData is a no-op function used in profiles
 123 // to mark the number of profiling stack traces that were
 124 // discarded due to slow data writers.
 125 static void
 126 LostProfileData(void)
 127 {
 128 }
 129
 130 extern void runtime_SetCPUProfileRate(intgo)
 131      __asm__ (GOSYM_PREFIX "runtime.SetCPUProfileRate");
 132
 133 // SetCPUProfileRate sets the CPU profiling rate.
 134 // The user documentation is in debug.go.
 135 void
 136 runtime_SetCPUProfileRate(intgo hz)
 137 {
 138         uintptr *p;
 139         uintptr n;
 140
 141         // Clamp hz to something reasonable.
 142         if(hz < 0)
 143                 hz = 0;
 144         if(hz > 1000000)
 145                 hz = 1000000;
 146
 147         runtime_lock(&lk);
 148         if(hz > 0) {
 149                 if(prof == nil) {
 150                         prof = runtime_SysAlloc(sizeof *prof, &mstats.other_sys);
 151                         if(prof == nil) {
 152                                 runtime_printf("runtime: cpu profiling cannot allocate memory\n");
 153                                 runtime_unlock(&lk);
 154                                 return;
 155                         }
 156                 }
 157                 if(prof->on || prof->handoff != 0) {
 158                         runtime_printf("runtime: cannot set cpu profile rate until previous profile has finished.\n");
 159                         runtime_unlock(&lk);
 160                         return;
 161                 }
 162
 163                 prof->on = true;
 164                 p = prof->log[0];
 165                 // pprof binary header format.
 166                 // http://code.google.com/p/google-perftools/source/browse/trunk/src/profiledata.cc#117
 167                 *p++ = 0;  // count for header
 168                 *p++ = 3;  // depth for header
 169                 *p++ = 0;  // version number
 170                 *p++ = 1000000 / hz;  // period (microseconds)
 171                 *p++ = 0;
 172                 prof->nlog = p - prof->log[0];
 173                 prof->toggle = 0;
 174                 prof->wholding = false;
 175                 prof->wtoggle = 0;
 176                 prof->flushing = false;
 177                 prof->eod_sent = false;
 178                 runtime_noteclear(&prof->wait);
 179
 180                 runtime_setcpuprofilerate(tick, hz);
 181         } else if(prof != nil && prof->on) {
 182                 runtime_setcpuprofilerate(nil, 0);
 183                 prof->on = false;
 184
 185                 // Now add is not running anymore, and getprofile owns the entire log.
 186                 // Set the high bit in prof->handoff to tell getprofile.
 187                 for(;;) {
 188                         n = prof->handoff;
 189                         if(n&0x80000000)
 190                                 runtime_printf("runtime: setcpuprofile(off) twice");
 191                         if(runtime_cas(&prof->handoff, n, n|0x80000000))
 192                                 break;
 193                 }
 194                 if(n == 0) {
 195                         // we did the transition from 0 -> nonzero so we wake getprofile
 196                         runtime_notewakeup(&prof->wait);
 197                 }
 198         }
 199         runtime_unlock(&lk);
 200 }
 201
 202 static void
 203 tick(uintptr *pc, int32 n)
 204 {
 205         add(prof, pc, n);
 206 }
 207
 208 // add adds the stack trace to the profile.
 209 // It is called from signal handlers and other limited environments
 210 // and cannot allocate memory or acquire locks that might be
 211 // held at the time of the signal, nor can it use substantial amounts
 212 // of stack.  It is allowed to call evict.
 213 static void
 214 add(Profile *p, uintptr *pc, int32 n)
 215 {
 216         int32 i, j;
 217         uintptr h, x;
 218         Bucket *b;
 219         Entry *e;
 220
 221         if(n > MaxStack)
 222                 n = MaxStack;
 223
 224         // Compute hash.
 225         h = 0;
 226         for(i=0; i<n; i++) {
 227                 h = h<<8 | (h>>(8*(sizeof(h)-1)));
 228                 x = pc[i];
 229                 h += x*31 + x*7 + x*3;
 230         }
 231         p->count++;
 232
 233         // Add to entry count if already present in table.
 234         b = &p->hash[h%HashSize];
 235         for(i=0; i<Assoc; i++) {
 236                 e = &b->entry[i];
 237                 if(e->depth != (uintptr)n)
 238                         continue;
 239                 for(j=0; j<n; j++)
 240                         if(e->stack[j] != pc[j])
 241                                 goto ContinueAssoc;
 242                 e->count++;
 243                 return;
 244         ContinueAssoc:;
 245         }
 246
 247         // Evict entry with smallest count.
 248         e = &b->entry[0];
 249         for(i=1; i<Assoc; i++)
 250                 if(b->entry[i].count < e->count)
 251                         e = &b->entry[i];
 252         if(e->count > 0) {
 253                 if(!evict(p, e)) {
 254                         // Could not evict entry.  Record lost stack.
 255                         p->lost++;
 256                         p->totallost++;
 257                         return;
 258                 }
 259                 p->evicts++;
 260         }
 261
 262         // Reuse the newly evicted entry.
 263         e->depth = n;
 264         e->count = 1;
 265         for(i=0; i<n; i++)
 266                 e->stack[i] = pc[i];
 267 }
 268
 269 // evict copies the given entry's data into the log, so that
 270 // the entry can be reused.  evict is called from add, which
 271 // is called from the profiling signal handler, so it must not
 272 // allocate memory or block.  It is safe to call flushLog.
 273 // evict returns true if the entry was copied to the log,
 274 // false if there was no room available.
 275 static bool
 276 evict(Profile *p, Entry *e)
 277 {
 278         int32 i, d, nslot;
 279         uintptr *log, *q;
 280
 281         d = e->depth;
 282         nslot = d+2;
 283         log = p->log[p->toggle];
 284         if(p->nlog+nslot > nelem(p->log[0])) {
 285                 if(!flushlog(p))
 286                         return false;
 287                 log = p->log[p->toggle];
 288         }
 289
 290         q = log+p->nlog;
 291         *q++ = e->count;
 292         *q++ = d;
 293         for(i=0; i<d; i++)
 294                 *q++ = e->stack[i];
 295         p->nlog = q - log;
 296         e->count = 0;
 297         return true;
 298 }
 299
 300 // flushlog tries to flush the current log and switch to the other one.
 301 // flushlog is called from evict, called from add, called from the signal handler,
 302 // so it cannot allocate memory or block.  It can try to swap logs with
 303 // the writing goroutine, as explained in the comment at the top of this file.
 304 static bool
 305 flushlog(Profile *p)
 306 {
 307         uintptr *log, *q;
 308
 309         if(!runtime_cas(&p->handoff, 0, p->nlog))
 310                 return false;
 311         runtime_notewakeup(&p->wait);
 312
 313         p->toggle = 1 - p->toggle;
 314         log = p->log[p->toggle];
 315         q = log;
 316         if(p->lost > 0) {
 317                 *q++ = p->lost;
 318                 *q++ = 1;
 319                 *q++ = (uintptr)LostProfileData;
 320         }
 321         p->nlog = q - log;
 322         return true;
 323 }
 324
 325 // getprofile blocks until the next block of profiling data is available
 326 // and returns it as a []byte.  It is called from the writing goroutine.
 327 Slice
 328 getprofile(Profile *p)
 329 {
 330         uint32 i, j, n;
 331         Slice ret;
 332         Bucket *b;
 333         Entry *e;
 334
 335         ret.array = nil;
 336         ret.len = 0;
 337         ret.cap = 0;
 338
 339         if(p == nil)
 340                 return ret;
 341
 342         if(p->wholding) {
 343                 // Release previous log to signal handling side.
 344                 // Loop because we are racing against SetCPUProfileRate(0).
 345                 for(;;) {
 346                         n = p->handoff;
 347                         if(n == 0) {
 348                                 runtime_printf("runtime: phase error during cpu profile handoff\n");
 349                                 return ret;
 350                         }
 351                         if(n & 0x80000000) {
 352                                 p->wtoggle = 1 - p->wtoggle;
 353                                 p->wholding = false;
 354                                 p->flushing = true;
 355                                 goto flush;
 356                         }
 357                         if(runtime_cas(&p->handoff, n, 0))
 358                                 break;
 359                 }
 360                 p->wtoggle = 1 - p->wtoggle;
 361                 p->wholding = false;
 362         }
 363
 364         if(p->flushing)
 365                 goto flush;
 366
 367         if(!p->on && p->handoff == 0)
 368                 return ret;
 369
 370         // Wait for new log.
 371         runtime_notetsleepg(&p->wait, -1);
 372         runtime_noteclear(&p->wait);
 373
 374         n = p->handoff;
 375         if(n == 0) {
 376                 runtime_printf("runtime: phase error during cpu profile wait\n");
 377                 return ret;
 378         }
 379         if(n == 0x80000000) {
 380                 p->flushing = true;
 381                 goto flush;
 382         }
 383         n &= ~0x80000000;
 384
 385         // Return new log to caller.
 386         p->wholding = true;
 387
 388         ret.array = (byte*)p->log[p->wtoggle];
 389         ret.len = n*sizeof(uintptr);
 390         ret.cap = ret.len;
 391         return ret;
 392
 393 flush:
 394         // In flush mode.
 395         // Add is no longer being called.  We own the log.
 396         // Also, p->handoff is non-zero, so flushlog will return false.
 397         // Evict the hash table into the log and return it.
 398         for(i=0; i<HashSize; i++) {
 399                 b = &p->hash[i];
 400                 for(j=0; j<Assoc; j++) {
 401                         e = &b->entry[j];
 402                         if(e->count > 0 && !evict(p, e)) {
 403                                 // Filled the log.  Stop the loop and return what we've got.
 404                                 goto breakflush;
 405                         }
 406                 }
 407         }
 408 breakflush:
 409
 410         // Return pending log data.
 411         if(p->nlog > 0) {
 412                 // Note that we're using toggle now, not wtoggle,
 413                 // because we're working on the log directly.
 414                 ret.array = (byte*)p->log[p->toggle];
 415                 ret.len = p->nlog*sizeof(uintptr);
 416                 ret.cap = ret.len;
 417                 p->nlog = 0;
 418                 return ret;
 419         }
 420
 421         // Made it through the table without finding anything to log.
 422         if(!p->eod_sent) {
 423                 // We may not have space to append this to the partial log buf,
 424                 // so we always return a new slice for the end-of-data marker.
 425                 p->eod_sent = true;
 426                 ret.array = (byte*)eod;
 427                 ret.len = sizeof eod;
 428                 ret.cap = ret.len;
 429                 return ret;
 430         }
 431
 432         // Finally done.  Clean up and return nil.
 433         p->flushing = false;
 434         if(!runtime_cas(&p->handoff, p->handoff, 0))
 435                 runtime_printf("runtime: profile flush racing with something\n");
 436         return ret;  // set to nil at top of function
 437 }
 438
 439 // CPUProfile returns the next cpu profile block as a []byte.
 440 // The user documentation is in debug.go.
 441 func CPUProfile() (ret Slice) {
 442         ret = getprofile(prof);
 443 }