| // Copyright 2011 The Go Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style |
| // license that can be found in the LICENSE file. |
| |
| // CPU profiling. |
| // Based on algorithms and data structures used in |
| // http://code.google.com/p/google-perftools/. |
| // |
| // The main difference between this code and the google-perftools |
| // code is that this code is written to allow copying the profile data |
| // to an arbitrary io.Writer, while the google-perftools code always |
| // writes to an operating system file. |
| // |
| // The signal handler for the profiling clock tick adds a new stack trace |
| // to a hash table tracking counts for recent traces. Most clock ticks |
| // hit in the cache. In the event of a cache miss, an entry must be |
| // evicted from the hash table, copied to a log that will eventually be |
| // written as profile data. The google-perftools code flushed the |
| // log itself during the signal handler. This code cannot do that, because |
| // the io.Writer might block or need system calls or locks that are not |
| // safe to use from within the signal handler. Instead, we split the log |
| // into two halves and let the signal handler fill one half while a goroutine |
| // is writing out the other half. When the signal handler fills its half, it |
| // offers to swap with the goroutine. If the writer is not done with its half, |
| // we lose the stack trace for this clock tick (and record that loss). |
| // The goroutine interacts with the signal handler by calling getprofile() to |
| // get the next log piece to write, implicitly handing back the last log |
| // piece it obtained. |
| // |
| // The state of this dance between the signal handler and the goroutine |
| // is encoded in the Profile.handoff field. If handoff == 0, then the goroutine |
| // is not using either log half and is waiting (or will soon be waiting) for |
| // a new piece by calling notesleep(&p->wait). If the signal handler |
| // changes handoff from 0 to non-zero, it must call notewakeup(&p->wait) |
| // to wake the goroutine. The value indicates the number of entries in the |
| // log half being handed off. The goroutine leaves the non-zero value in |
| // place until it has finished processing the log half and then flips the number |
| // back to zero. Setting the high bit in handoff means that the profiling is over, |
| // and the goroutine is now in charge of flushing the data left in the hash table |
| // to the log and returning that data. |
| // |
| // The handoff field is manipulated using atomic operations. |
| // For the most part, the manipulation of handoff is orderly: if handoff == 0 |
| // then the signal handler owns it and can change it to non-zero. |
| // If handoff != 0 then the goroutine owns it and can change it to zero. |
| // If that were the end of the story then we would not need to manipulate |
| // handoff using atomic operations. The operations are needed, however, |
| // in order to let the log closer set the high bit to indicate "EOF" safely |
| // in the situation when normally the goroutine "owns" handoff. |
| |
| #include "runtime.h" |
| #include "malloc.h" |
| |
| enum |
| { |
| HashSize = 1<<10, |
| LogSize = 1<<17, |
| Assoc = 4, |
| MaxStack = 64, |
| }; |
| |
| typedef struct Profile Profile; |
| typedef struct Bucket Bucket; |
| typedef struct Entry Entry; |
| |
| struct Entry { |
| uintptr count; |
| uintptr depth; |
| uintptr stack[MaxStack]; |
| }; |
| |
| struct Bucket { |
| Entry entry[Assoc]; |
| }; |
| |
| struct Profile { |
| bool on; // profiling is on |
| Note wait; // goroutine waits here |
| uintptr count; // tick count |
| uintptr evicts; // eviction count |
| uintptr lost; // lost ticks that need to be logged |
| uintptr totallost; // total lost ticks |
| |
| // Active recent stack traces. |
| Bucket hash[HashSize]; |
| |
| // Log of traces evicted from hash. |
| // Signal handler has filled log[toggle][:nlog]. |
| // Goroutine is writing log[1-toggle][:handoff]. |
| uintptr log[2][LogSize/2]; |
| uintptr nlog; |
| int32 toggle; |
| uint32 handoff; |
| |
| // Writer state. |
| // Writer maintains its own toggle to avoid races |
| // looking at signal handler's toggle. |
| uint32 wtoggle; |
| bool wholding; // holding & need to release a log half |
| bool flushing; // flushing hash table - profile is over |
| }; |
| |
| static Lock lk; |
| static Profile *prof; |
| |
| static void tick(uintptr*, int32); |
| static void add(Profile*, uintptr*, int32); |
| static bool evict(Profile*, Entry*); |
| static bool flushlog(Profile*); |
| |
| // LostProfileData is a no-op function used in profiles |
| // to mark the number of profiling stack traces that were |
| // discarded due to slow data writers. |
| static void LostProfileData(void) { |
| } |
| |
| // SetCPUProfileRate sets the CPU profiling rate. |
| // The user documentation is in debug.go. |
| void |
| runtime·SetCPUProfileRate(int32 hz) |
| { |
| uintptr *p; |
| uintptr n; |
| |
| // Call findfunc now so that it won't have to |
| // build tables during the signal handler. |
| runtime·findfunc(0); |
| |
| // Clamp hz to something reasonable. |
| if(hz < 0) |
| hz = 0; |
| if(hz > 1000000) |
| hz = 1000000; |
| |
| runtime·lock(&lk); |
| if(hz > 0) { |
| if(prof == nil) { |
| prof = runtime·SysAlloc(sizeof *prof); |
| if(prof == nil) { |
| runtime·printf("runtime: cpu profiling cannot allocate memory\n"); |
| runtime·unlock(&lk); |
| return; |
| } |
| } |
| if(prof->on || prof->handoff != 0) { |
| runtime·printf("runtime: cannot set cpu profile rate until previous profile has finished.\n"); |
| runtime·unlock(&lk); |
| return; |
| } |
| |
| prof->on = true; |
| p = prof->log[0]; |
| // pprof binary header format. |
| // http://code.google.com/p/google-perftools/source/browse/trunk/src/profiledata.cc#117 |
| *p++ = 0; // count for header |
| *p++ = 3; // depth for header |
| *p++ = 0; // version number |
| *p++ = 1000000 / hz; // period (microseconds) |
| *p++ = 0; |
| prof->nlog = p - prof->log[0]; |
| prof->toggle = 0; |
| prof->wholding = false; |
| prof->wtoggle = 0; |
| prof->flushing = false; |
| runtime·noteclear(&prof->wait); |
| |
| runtime·setcpuprofilerate(tick, hz); |
| } else if(prof->on) { |
| runtime·setcpuprofilerate(nil, 0); |
| prof->on = false; |
| |
| // Now add is not running anymore, and getprofile owns the entire log. |
| // Set the high bit in prof->handoff to tell getprofile. |
| for(;;) { |
| n = prof->handoff; |
| if(n&0x80000000) |
| runtime·printf("runtime: setcpuprofile(off) twice"); |
| if(runtime·cas(&prof->handoff, n, n|0x80000000)) |
| break; |
| } |
| if(n == 0) { |
| // we did the transition from 0 -> nonzero so we wake getprofile |
| runtime·notewakeup(&prof->wait); |
| } |
| } |
| runtime·unlock(&lk); |
| } |
| |
| static void |
| tick(uintptr *pc, int32 n) |
| { |
| add(prof, pc, n); |
| } |
| |
| // add adds the stack trace to the profile. |
| // It is called from signal handlers and other limited environments |
| // and cannot allocate memory or acquire locks that might be |
| // held at the time of the signal, nor can it use substantial amounts |
| // of stack. It is allowed to call evict. |
| static void |
| add(Profile *p, uintptr *pc, int32 n) |
| { |
| int32 i, j; |
| uintptr h, x; |
| Bucket *b; |
| Entry *e; |
| |
| if(n > MaxStack) |
| n = MaxStack; |
| |
| // Compute hash. |
| h = 0; |
| for(i=0; i<n; i++) { |
| h = h<<8 | (h>>(8*(sizeof(h)-1))); |
| x = pc[i]; |
| h += x*31 + x*7 + x*3; |
| } |
| p->count++; |
| |
| // Add to entry count if already present in table. |
| b = &p->hash[h%HashSize]; |
| for(i=0; i<Assoc; i++) { |
| e = &b->entry[i]; |
| if(e->depth != n) |
| continue; |
| for(j=0; j<n; j++) |
| if(e->stack[j] != pc[j]) |
| goto ContinueAssoc; |
| e->count++; |
| return; |
| ContinueAssoc:; |
| } |
| |
| // Evict entry with smallest count. |
| e = &b->entry[0]; |
| for(i=1; i<Assoc; i++) |
| if(b->entry[i].count < e->count) |
| e = &b->entry[i]; |
| if(e->count > 0) { |
| if(!evict(p, e)) { |
| // Could not evict entry. Record lost stack. |
| p->lost++; |
| p->totallost++; |
| return; |
| } |
| p->evicts++; |
| } |
| |
| // Reuse the newly evicted entry. |
| e->depth = n; |
| e->count = 1; |
| for(i=0; i<n; i++) |
| e->stack[i] = pc[i]; |
| } |
| |
| // evict copies the given entry's data into the log, so that |
| // the entry can be reused. evict is called from add, which |
| // is called from the profiling signal handler, so it must not |
| // allocate memory or block. It is safe to call flushLog. |
| // evict returns true if the entry was copied to the log, |
| // false if there was no room available. |
| static bool |
| evict(Profile *p, Entry *e) |
| { |
| int32 i, d, nslot; |
| uintptr *log, *q; |
| |
| d = e->depth; |
| nslot = d+2; |
| log = p->log[p->toggle]; |
| if(p->nlog+nslot > nelem(p->log[0])) { |
| if(!flushlog(p)) |
| return false; |
| log = p->log[p->toggle]; |
| } |
| |
| q = log+p->nlog; |
| *q++ = e->count; |
| *q++ = d; |
| for(i=0; i<d; i++) |
| *q++ = e->stack[i]; |
| p->nlog = q - log; |
| e->count = 0; |
| return true; |
| } |
| |
| // flushlog tries to flush the current log and switch to the other one. |
| // flushlog is called from evict, called from add, called from the signal handler, |
| // so it cannot allocate memory or block. It can try to swap logs with |
| // the writing goroutine, as explained in the comment at the top of this file. |
| static bool |
| flushlog(Profile *p) |
| { |
| uintptr *log, *q; |
| |
| if(!runtime·cas(&p->handoff, 0, p->nlog)) |
| return false; |
| runtime·notewakeup(&p->wait); |
| |
| p->toggle = 1 - p->toggle; |
| log = p->log[p->toggle]; |
| q = log; |
| if(p->lost > 0) { |
| *q++ = p->lost; |
| *q++ = 1; |
| *q++ = (uintptr)LostProfileData; |
| } |
| p->nlog = q - log; |
| return true; |
| } |
| |
| // getprofile blocks until the next block of profiling data is available |
| // and returns it as a []byte. It is called from the writing goroutine. |
| Slice |
| getprofile(Profile *p) |
| { |
| uint32 i, j, n; |
| Slice ret; |
| Bucket *b; |
| Entry *e; |
| |
| ret.array = nil; |
| ret.len = 0; |
| ret.cap = 0; |
| |
| if(p == nil) |
| return ret; |
| |
| if(p->wholding) { |
| // Release previous log to signal handling side. |
| // Loop because we are racing against setprofile(off). |
| for(;;) { |
| n = p->handoff; |
| if(n == 0) { |
| runtime·printf("runtime: phase error during cpu profile handoff\n"); |
| return ret; |
| } |
| if(n & 0x80000000) { |
| p->wtoggle = 1 - p->wtoggle; |
| p->wholding = false; |
| p->flushing = true; |
| goto flush; |
| } |
| if(runtime·cas(&p->handoff, n, 0)) |
| break; |
| } |
| p->wtoggle = 1 - p->wtoggle; |
| p->wholding = false; |
| } |
| |
| if(p->flushing) |
| goto flush; |
| |
| if(!p->on && p->handoff == 0) |
| return ret; |
| |
| // Wait for new log. |
| runtime·entersyscall(); |
| runtime·notesleep(&p->wait); |
| runtime·exitsyscall(); |
| runtime·noteclear(&p->wait); |
| |
| n = p->handoff; |
| if(n == 0) { |
| runtime·printf("runtime: phase error during cpu profile wait\n"); |
| return ret; |
| } |
| if(n == 0x80000000) { |
| p->flushing = true; |
| goto flush; |
| } |
| n &= ~0x80000000; |
| |
| // Return new log to caller. |
| p->wholding = true; |
| |
| ret.array = (byte*)p->log[p->wtoggle]; |
| ret.len = n*sizeof(uintptr); |
| ret.cap = ret.len; |
| return ret; |
| |
| flush: |
| // In flush mode. |
| // Add is no longer being called. We own the log. |
| // Also, p->handoff is non-zero, so flushlog will return false. |
| // Evict the hash table into the log and return it. |
| for(i=0; i<HashSize; i++) { |
| b = &p->hash[i]; |
| for(j=0; j<Assoc; j++) { |
| e = &b->entry[j]; |
| if(e->count > 0 && !evict(p, e)) { |
| // Filled the log. Stop the loop and return what we've got. |
| goto breakflush; |
| } |
| } |
| } |
| breakflush: |
| |
| // Return pending log data. |
| if(p->nlog > 0) { |
| // Note that we're using toggle now, not wtoggle, |
| // because we're working on the log directly. |
| ret.array = (byte*)p->log[p->toggle]; |
| ret.len = p->nlog*sizeof(uintptr); |
| ret.cap = ret.len; |
| p->nlog = 0; |
| return ret; |
| } |
| |
| // Made it through the table without finding anything to log. |
| // Finally done. Clean up and return nil. |
| p->flushing = false; |
| if(!runtime·cas(&p->handoff, p->handoff, 0)) |
| runtime·printf("runtime: profile flush racing with something\n"); |
| return ret; // set to nil at top of function |
| } |
| |
| // CPUProfile returns the next cpu profile block as a []byte. |
| // The user documentation is in debug.go. |
| void |
| runtime·CPUProfile(Slice ret) |
| { |
| ret = getprofile(prof); |
| FLUSH(&ret); |
| } |