github.com/letsencrypt/go@v0.0.0-20160714163537-4054769a31f6/src/runtime/trace.go (about) 1 // Copyright 2014 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 // Go execution tracer. 6 // The tracer captures a wide range of execution events like goroutine 7 // creation/blocking/unblocking, syscall enter/exit/block, GC-related events, 8 // changes of heap size, processor start/stop, etc and writes them to a buffer 9 // in a compact form. A precise nanosecond-precision timestamp and a stack 10 // trace is captured for most events. 11 // See https://golang.org/s/go15trace for more info. 12 13 package runtime 14 15 import ( 16 "runtime/internal/sys" 17 "unsafe" 18 ) 19 20 // Event types in the trace, args are given in square brackets. 21 const ( 22 traceEvNone = 0 // unused 23 traceEvBatch = 1 // start of per-P batch of events [pid, timestamp] 24 traceEvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] 25 traceEvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] 26 traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] 27 traceEvProcStart = 5 // start of P [timestamp, thread id] 28 traceEvProcStop = 6 // stop of P [timestamp] 29 traceEvGCStart = 7 // GC start [timestamp, seq, stack id] 30 traceEvGCDone = 8 // GC done [timestamp] 31 traceEvGCScanStart = 9 // GC scan start [timestamp] 32 traceEvGCScanDone = 10 // GC scan done [timestamp] 33 traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id] 34 traceEvGCSweepDone = 12 // GC sweep done [timestamp] 35 traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] 36 traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 37 traceEvGoEnd = 15 // goroutine ends [timestamp] 38 traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] 39 traceEvGoSched = 17 // goroutine calls Gosched [timestamp, stack] 40 traceEvGoPreempt = 18 // goroutine is preempted [timestamp, stack] 41 traceEvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] 42 traceEvGoBlock = 20 // goroutine blocks [timestamp, stack] 43 traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] 44 traceEvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] 45 traceEvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] 46 traceEvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] 47 traceEvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] 48 traceEvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] 49 traceEvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] 50 traceEvGoSysCall = 28 // syscall enter [timestamp, stack] 51 traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] 52 traceEvGoSysBlock = 30 // syscall blocks [timestamp] 53 traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] 54 traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] 55 traceEvHeapAlloc = 33 // memstats.heap_live change [timestamp, heap_alloc] 56 traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] 57 traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] 58 traceEvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] 59 traceEvString = 37 // string dictionary entry [ID, length, string] 60 traceEvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] 61 traceEvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] 62 traceEvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] 63 traceEvCount = 41 64 ) 65 66 const ( 67 // Timestamps in trace are cputicks/traceTickDiv. 68 // This makes absolute values of timestamp diffs smaller, 69 // and so they are encoded in less number of bytes. 70 // 64 on x86 is somewhat arbitrary (one tick is ~20ns on a 3GHz machine). 71 // The suggested increment frequency for PowerPC's time base register is 72 // 512 MHz according to Power ISA v2.07 section 6.2, so we use 16 on ppc64 73 // and ppc64le. 74 // Tracing won't work reliably for architectures where cputicks is emulated 75 // by nanotime, so the value doesn't matter for those architectures. 76 traceTickDiv = 16 + 48*(sys.Goarch386|sys.GoarchAmd64|sys.GoarchAmd64p32) 77 // Maximum number of PCs in a single stack trace. 78 // Since events contain only stack id rather than whole stack trace, 79 // we can allow quite large values here. 80 traceStackSize = 128 81 // Identifier of a fake P that is used when we trace without a real P. 82 traceGlobProc = -1 83 // Maximum number of bytes to encode uint64 in base-128. 84 traceBytesPerNumber = 10 85 // Shift of the number of arguments in the first event byte. 86 traceArgCountShift = 6 87 // Flag passed to traceGoPark to denote that the previous wakeup of this 88 // goroutine was futile. For example, a goroutine was unblocked on a mutex, 89 // but another goroutine got ahead and acquired the mutex before the first 90 // goroutine is scheduled, so the first goroutine has to block again. 91 // Such wakeups happen on buffered channels and sync.Mutex, 92 // but are generally not interesting for end user. 93 traceFutileWakeup byte = 128 94 ) 95 96 // trace is global tracing context. 97 var trace struct { 98 lock mutex // protects the following members 99 lockOwner *g // to avoid deadlocks during recursive lock locks 100 enabled bool // when set runtime traces events 101 shutdown bool // set when we are waiting for trace reader to finish after setting enabled to false 102 headerWritten bool // whether ReadTrace has emitted trace header 103 footerWritten bool // whether ReadTrace has emitted trace footer 104 shutdownSema uint32 // used to wait for ReadTrace completion 105 seqStart uint64 // sequence number when tracing was started 106 ticksStart int64 // cputicks when tracing was started 107 ticksEnd int64 // cputicks when tracing was stopped 108 timeStart int64 // nanotime when tracing was started 109 timeEnd int64 // nanotime when tracing was stopped 110 seqGC uint64 // GC start/done sequencer 111 reading traceBufPtr // buffer currently handed off to user 112 empty traceBufPtr // stack of empty buffers 113 fullHead traceBufPtr // queue of full buffers 114 fullTail traceBufPtr 115 reader *g // goroutine that called ReadTrace, or nil 116 stackTab traceStackTable // maps stack traces to unique ids 117 118 // Dictionary for traceEvString. 119 // Currently this is used only for func/file:line info after tracing session, 120 // so we assume single-threaded access. 121 strings map[string]uint64 122 stringSeq uint64 123 124 bufLock mutex // protects buf 125 buf traceBufPtr // global trace buffer, used when running without a p 126 } 127 128 // traceBufHeader is per-P tracing buffer. 129 type traceBufHeader struct { 130 link traceBufPtr // in trace.empty/full 131 lastTicks uint64 // when we wrote the last event 132 pos int // next write offset in arr 133 stk [traceStackSize]uintptr // scratch buffer for traceback 134 } 135 136 // traceBuf is per-P tracing buffer. 137 type traceBuf struct { 138 traceBufHeader 139 arr [64<<10 - unsafe.Sizeof(traceBufHeader{})]byte // underlying buffer for traceBufHeader.buf 140 } 141 142 // traceBufPtr is a *traceBuf that is not traced by the garbage 143 // collector and doesn't have write barriers. traceBufs are not 144 // allocated from the GC'd heap, so this is safe, and are often 145 // manipulated in contexts where write barriers are not allowed, so 146 // this is necessary. 147 type traceBufPtr uintptr 148 149 func (tp traceBufPtr) ptr() *traceBuf { return (*traceBuf)(unsafe.Pointer(tp)) } 150 func (tp *traceBufPtr) set(b *traceBuf) { *tp = traceBufPtr(unsafe.Pointer(b)) } 151 func traceBufPtrOf(b *traceBuf) traceBufPtr { 152 return traceBufPtr(unsafe.Pointer(b)) 153 } 154 155 // StartTrace enables tracing for the current process. 156 // While tracing, the data will be buffered and available via ReadTrace. 157 // StartTrace returns an error if tracing is already enabled. 158 // Most clients should use the runtime/trace package or the testing package's 159 // -test.trace flag instead of calling StartTrace directly. 160 func StartTrace() error { 161 // Stop the world, so that we can take a consistent snapshot 162 // of all goroutines at the beginning of the trace. 163 stopTheWorld("start tracing") 164 165 // We are in stop-the-world, but syscalls can finish and write to trace concurrently. 166 // Exitsyscall could check trace.enabled long before and then suddenly wake up 167 // and decide to write to trace at a random point in time. 168 // However, such syscall will use the global trace.buf buffer, because we've 169 // acquired all p's by doing stop-the-world. So this protects us from such races. 170 lock(&trace.bufLock) 171 172 if trace.enabled || trace.shutdown { 173 unlock(&trace.bufLock) 174 startTheWorld() 175 return errorString("tracing is already enabled") 176 } 177 178 // Can't set trace.enabled yet. While the world is stopped, exitsyscall could 179 // already emit a delayed event (see exitTicks in exitsyscall) if we set trace.enabled here. 180 // That would lead to an inconsistent trace: 181 // - either GoSysExit appears before EvGoInSyscall, 182 // - or GoSysExit appears for a goroutine for which we don't emit EvGoInSyscall below. 183 // To instruct traceEvent that it must not ignore events below, we set startingtrace. 184 // trace.enabled is set afterwards once we have emitted all preliminary events. 185 _g_ := getg() 186 _g_.m.startingtrace = true 187 for _, gp := range allgs { 188 status := readgstatus(gp) 189 if status != _Gdead { 190 traceGoCreate(gp, gp.startpc) // also resets gp.traceseq/tracelastp 191 } 192 if status == _Gwaiting { 193 // traceEvGoWaiting is implied to have seq=1. 194 gp.traceseq++ 195 traceEvent(traceEvGoWaiting, -1, uint64(gp.goid)) 196 } 197 if status == _Gsyscall { 198 gp.traceseq++ 199 traceEvent(traceEvGoInSyscall, -1, uint64(gp.goid)) 200 } else { 201 gp.sysblocktraced = false 202 } 203 } 204 traceProcStart() 205 traceGoStart() 206 // Note: ticksStart needs to be set after we emit traceEvGoInSyscall events. 207 // If we do it the other way around, it is possible that exitsyscall will 208 // query sysexitticks after ticksStart but before traceEvGoInSyscall timestamp. 209 // It will lead to a false conclusion that cputicks is broken. 210 trace.ticksStart = cputicks() 211 trace.timeStart = nanotime() 212 trace.headerWritten = false 213 trace.footerWritten = false 214 trace.strings = make(map[string]uint64) 215 trace.stringSeq = 0 216 trace.seqGC = 0 217 _g_.m.startingtrace = false 218 trace.enabled = true 219 220 unlock(&trace.bufLock) 221 222 startTheWorld() 223 return nil 224 } 225 226 // StopTrace stops tracing, if it was previously enabled. 227 // StopTrace only returns after all the reads for the trace have completed. 228 func StopTrace() { 229 // Stop the world so that we can collect the trace buffers from all p's below, 230 // and also to avoid races with traceEvent. 231 stopTheWorld("stop tracing") 232 233 // See the comment in StartTrace. 234 lock(&trace.bufLock) 235 236 if !trace.enabled { 237 unlock(&trace.bufLock) 238 startTheWorld() 239 return 240 } 241 242 traceGoSched() 243 244 for _, p := range &allp { 245 if p == nil { 246 break 247 } 248 buf := p.tracebuf 249 if buf != 0 { 250 traceFullQueue(buf) 251 p.tracebuf = 0 252 } 253 } 254 if trace.buf != 0 && trace.buf.ptr().pos != 0 { 255 buf := trace.buf 256 trace.buf = 0 257 traceFullQueue(buf) 258 } 259 260 for { 261 trace.ticksEnd = cputicks() 262 trace.timeEnd = nanotime() 263 // Windows time can tick only every 15ms, wait for at least one tick. 264 if trace.timeEnd != trace.timeStart { 265 break 266 } 267 osyield() 268 } 269 270 trace.enabled = false 271 trace.shutdown = true 272 unlock(&trace.bufLock) 273 274 startTheWorld() 275 276 // The world is started but we've set trace.shutdown, so new tracing can't start. 277 // Wait for the trace reader to flush pending buffers and stop. 278 semacquire(&trace.shutdownSema, false) 279 if raceenabled { 280 raceacquire(unsafe.Pointer(&trace.shutdownSema)) 281 } 282 283 // The lock protects us from races with StartTrace/StopTrace because they do stop-the-world. 284 lock(&trace.lock) 285 for _, p := range &allp { 286 if p == nil { 287 break 288 } 289 if p.tracebuf != 0 { 290 throw("trace: non-empty trace buffer in proc") 291 } 292 } 293 if trace.buf != 0 { 294 throw("trace: non-empty global trace buffer") 295 } 296 if trace.fullHead != 0 || trace.fullTail != 0 { 297 throw("trace: non-empty full trace buffer") 298 } 299 if trace.reading != 0 || trace.reader != nil { 300 throw("trace: reading after shutdown") 301 } 302 for trace.empty != 0 { 303 buf := trace.empty 304 trace.empty = buf.ptr().link 305 sysFree(unsafe.Pointer(buf), unsafe.Sizeof(*buf.ptr()), &memstats.other_sys) 306 } 307 trace.strings = nil 308 trace.shutdown = false 309 unlock(&trace.lock) 310 } 311 312 // ReadTrace returns the next chunk of binary tracing data, blocking until data 313 // is available. If tracing is turned off and all the data accumulated while it 314 // was on has been returned, ReadTrace returns nil. The caller must copy the 315 // returned data before calling ReadTrace again. 316 // ReadTrace must be called from one goroutine at a time. 317 func ReadTrace() []byte { 318 // This function may need to lock trace.lock recursively 319 // (goparkunlock -> traceGoPark -> traceEvent -> traceFlush). 320 // To allow this we use trace.lockOwner. 321 // Also this function must not allocate while holding trace.lock: 322 // allocation can call heap allocate, which will try to emit a trace 323 // event while holding heap lock. 324 lock(&trace.lock) 325 trace.lockOwner = getg() 326 327 if trace.reader != nil { 328 // More than one goroutine reads trace. This is bad. 329 // But we rather do not crash the program because of tracing, 330 // because tracing can be enabled at runtime on prod servers. 331 trace.lockOwner = nil 332 unlock(&trace.lock) 333 println("runtime: ReadTrace called from multiple goroutines simultaneously") 334 return nil 335 } 336 // Recycle the old buffer. 337 if buf := trace.reading; buf != 0 { 338 buf.ptr().link = trace.empty 339 trace.empty = buf 340 trace.reading = 0 341 } 342 // Write trace header. 343 if !trace.headerWritten { 344 trace.headerWritten = true 345 trace.lockOwner = nil 346 unlock(&trace.lock) 347 return []byte("go 1.7 trace\x00\x00\x00\x00") 348 } 349 // Wait for new data. 350 if trace.fullHead == 0 && !trace.shutdown { 351 trace.reader = getg() 352 goparkunlock(&trace.lock, "trace reader (blocked)", traceEvGoBlock, 2) 353 lock(&trace.lock) 354 } 355 // Write a buffer. 356 if trace.fullHead != 0 { 357 buf := traceFullDequeue() 358 trace.reading = buf 359 trace.lockOwner = nil 360 unlock(&trace.lock) 361 return buf.ptr().arr[:buf.ptr().pos] 362 } 363 // Write footer with timer frequency. 364 if !trace.footerWritten { 365 trace.footerWritten = true 366 // Use float64 because (trace.ticksEnd - trace.ticksStart) * 1e9 can overflow int64. 367 freq := float64(trace.ticksEnd-trace.ticksStart) * 1e9 / float64(trace.timeEnd-trace.timeStart) / traceTickDiv 368 trace.lockOwner = nil 369 unlock(&trace.lock) 370 var data []byte 371 data = append(data, traceEvFrequency|0<<traceArgCountShift) 372 data = traceAppend(data, uint64(freq)) 373 if timers.gp != nil { 374 data = append(data, traceEvTimerGoroutine|0<<traceArgCountShift) 375 data = traceAppend(data, uint64(timers.gp.goid)) 376 } 377 // This will emit a bunch of full buffers, we will pick them up 378 // on the next iteration. 379 trace.stackTab.dump() 380 return data 381 } 382 // Done. 383 if trace.shutdown { 384 trace.lockOwner = nil 385 unlock(&trace.lock) 386 if raceenabled { 387 // Model synchronization on trace.shutdownSema, which race 388 // detector does not see. This is required to avoid false 389 // race reports on writer passed to trace.Start. 390 racerelease(unsafe.Pointer(&trace.shutdownSema)) 391 } 392 // trace.enabled is already reset, so can call traceable functions. 393 semrelease(&trace.shutdownSema) 394 return nil 395 } 396 // Also bad, but see the comment above. 397 trace.lockOwner = nil 398 unlock(&trace.lock) 399 println("runtime: spurious wakeup of trace reader") 400 return nil 401 } 402 403 // traceReader returns the trace reader that should be woken up, if any. 404 func traceReader() *g { 405 if trace.reader == nil || (trace.fullHead == 0 && !trace.shutdown) { 406 return nil 407 } 408 lock(&trace.lock) 409 if trace.reader == nil || (trace.fullHead == 0 && !trace.shutdown) { 410 unlock(&trace.lock) 411 return nil 412 } 413 gp := trace.reader 414 trace.reader = nil 415 unlock(&trace.lock) 416 return gp 417 } 418 419 // traceProcFree frees trace buffer associated with pp. 420 func traceProcFree(pp *p) { 421 buf := pp.tracebuf 422 pp.tracebuf = 0 423 if buf == 0 { 424 return 425 } 426 lock(&trace.lock) 427 traceFullQueue(buf) 428 unlock(&trace.lock) 429 } 430 431 // traceFullQueue queues buf into queue of full buffers. 432 func traceFullQueue(buf traceBufPtr) { 433 buf.ptr().link = 0 434 if trace.fullHead == 0 { 435 trace.fullHead = buf 436 } else { 437 trace.fullTail.ptr().link = buf 438 } 439 trace.fullTail = buf 440 } 441 442 // traceFullDequeue dequeues from queue of full buffers. 443 func traceFullDequeue() traceBufPtr { 444 buf := trace.fullHead 445 if buf == 0 { 446 return 0 447 } 448 trace.fullHead = buf.ptr().link 449 if trace.fullHead == 0 { 450 trace.fullTail = 0 451 } 452 buf.ptr().link = 0 453 return buf 454 } 455 456 // traceEvent writes a single event to trace buffer, flushing the buffer if necessary. 457 // ev is event type. 458 // If skip > 0, write current stack id as the last argument (skipping skip top frames). 459 // If skip = 0, this event type should contain a stack, but we don't want 460 // to collect and remember it for this particular call. 461 func traceEvent(ev byte, skip int, args ...uint64) { 462 mp, pid, bufp := traceAcquireBuffer() 463 // Double-check trace.enabled now that we've done m.locks++ and acquired bufLock. 464 // This protects from races between traceEvent and StartTrace/StopTrace. 465 466 // The caller checked that trace.enabled == true, but trace.enabled might have been 467 // turned off between the check and now. Check again. traceLockBuffer did mp.locks++, 468 // StopTrace does stopTheWorld, and stopTheWorld waits for mp.locks to go back to zero, 469 // so if we see trace.enabled == true now, we know it's true for the rest of the function. 470 // Exitsyscall can run even during stopTheWorld. The race with StartTrace/StopTrace 471 // during tracing in exitsyscall is resolved by locking trace.bufLock in traceLockBuffer. 472 if !trace.enabled && !mp.startingtrace { 473 traceReleaseBuffer(pid) 474 return 475 } 476 buf := (*bufp).ptr() 477 const maxSize = 2 + 5*traceBytesPerNumber // event type, length, sequence, timestamp, stack id and two add params 478 if buf == nil || len(buf.arr)-buf.pos < maxSize { 479 buf = traceFlush(traceBufPtrOf(buf)).ptr() 480 (*bufp).set(buf) 481 } 482 483 ticks := uint64(cputicks()) / traceTickDiv 484 tickDiff := ticks - buf.lastTicks 485 if buf.pos == 0 { 486 buf.byte(traceEvBatch | 1<<traceArgCountShift) 487 buf.varint(uint64(pid)) 488 buf.varint(ticks) 489 tickDiff = 0 490 } 491 buf.lastTicks = ticks 492 narg := byte(len(args)) 493 if skip >= 0 { 494 narg++ 495 } 496 // We have only 2 bits for number of arguments. 497 // If number is >= 3, then the event type is followed by event length in bytes. 498 if narg > 3 { 499 narg = 3 500 } 501 startPos := buf.pos 502 buf.byte(ev | narg<<traceArgCountShift) 503 var lenp *byte 504 if narg == 3 { 505 // Reserve the byte for length assuming that length < 128. 506 buf.varint(0) 507 lenp = &buf.arr[buf.pos-1] 508 } 509 buf.varint(tickDiff) 510 for _, a := range args { 511 buf.varint(a) 512 } 513 if skip == 0 { 514 buf.varint(0) 515 } else if skip > 0 { 516 _g_ := getg() 517 gp := mp.curg 518 var nstk int 519 if gp == _g_ { 520 nstk = callers(skip, buf.stk[:]) 521 } else if gp != nil { 522 gp = mp.curg 523 // This may happen when tracing a system call, 524 // so we must lock the stack. 525 if gcTryLockStackBarriers(gp) { 526 nstk = gcallers(gp, skip, buf.stk[:]) 527 gcUnlockStackBarriers(gp) 528 } 529 } 530 if nstk > 0 { 531 nstk-- // skip runtime.goexit 532 } 533 if nstk > 0 && gp.goid == 1 { 534 nstk-- // skip runtime.main 535 } 536 id := trace.stackTab.put(buf.stk[:nstk]) 537 buf.varint(uint64(id)) 538 } 539 evSize := buf.pos - startPos 540 if evSize > maxSize { 541 throw("invalid length of trace event") 542 } 543 if lenp != nil { 544 // Fill in actual length. 545 *lenp = byte(evSize - 2) 546 } 547 traceReleaseBuffer(pid) 548 } 549 550 // traceAcquireBuffer returns trace buffer to use and, if necessary, locks it. 551 func traceAcquireBuffer() (mp *m, pid int32, bufp *traceBufPtr) { 552 mp = acquirem() 553 if p := mp.p.ptr(); p != nil { 554 return mp, p.id, &p.tracebuf 555 } 556 lock(&trace.bufLock) 557 return mp, traceGlobProc, &trace.buf 558 } 559 560 // traceReleaseBuffer releases a buffer previously acquired with traceAcquireBuffer. 561 func traceReleaseBuffer(pid int32) { 562 if pid == traceGlobProc { 563 unlock(&trace.bufLock) 564 } 565 releasem(getg().m) 566 } 567 568 // traceFlush puts buf onto stack of full buffers and returns an empty buffer. 569 func traceFlush(buf traceBufPtr) traceBufPtr { 570 owner := trace.lockOwner 571 dolock := owner == nil || owner != getg().m.curg 572 if dolock { 573 lock(&trace.lock) 574 } 575 if buf != 0 { 576 traceFullQueue(buf) 577 } 578 if trace.empty != 0 { 579 buf = trace.empty 580 trace.empty = buf.ptr().link 581 } else { 582 buf = traceBufPtr(sysAlloc(unsafe.Sizeof(traceBuf{}), &memstats.other_sys)) 583 if buf == 0 { 584 throw("trace: out of memory") 585 } 586 } 587 bufp := buf.ptr() 588 bufp.link.set(nil) 589 bufp.pos = 0 590 bufp.lastTicks = 0 591 if dolock { 592 unlock(&trace.lock) 593 } 594 return buf 595 } 596 597 func traceString(buf *traceBuf, s string) (uint64, *traceBuf) { 598 if s == "" { 599 return 0, buf 600 } 601 if id, ok := trace.strings[s]; ok { 602 return id, buf 603 } 604 605 trace.stringSeq++ 606 id := trace.stringSeq 607 trace.strings[s] = id 608 609 size := 1 + 2*traceBytesPerNumber + len(s) 610 if len(buf.arr)-buf.pos < size { 611 buf = traceFlush(traceBufPtrOf(buf)).ptr() 612 } 613 buf.byte(traceEvString) 614 buf.varint(id) 615 buf.varint(uint64(len(s))) 616 buf.pos += copy(buf.arr[buf.pos:], s) 617 return id, buf 618 } 619 620 // traceAppend appends v to buf in little-endian-base-128 encoding. 621 func traceAppend(buf []byte, v uint64) []byte { 622 for ; v >= 0x80; v >>= 7 { 623 buf = append(buf, 0x80|byte(v)) 624 } 625 buf = append(buf, byte(v)) 626 return buf 627 } 628 629 // varint appends v to buf in little-endian-base-128 encoding. 630 func (buf *traceBuf) varint(v uint64) { 631 pos := buf.pos 632 for ; v >= 0x80; v >>= 7 { 633 buf.arr[pos] = 0x80 | byte(v) 634 pos++ 635 } 636 buf.arr[pos] = byte(v) 637 pos++ 638 buf.pos = pos 639 } 640 641 // byte appends v to buf. 642 func (buf *traceBuf) byte(v byte) { 643 buf.arr[buf.pos] = v 644 buf.pos++ 645 } 646 647 // traceStackTable maps stack traces (arrays of PC's) to unique uint32 ids. 648 // It is lock-free for reading. 649 type traceStackTable struct { 650 lock mutex 651 seq uint32 652 mem traceAlloc 653 tab [1 << 13]traceStackPtr 654 } 655 656 // traceStack is a single stack in traceStackTable. 657 type traceStack struct { 658 link traceStackPtr 659 hash uintptr 660 id uint32 661 n int 662 stk [0]uintptr // real type [n]uintptr 663 } 664 665 type traceStackPtr uintptr 666 667 func (tp traceStackPtr) ptr() *traceStack { return (*traceStack)(unsafe.Pointer(tp)) } 668 669 // stack returns slice of PCs. 670 func (ts *traceStack) stack() []uintptr { 671 return (*[traceStackSize]uintptr)(unsafe.Pointer(&ts.stk))[:ts.n] 672 } 673 674 // put returns a unique id for the stack trace pcs and caches it in the table, 675 // if it sees the trace for the first time. 676 func (tab *traceStackTable) put(pcs []uintptr) uint32 { 677 if len(pcs) == 0 { 678 return 0 679 } 680 hash := memhash(unsafe.Pointer(&pcs[0]), 0, uintptr(len(pcs))*unsafe.Sizeof(pcs[0])) 681 // First, search the hashtable w/o the mutex. 682 if id := tab.find(pcs, hash); id != 0 { 683 return id 684 } 685 // Now, double check under the mutex. 686 lock(&tab.lock) 687 if id := tab.find(pcs, hash); id != 0 { 688 unlock(&tab.lock) 689 return id 690 } 691 // Create new record. 692 tab.seq++ 693 stk := tab.newStack(len(pcs)) 694 stk.hash = hash 695 stk.id = tab.seq 696 stk.n = len(pcs) 697 stkpc := stk.stack() 698 for i, pc := range pcs { 699 stkpc[i] = pc 700 } 701 part := int(hash % uintptr(len(tab.tab))) 702 stk.link = tab.tab[part] 703 atomicstorep(unsafe.Pointer(&tab.tab[part]), unsafe.Pointer(stk)) 704 unlock(&tab.lock) 705 return stk.id 706 } 707 708 // find checks if the stack trace pcs is already present in the table. 709 func (tab *traceStackTable) find(pcs []uintptr, hash uintptr) uint32 { 710 part := int(hash % uintptr(len(tab.tab))) 711 Search: 712 for stk := tab.tab[part].ptr(); stk != nil; stk = stk.link.ptr() { 713 if stk.hash == hash && stk.n == len(pcs) { 714 for i, stkpc := range stk.stack() { 715 if stkpc != pcs[i] { 716 continue Search 717 } 718 } 719 return stk.id 720 } 721 } 722 return 0 723 } 724 725 // newStack allocates a new stack of size n. 726 func (tab *traceStackTable) newStack(n int) *traceStack { 727 return (*traceStack)(tab.mem.alloc(unsafe.Sizeof(traceStack{}) + uintptr(n)*sys.PtrSize)) 728 } 729 730 // dump writes all previously cached stacks to trace buffers, 731 // releases all memory and resets state. 732 func (tab *traceStackTable) dump() { 733 frames := make(map[uintptr]traceFrame) 734 var tmp [(2 + 4*traceStackSize) * traceBytesPerNumber]byte 735 buf := traceFlush(0).ptr() 736 for _, stk := range tab.tab { 737 stk := stk.ptr() 738 for ; stk != nil; stk = stk.link.ptr() { 739 tmpbuf := tmp[:0] 740 tmpbuf = traceAppend(tmpbuf, uint64(stk.id)) 741 tmpbuf = traceAppend(tmpbuf, uint64(stk.n)) 742 for _, pc := range stk.stack() { 743 var frame traceFrame 744 frame, buf = traceFrameForPC(buf, frames, pc) 745 tmpbuf = traceAppend(tmpbuf, uint64(pc)) 746 tmpbuf = traceAppend(tmpbuf, uint64(frame.funcID)) 747 tmpbuf = traceAppend(tmpbuf, uint64(frame.fileID)) 748 tmpbuf = traceAppend(tmpbuf, uint64(frame.line)) 749 } 750 // Now copy to the buffer. 751 size := 1 + traceBytesPerNumber + len(tmpbuf) 752 if len(buf.arr)-buf.pos < size { 753 buf = traceFlush(traceBufPtrOf(buf)).ptr() 754 } 755 buf.byte(traceEvStack | 3<<traceArgCountShift) 756 buf.varint(uint64(len(tmpbuf))) 757 buf.pos += copy(buf.arr[buf.pos:], tmpbuf) 758 } 759 } 760 761 lock(&trace.lock) 762 traceFullQueue(traceBufPtrOf(buf)) 763 unlock(&trace.lock) 764 765 tab.mem.drop() 766 *tab = traceStackTable{} 767 } 768 769 type traceFrame struct { 770 funcID uint64 771 fileID uint64 772 line uint64 773 } 774 775 func traceFrameForPC(buf *traceBuf, frames map[uintptr]traceFrame, pc uintptr) (traceFrame, *traceBuf) { 776 if frame, ok := frames[pc]; ok { 777 return frame, buf 778 } 779 780 var frame traceFrame 781 f := findfunc(pc) 782 if f == nil { 783 frames[pc] = frame 784 return frame, buf 785 } 786 787 fn := funcname(f) 788 const maxLen = 1 << 10 789 if len(fn) > maxLen { 790 fn = fn[len(fn)-maxLen:] 791 } 792 frame.funcID, buf = traceString(buf, fn) 793 file, line := funcline(f, pc-sys.PCQuantum) 794 frame.line = uint64(line) 795 if len(file) > maxLen { 796 file = file[len(file)-maxLen:] 797 } 798 frame.fileID, buf = traceString(buf, file) 799 return frame, buf 800 } 801 802 // traceAlloc is a non-thread-safe region allocator. 803 // It holds a linked list of traceAllocBlock. 804 type traceAlloc struct { 805 head traceAllocBlockPtr 806 off uintptr 807 } 808 809 // traceAllocBlock is a block in traceAlloc. 810 // 811 // traceAllocBlock is allocated from non-GC'd memory, so it must not 812 // contain heap pointers. Writes to pointers to traceAllocBlocks do 813 // not need write barriers. 814 type traceAllocBlock struct { 815 next traceAllocBlockPtr 816 data [64<<10 - sys.PtrSize]byte 817 } 818 819 type traceAllocBlockPtr uintptr 820 821 func (p traceAllocBlockPtr) ptr() *traceAllocBlock { return (*traceAllocBlock)(unsafe.Pointer(p)) } 822 func (p *traceAllocBlockPtr) set(x *traceAllocBlock) { *p = traceAllocBlockPtr(unsafe.Pointer(x)) } 823 824 // alloc allocates n-byte block. 825 func (a *traceAlloc) alloc(n uintptr) unsafe.Pointer { 826 n = round(n, sys.PtrSize) 827 if a.head == 0 || a.off+n > uintptr(len(a.head.ptr().data)) { 828 if n > uintptr(len(a.head.ptr().data)) { 829 throw("trace: alloc too large") 830 } 831 block := (*traceAllocBlock)(sysAlloc(unsafe.Sizeof(traceAllocBlock{}), &memstats.other_sys)) 832 if block == nil { 833 throw("trace: out of memory") 834 } 835 block.next.set(a.head.ptr()) 836 a.head.set(block) 837 a.off = 0 838 } 839 p := &a.head.ptr().data[a.off] 840 a.off += n 841 return unsafe.Pointer(p) 842 } 843 844 // drop frees all previously allocated memory and resets the allocator. 845 func (a *traceAlloc) drop() { 846 for a.head != 0 { 847 block := a.head.ptr() 848 a.head.set(block.next.ptr()) 849 sysFree(unsafe.Pointer(block), unsafe.Sizeof(traceAllocBlock{}), &memstats.other_sys) 850 } 851 } 852 853 // The following functions write specific events to trace. 854 855 func traceGomaxprocs(procs int32) { 856 traceEvent(traceEvGomaxprocs, 1, uint64(procs)) 857 } 858 859 func traceProcStart() { 860 traceEvent(traceEvProcStart, -1, uint64(getg().m.id)) 861 } 862 863 func traceProcStop(pp *p) { 864 // Sysmon and stopTheWorld can stop Ps blocked in syscalls, 865 // to handle this we temporary employ the P. 866 mp := acquirem() 867 oldp := mp.p 868 mp.p.set(pp) 869 traceEvent(traceEvProcStop, -1) 870 mp.p = oldp 871 releasem(mp) 872 } 873 874 func traceGCStart() { 875 traceEvent(traceEvGCStart, 3, trace.seqGC) 876 trace.seqGC++ 877 } 878 879 func traceGCDone() { 880 traceEvent(traceEvGCDone, -1) 881 } 882 883 func traceGCScanStart() { 884 traceEvent(traceEvGCScanStart, -1) 885 } 886 887 func traceGCScanDone() { 888 traceEvent(traceEvGCScanDone, -1) 889 } 890 891 func traceGCSweepStart() { 892 traceEvent(traceEvGCSweepStart, 1) 893 } 894 895 func traceGCSweepDone() { 896 traceEvent(traceEvGCSweepDone, -1) 897 } 898 899 func traceGoCreate(newg *g, pc uintptr) { 900 newg.traceseq = 0 901 newg.tracelastp = getg().m.p 902 // +PCQuantum because traceFrameForPC expects return PCs and subtracts PCQuantum. 903 id := trace.stackTab.put([]uintptr{pc + sys.PCQuantum}) 904 traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(id)) 905 } 906 907 func traceGoStart() { 908 _g_ := getg().m.curg 909 _p_ := _g_.m.p 910 _g_.traceseq++ 911 if _g_.tracelastp == _p_ { 912 traceEvent(traceEvGoStartLocal, -1, uint64(_g_.goid)) 913 } else { 914 _g_.tracelastp = _p_ 915 traceEvent(traceEvGoStart, -1, uint64(_g_.goid), _g_.traceseq) 916 } 917 } 918 919 func traceGoEnd() { 920 traceEvent(traceEvGoEnd, -1) 921 } 922 923 func traceGoSched() { 924 _g_ := getg() 925 _g_.tracelastp = _g_.m.p 926 traceEvent(traceEvGoSched, 1) 927 } 928 929 func traceGoPreempt() { 930 _g_ := getg() 931 _g_.tracelastp = _g_.m.p 932 traceEvent(traceEvGoPreempt, 1) 933 } 934 935 func traceGoPark(traceEv byte, skip int, gp *g) { 936 if traceEv&traceFutileWakeup != 0 { 937 traceEvent(traceEvFutileWakeup, -1) 938 } 939 traceEvent(traceEv & ^traceFutileWakeup, skip) 940 } 941 942 func traceGoUnpark(gp *g, skip int) { 943 _p_ := getg().m.p 944 gp.traceseq++ 945 if gp.tracelastp == _p_ { 946 traceEvent(traceEvGoUnblockLocal, skip, uint64(gp.goid)) 947 } else { 948 gp.tracelastp = _p_ 949 traceEvent(traceEvGoUnblock, skip, uint64(gp.goid), gp.traceseq) 950 } 951 } 952 953 func traceGoSysCall() { 954 traceEvent(traceEvGoSysCall, 1) 955 } 956 957 func traceGoSysExit(ts int64) { 958 if ts != 0 && ts < trace.ticksStart { 959 // There is a race between the code that initializes sysexitticks 960 // (in exitsyscall, which runs without a P, and therefore is not 961 // stopped with the rest of the world) and the code that initializes 962 // a new trace. The recorded sysexitticks must therefore be treated 963 // as "best effort". If they are valid for this trace, then great, 964 // use them for greater accuracy. But if they're not valid for this 965 // trace, assume that the trace was started after the actual syscall 966 // exit (but before we actually managed to start the goroutine, 967 // aka right now), and assign a fresh time stamp to keep the log consistent. 968 ts = 0 969 } 970 _g_ := getg().m.curg 971 _g_.traceseq++ 972 _g_.tracelastp = _g_.m.p 973 traceEvent(traceEvGoSysExit, -1, uint64(_g_.goid), _g_.traceseq, uint64(ts)/traceTickDiv) 974 } 975 976 func traceGoSysBlock(pp *p) { 977 // Sysmon and stopTheWorld can declare syscalls running on remote Ps as blocked, 978 // to handle this we temporary employ the P. 979 mp := acquirem() 980 oldp := mp.p 981 mp.p.set(pp) 982 traceEvent(traceEvGoSysBlock, -1) 983 mp.p = oldp 984 releasem(mp) 985 } 986 987 func traceHeapAlloc() { 988 traceEvent(traceEvHeapAlloc, -1, memstats.heap_live) 989 } 990 991 func traceNextGC() { 992 traceEvent(traceEvNextGC, -1, memstats.next_gc) 993 }