Source file src/pkg/runtime/pprof/pprof.go
1 // Copyright 2010 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 // Package pprof writes runtime profiling data in the format expected 6 // by the pprof visualization tool. 7 // For more information about pprof, see 8 // http://code.google.com/p/google-perftools/. 9 package pprof 10 11 import ( 12 "bufio" 13 "bytes" 14 "fmt" 15 "io" 16 "runtime" 17 "sort" 18 "strings" 19 "sync" 20 "text/tabwriter" 21 ) 22 23 // BUG(rsc): A bug in the OS X Snow Leopard 64-bit kernel prevents 24 // CPU profiling from giving accurate results on that system. 25 26 // A Profile is a collection of stack traces showing the call sequences 27 // that led to instances of a particular event, such as allocation. 28 // Packages can create and maintain their own profiles; the most common 29 // use is for tracking resources that must be explicitly closed, such as files 30 // or network connections. 31 // 32 // A Profile's methods can be called from multiple goroutines simultaneously. 33 // 34 // Each Profile has a unique name. A few profiles are predefined: 35 // 36 // goroutine - stack traces of all current goroutines 37 // heap - a sampling of all heap allocations 38 // threadcreate - stack traces that led to the creation of new OS threads 39 // 40 // These predefine profiles maintain themselves and panic on an explicit 41 // Add or Remove method call. 42 // 43 // The CPU profile is not available as a Profile. It has a special API, 44 // the StartCPUProfile and StopCPUProfile functions, because it streams 45 // output to a writer during profiling. 46 // 47 type Profile struct { 48 name string 49 mu sync.Mutex 50 m map[interface{}][]uintptr 51 count func() int 52 write func(io.Writer, int) error 53 } 54 55 // profiles records all registered profiles. 56 var profiles struct { 57 mu sync.Mutex 58 m map[string]*Profile 59 } 60 61 var goroutineProfile = &Profile{ 62 name: "goroutine", 63 count: countGoroutine, 64 write: writeGoroutine, 65 } 66 67 var threadcreateProfile = &Profile{ 68 name: "threadcreate", 69 count: countThreadCreate, 70 write: writeThreadCreate, 71 } 72 73 var heapProfile = &Profile{ 74 name: "heap", 75 count: countHeap, 76 write: writeHeap, 77 } 78 79 func lockProfiles() { 80 profiles.mu.Lock() 81 if profiles.m == nil { 82 // Initial built-in profiles. 83 profiles.m = map[string]*Profile{ 84 "goroutine": goroutineProfile, 85 "threadcreate": threadcreateProfile, 86 "heap": heapProfile, 87 } 88 } 89 } 90 91 func unlockProfiles() { 92 profiles.mu.Unlock() 93 } 94 95 // NewProfile creates a new profile with the given name. 96 // If a profile with that name already exists, NewProfile panics. 97 // The convention is to use a 'import/path.' prefix to create 98 // separate name spaces for each package. 99 func NewProfile(name string) *Profile { 100 lockProfiles() 101 defer unlockProfiles() 102 if name == "" { 103 panic("pprof: NewProfile with empty name") 104 } 105 if profiles.m[name] != nil { 106 panic("pprof: NewProfile name already in use: " + name) 107 } 108 p := &Profile{ 109 name: name, 110 m: map[interface{}][]uintptr{}, 111 } 112 profiles.m[name] = p 113 return p 114 } 115 116 // Lookup returns the profile with the given name, or nil if no such profile exists. 117 func Lookup(name string) *Profile { 118 lockProfiles() 119 defer unlockProfiles() 120 return profiles.m[name] 121 } 122 123 // Profiles returns a slice of all the known profiles, sorted by name. 124 func Profiles() []*Profile { 125 lockProfiles() 126 defer unlockProfiles() 127 128 var all []*Profile 129 for _, p := range profiles.m { 130 all = append(all, p) 131 } 132 133 sort.Sort(byName(all)) 134 return all 135 } 136 137 type byName []*Profile 138 139 func (x byName) Len() int { return len(x) } 140 func (x byName) Swap(i, j int) { x[i], x[j] = x[j], x[i] } 141 func (x byName) Less(i, j int) bool { return x[i].name < x[j].name } 142 143 // Name returns this profile's name, which can be passed to Lookup to reobtain the profile. 144 func (p *Profile) Name() string { 145 return p.name 146 } 147 148 // Count returns the number of execution stacks currently in the profile. 149 func (p *Profile) Count() int { 150 p.mu.Lock() 151 defer p.mu.Unlock() 152 if p.count != nil { 153 return p.count() 154 } 155 return len(p.m) 156 } 157 158 // Add adds the current execution stack to the profile, associated with value. 159 // Add stores value in an internal map, so value must be suitable for use as 160 // a map key and will not be garbage collected until the corresponding 161 // call to Remove. Add panics if the profile already contains a stack for value. 162 // 163 // The skip parameter has the same meaning as runtime.Caller's skip 164 // and controls where the stack trace begins. Passing skip=0 begins the 165 // trace in the function calling Add. For example, given this 166 // execution stack: 167 // 168 // Add 169 // called from rpc.NewClient 170 // called from mypkg.Run 171 // called from main.main 172 // 173 // Passing skip=0 begins the stack trace at the call to Add inside rpc.NewClient. 174 // Passing skip=1 begins the stack trace at the call to NewClient inside mypkg.Run. 175 // 176 func (p *Profile) Add(value interface{}, skip int) { 177 if p.name == "" { 178 panic("pprof: use of uninitialized Profile") 179 } 180 if p.write != nil { 181 panic("pprof: Add called on built-in Profile " + p.name) 182 } 183 184 stk := make([]uintptr, 32) 185 n := runtime.Callers(skip+1, stk[:]) 186 187 p.mu.Lock() 188 defer p.mu.Unlock() 189 if p.m[value] != nil { 190 panic("pprof: Profile.Add of duplicate value") 191 } 192 p.m[value] = stk[:n] 193 } 194 195 // Remove removes the execution stack associated with value from the profile. 196 // It is a no-op if the value is not in the profile. 197 func (p *Profile) Remove(value interface{}) { 198 p.mu.Lock() 199 defer p.mu.Unlock() 200 delete(p.m, value) 201 } 202 203 // WriteTo writes a pprof-formatted snapshot of the profile to w. 204 // If a write to w returns an error, WriteTo returns that error. 205 // Otherwise, WriteTo returns nil. 206 // 207 // The debug parameter enables additional output. 208 // Passing debug=0 prints only the hexadecimal addresses that pprof needs. 209 // Passing debug=1 adds comments translating addresses to function names 210 // and line numbers, so that a programmer can read the profile without tools. 211 // 212 // The predefined profiles may assign meaning to other debug values; 213 // for example, when printing the "goroutine" profile, debug=2 means to 214 // print the goroutine stacks in the same form that a Go program uses 215 // when dying due to an unrecovered panic. 216 func (p *Profile) WriteTo(w io.Writer, debug int) error { 217 if p.name == "" { 218 panic("pprof: use of zero Profile") 219 } 220 if p.write != nil { 221 return p.write(w, debug) 222 } 223 224 // Obtain consistent snapshot under lock; then process without lock. 225 var all [][]uintptr 226 p.mu.Lock() 227 for _, stk := range p.m { 228 all = append(all, stk) 229 } 230 p.mu.Unlock() 231 232 // Map order is non-deterministic; make output deterministic. 233 sort.Sort(stackProfile(all)) 234 235 return printCountProfile(w, debug, p.name, stackProfile(all)) 236 } 237 238 type stackProfile [][]uintptr 239 240 func (x stackProfile) Len() int { return len(x) } 241 func (x stackProfile) Stack(i int) []uintptr { return x[i] } 242 func (x stackProfile) Swap(i, j int) { x[i], x[j] = x[j], x[i] } 243 func (x stackProfile) Less(i, j int) bool { 244 t, u := x[i], x[j] 245 for k := 0; k < len(t) && k < len(u); k++ { 246 if t[k] != u[k] { 247 return t[k] < u[k] 248 } 249 } 250 return len(t) < len(u) 251 } 252 253 // A countProfile is a set of stack traces to be printed as counts 254 // grouped by stack trace. There are multiple implementations: 255 // all that matters is that we can find out how many traces there are 256 // and obtain each trace in turn. 257 type countProfile interface { 258 Len() int 259 Stack(i int) []uintptr 260 } 261 262 // printCountProfile prints a countProfile at the specified debug level. 263 func printCountProfile(w io.Writer, debug int, name string, p countProfile) error { 264 b := bufio.NewWriter(w) 265 var tw *tabwriter.Writer 266 w = b 267 if debug > 0 { 268 tw = tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) 269 w = tw 270 } 271 272 fmt.Fprintf(w, "%s profile: total %d\n", name, p.Len()) 273 274 // Build count of each stack. 275 var buf bytes.Buffer 276 key := func(stk []uintptr) string { 277 buf.Reset() 278 fmt.Fprintf(&buf, "@") 279 for _, pc := range stk { 280 fmt.Fprintf(&buf, " %#x", pc) 281 } 282 return buf.String() 283 } 284 m := map[string]int{} 285 n := p.Len() 286 for i := 0; i < n; i++ { 287 m[key(p.Stack(i))]++ 288 } 289 290 // Print stacks, listing count on first occurrence of a unique stack. 291 for i := 0; i < n; i++ { 292 stk := p.Stack(i) 293 s := key(stk) 294 if count := m[s]; count != 0 { 295 fmt.Fprintf(w, "%d %s\n", count, s) 296 if debug > 0 { 297 printStackRecord(w, stk, false) 298 } 299 delete(m, s) 300 } 301 } 302 303 if tw != nil { 304 tw.Flush() 305 } 306 return b.Flush() 307 } 308 309 // printStackRecord prints the function + source line information 310 // for a single stack trace. 311 func printStackRecord(w io.Writer, stk []uintptr, allFrames bool) { 312 show := allFrames 313 for _, pc := range stk { 314 f := runtime.FuncForPC(pc) 315 if f == nil { 316 show = true 317 fmt.Fprintf(w, "#\t%#x\n", pc) 318 } else { 319 file, line := f.FileLine(pc) 320 name := f.Name() 321 // Hide runtime.goexit and any runtime functions at the beginning. 322 // This is useful mainly for allocation traces. 323 if name == "runtime.goexit" || !show && strings.HasPrefix(name, "runtime.") { 324 continue 325 } 326 show = true 327 fmt.Fprintf(w, "#\t%#x\t%s+%#x\t%s:%d\n", pc, f.Name(), pc-f.Entry(), file, line) 328 } 329 } 330 if !show { 331 // We didn't print anything; do it again, 332 // and this time include runtime functions. 333 printStackRecord(w, stk, true) 334 return 335 } 336 fmt.Fprintf(w, "\n") 337 } 338 339 // Interface to system profiles. 340 341 type byInUseBytes []runtime.MemProfileRecord 342 343 func (x byInUseBytes) Len() int { return len(x) } 344 func (x byInUseBytes) Swap(i, j int) { x[i], x[j] = x[j], x[i] } 345 func (x byInUseBytes) Less(i, j int) bool { return x[i].InUseBytes() > x[j].InUseBytes() } 346 347 // WriteHeapProfile is shorthand for Lookup("heap").WriteTo(w, 0). 348 // It is preserved for backwards compatibility. 349 func WriteHeapProfile(w io.Writer) error { 350 return writeHeap(w, 0) 351 } 352 353 // countHeap returns the number of records in the heap profile. 354 func countHeap() int { 355 n, _ := runtime.MemProfile(nil, false) 356 return n 357 } 358 359 // writeHeapProfile writes the current runtime heap profile to w. 360 func writeHeap(w io.Writer, debug int) error { 361 // Find out how many records there are (MemProfile(nil, false)), 362 // allocate that many records, and get the data. 363 // There's a race—more records might be added between 364 // the two calls—so allocate a few extra records for safety 365 // and also try again if we're very unlucky. 366 // The loop should only execute one iteration in the common case. 367 var p []runtime.MemProfileRecord 368 n, ok := runtime.MemProfile(nil, false) 369 for { 370 // Allocate room for a slightly bigger profile, 371 // in case a few more entries have been added 372 // since the call to MemProfile. 373 p = make([]runtime.MemProfileRecord, n+50) 374 n, ok = runtime.MemProfile(p, false) 375 if ok { 376 p = p[0:n] 377 break 378 } 379 // Profile grew; try again. 380 } 381 382 sort.Sort(byInUseBytes(p)) 383 384 b := bufio.NewWriter(w) 385 var tw *tabwriter.Writer 386 w = b 387 if debug > 0 { 388 tw = tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) 389 w = tw 390 } 391 392 var total runtime.MemProfileRecord 393 for i := range p { 394 r := &p[i] 395 total.AllocBytes += r.AllocBytes 396 total.AllocObjects += r.AllocObjects 397 total.FreeBytes += r.FreeBytes 398 total.FreeObjects += r.FreeObjects 399 } 400 401 // Technically the rate is MemProfileRate not 2*MemProfileRate, 402 // but early versions of the C++ heap profiler reported 2*MemProfileRate, 403 // so that's what pprof has come to expect. 404 fmt.Fprintf(w, "heap profile: %d: %d [%d: %d] @ heap/%d\n", 405 total.InUseObjects(), total.InUseBytes(), 406 total.AllocObjects, total.AllocBytes, 407 2*runtime.MemProfileRate) 408 409 for i := range p { 410 r := &p[i] 411 fmt.Fprintf(w, "%d: %d [%d: %d] @", 412 r.InUseObjects(), r.InUseBytes(), 413 r.AllocObjects, r.AllocBytes) 414 for _, pc := range r.Stack() { 415 fmt.Fprintf(w, " %#x", pc) 416 } 417 fmt.Fprintf(w, "\n") 418 if debug > 0 { 419 printStackRecord(w, r.Stack(), false) 420 } 421 } 422 423 // Print memstats information too. 424 // Pprof will ignore, but useful for people 425 if debug > 0 { 426 s := new(runtime.MemStats) 427 runtime.ReadMemStats(s) 428 fmt.Fprintf(w, "\n# runtime.MemStats\n") 429 fmt.Fprintf(w, "# Alloc = %d\n", s.Alloc) 430 fmt.Fprintf(w, "# TotalAlloc = %d\n", s.TotalAlloc) 431 fmt.Fprintf(w, "# Sys = %d\n", s.Sys) 432 fmt.Fprintf(w, "# Lookups = %d\n", s.Lookups) 433 fmt.Fprintf(w, "# Mallocs = %d\n", s.Mallocs) 434 435 fmt.Fprintf(w, "# HeapAlloc = %d\n", s.HeapAlloc) 436 fmt.Fprintf(w, "# HeapSys = %d\n", s.HeapSys) 437 fmt.Fprintf(w, "# HeapIdle = %d\n", s.HeapIdle) 438 fmt.Fprintf(w, "# HeapInuse = %d\n", s.HeapInuse) 439 440 fmt.Fprintf(w, "# Stack = %d / %d\n", s.StackInuse, s.StackSys) 441 fmt.Fprintf(w, "# MSpan = %d / %d\n", s.MSpanInuse, s.MSpanSys) 442 fmt.Fprintf(w, "# MCache = %d / %d\n", s.MCacheInuse, s.MCacheSys) 443 fmt.Fprintf(w, "# BuckHashSys = %d\n", s.BuckHashSys) 444 445 fmt.Fprintf(w, "# NextGC = %d\n", s.NextGC) 446 fmt.Fprintf(w, "# PauseNs = %d\n", s.PauseNs) 447 fmt.Fprintf(w, "# NumGC = %d\n", s.NumGC) 448 fmt.Fprintf(w, "# EnableGC = %v\n", s.EnableGC) 449 fmt.Fprintf(w, "# DebugGC = %v\n", s.DebugGC) 450 } 451 452 if tw != nil { 453 tw.Flush() 454 } 455 return b.Flush() 456 } 457 458 // countThreadCreate returns the size of the current ThreadCreateProfile. 459 func countThreadCreate() int { 460 n, _ := runtime.ThreadCreateProfile(nil) 461 return n 462 } 463 464 // writeThreadCreate writes the current runtime ThreadCreateProfile to w. 465 func writeThreadCreate(w io.Writer, debug int) error { 466 return writeRuntimeProfile(w, debug, "threadcreate", runtime.ThreadCreateProfile) 467 } 468 469 // countGoroutine returns the number of goroutines. 470 func countGoroutine() int { 471 return runtime.NumGoroutine() 472 } 473 474 // writeGoroutine writes the current runtime GoroutineProfile to w. 475 func writeGoroutine(w io.Writer, debug int) error { 476 if debug >= 2 { 477 return writeGoroutineStacks(w) 478 } 479 return writeRuntimeProfile(w, debug, "goroutine", runtime.GoroutineProfile) 480 } 481 482 func writeGoroutineStacks(w io.Writer) error { 483 // We don't know how big the buffer needs to be to collect 484 // all the goroutines. Start with 1 MB and try a few times, doubling each time. 485 // Give up and use a truncated trace if 64 MB is not enough. 486 buf := make([]byte, 1<<20) 487 for i := 0; ; i++ { 488 n := runtime.Stack(buf, true) 489 if n < len(buf) { 490 buf = buf[:n] 491 break 492 } 493 if len(buf) >= 64<<20 { 494 // Filled 64 MB - stop there. 495 break 496 } 497 buf = make([]byte, 2*len(buf)) 498 } 499 _, err := w.Write(buf) 500 return err 501 } 502 503 func writeRuntimeProfile(w io.Writer, debug int, name string, fetch func([]runtime.StackRecord) (int, bool)) error { 504 // Find out how many records there are (fetch(nil)), 505 // allocate that many records, and get the data. 506 // There's a race—more records might be added between 507 // the two calls—so allocate a few extra records for safety 508 // and also try again if we're very unlucky. 509 // The loop should only execute one iteration in the common case. 510 var p []runtime.StackRecord 511 n, ok := fetch(nil) 512 for { 513 // Allocate room for a slightly bigger profile, 514 // in case a few more entries have been added 515 // since the call to ThreadProfile. 516 p = make([]runtime.StackRecord, n+10) 517 n, ok = fetch(p) 518 if ok { 519 p = p[0:n] 520 break 521 } 522 // Profile grew; try again. 523 } 524 525 return printCountProfile(w, debug, name, runtimeProfile(p)) 526 } 527 528 type runtimeProfile []runtime.StackRecord 529 530 func (p runtimeProfile) Len() int { return len(p) } 531 func (p runtimeProfile) Stack(i int) []uintptr { return p[i].Stack() } 532 533 var cpu struct { 534 sync.Mutex 535 profiling bool 536 done chan bool 537 } 538 539 // StartCPUProfile enables CPU profiling for the current process. 540 // While profiling, the profile will be buffered and written to w. 541 // StartCPUProfile returns an error if profiling is already enabled. 542 func StartCPUProfile(w io.Writer) error { 543 // The runtime routines allow a variable profiling rate, 544 // but in practice operating systems cannot trigger signals 545 // at more than about 500 Hz, and our processing of the 546 // signal is not cheap (mostly getting the stack trace). 547 // 100 Hz is a reasonable choice: it is frequent enough to 548 // produce useful data, rare enough not to bog down the 549 // system, and a nice round number to make it easy to 550 // convert sample counts to seconds. Instead of requiring 551 // each client to specify the frequency, we hard code it. 552 const hz = 100 553 554 // Avoid queueing behind StopCPUProfile. 555 // Could use TryLock instead if we had it. 556 if cpu.profiling { 557 return fmt.Errorf("cpu profiling already in use") 558 } 559 560 cpu.Lock() 561 defer cpu.Unlock() 562 if cpu.done == nil { 563 cpu.done = make(chan bool) 564 } 565 // Double-check. 566 if cpu.profiling { 567 return fmt.Errorf("cpu profiling already in use") 568 } 569 cpu.profiling = true 570 runtime.SetCPUProfileRate(hz) 571 go profileWriter(w) 572 return nil 573 } 574 575 func profileWriter(w io.Writer) { 576 for { 577 data := runtime.CPUProfile() 578 if data == nil { 579 break 580 } 581 w.Write(data) 582 } 583 cpu.done <- true 584 } 585 586 // StopCPUProfile stops the current CPU profile, if any. 587 // StopCPUProfile only returns after all the writes for the 588 // profile have completed. 589 func StopCPUProfile() { 590 cpu.Lock() 591 defer cpu.Unlock() 592 593 if !cpu.profiling { 594 return 595 } 596 cpu.profiling = false 597 runtime.SetCPUProfileRate(0) 598 <-cpu.done 599 }