github.com/4ad/go@v0.0.0-20161219182952-69a12818b605/src/cmd/trace/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 package main 6 7 import ( 8 "encoding/json" 9 "fmt" 10 "internal/trace" 11 "log" 12 "net/http" 13 "path/filepath" 14 "runtime" 15 "strconv" 16 "strings" 17 "time" 18 ) 19 20 func init() { 21 http.HandleFunc("/trace", httpTrace) 22 http.HandleFunc("/jsontrace", httpJsonTrace) 23 http.HandleFunc("/trace_viewer_html", httpTraceViewerHTML) 24 } 25 26 // httpTrace serves either whole trace (goid==0) or trace for goid goroutine. 27 func httpTrace(w http.ResponseWriter, r *http.Request) { 28 _, err := parseEvents() 29 if err != nil { 30 http.Error(w, err.Error(), http.StatusInternalServerError) 31 return 32 } 33 if err := r.ParseForm(); err != nil { 34 http.Error(w, err.Error(), http.StatusInternalServerError) 35 return 36 } 37 html := strings.Replace(templTrace, "{{PARAMS}}", r.Form.Encode(), -1) 38 w.Write([]byte(html)) 39 40 } 41 42 // See https://github.com/catapult-project/catapult/blob/master/tracing/docs/embedding-trace-viewer.md 43 // This is almost verbatim copy of: 44 // https://github.com/catapult-project/catapult/blob/master/tracing/bin/index.html 45 // on revision 623a005a3ffa9de13c4b92bc72290e7bcd1ca591. 46 var templTrace = ` 47 <html> 48 <head> 49 <link href="/trace_viewer_html" rel="import"> 50 <script> 51 (function() { 52 var viewer; 53 var url; 54 var model; 55 56 function load() { 57 var req = new XMLHttpRequest(); 58 var is_binary = /[.]gz$/.test(url) || /[.]zip$/.test(url); 59 req.overrideMimeType('text/plain; charset=x-user-defined'); 60 req.open('GET', url, true); 61 if (is_binary) 62 req.responseType = 'arraybuffer'; 63 64 req.onreadystatechange = function(event) { 65 if (req.readyState !== 4) 66 return; 67 68 window.setTimeout(function() { 69 if (req.status === 200) 70 onResult(is_binary ? req.response : req.responseText); 71 else 72 onResultFail(req.status); 73 }, 0); 74 }; 75 req.send(null); 76 } 77 78 function onResultFail(err) { 79 var overlay = new tr.ui.b.Overlay(); 80 overlay.textContent = err + ': ' + url + ' could not be loaded'; 81 overlay.title = 'Failed to fetch data'; 82 overlay.visible = true; 83 } 84 85 function onResult(result) { 86 model = new tr.Model(); 87 var i = new tr.importer.Import(model); 88 var p = i.importTracesWithProgressDialog([result]); 89 p.then(onModelLoaded, onImportFail); 90 } 91 92 function onModelLoaded() { 93 viewer.model = model; 94 viewer.viewTitle = "trace"; 95 } 96 97 function onImportFail() { 98 var overlay = new tr.ui.b.Overlay(); 99 overlay.textContent = tr.b.normalizeException(err).message; 100 overlay.title = 'Import error'; 101 overlay.visible = true; 102 } 103 104 document.addEventListener('DOMContentLoaded', function() { 105 var container = document.createElement('track-view-container'); 106 container.id = 'track_view_container'; 107 108 viewer = document.createElement('tr-ui-timeline-view'); 109 viewer.track_view_container = container; 110 viewer.appendChild(container); 111 112 viewer.id = 'trace-viewer'; 113 viewer.globalMode = true; 114 document.body.appendChild(viewer); 115 116 url = '/jsontrace?{{PARAMS}}'; 117 load(); 118 }); 119 }()); 120 </script> 121 </head> 122 <body> 123 </body> 124 </html> 125 ` 126 127 // httpTraceViewerHTML serves static part of trace-viewer. 128 // This URL is queried from templTrace HTML. 129 func httpTraceViewerHTML(w http.ResponseWriter, r *http.Request) { 130 http.ServeFile(w, r, filepath.Join(runtime.GOROOT(), "misc", "trace", "trace_viewer_lean.html")) 131 } 132 133 // httpJsonTrace serves json trace, requested from within templTrace HTML. 134 func httpJsonTrace(w http.ResponseWriter, r *http.Request) { 135 // This is an AJAX handler, so instead of http.Error we use log.Printf to log errors. 136 events, err := parseEvents() 137 if err != nil { 138 log.Printf("failed to parse trace: %v", err) 139 return 140 } 141 142 params := &traceParams{ 143 events: events, 144 endTime: int64(1<<63 - 1), 145 } 146 147 if goids := r.FormValue("goid"); goids != "" { 148 // If goid argument is present, we are rendering a trace for this particular goroutine. 149 goid, err := strconv.ParseUint(goids, 10, 64) 150 if err != nil { 151 log.Printf("failed to parse goid parameter '%v': %v", goids, err) 152 return 153 } 154 analyzeGoroutines(events) 155 g := gs[goid] 156 params.gtrace = true 157 params.startTime = g.StartTime 158 params.endTime = g.EndTime 159 params.maing = goid 160 params.gs = trace.RelatedGoroutines(events, goid) 161 } 162 163 data := generateTrace(params) 164 165 if startStr, endStr := r.FormValue("start"), r.FormValue("end"); startStr != "" && endStr != "" { 166 // If start/end arguments are present, we are rendering a range of the trace. 167 start, err := strconv.ParseUint(startStr, 10, 64) 168 if err != nil { 169 log.Printf("failed to parse start parameter '%v': %v", startStr, err) 170 return 171 } 172 end, err := strconv.ParseUint(endStr, 10, 64) 173 if err != nil { 174 log.Printf("failed to parse end parameter '%v': %v", endStr, err) 175 return 176 } 177 if start >= uint64(len(data.Events)) || end <= start || end > uint64(len(data.Events)) { 178 log.Printf("bogus start/end parameters: %v/%v, trace size %v", start, end, len(data.Events)) 179 return 180 } 181 data.Events = append(data.Events[start:end], data.Events[data.footer:]...) 182 } 183 err = json.NewEncoder(w).Encode(data) 184 if err != nil { 185 log.Printf("failed to serialize trace: %v", err) 186 return 187 } 188 } 189 190 type Range struct { 191 Name string 192 Start int 193 End int 194 } 195 196 // splitTrace splits the trace into a number of ranges, 197 // each resulting in approx 100MB of json output (trace viewer can hardly handle more). 198 func splitTrace(data ViewerData) []Range { 199 const rangeSize = 100 << 20 200 var ranges []Range 201 cw := new(countingWriter) 202 enc := json.NewEncoder(cw) 203 // First calculate size of the mandatory part of the trace. 204 // This includes stack traces and thread names. 205 data1 := data 206 data1.Events = data.Events[data.footer:] 207 enc.Encode(data1) 208 auxSize := cw.size 209 cw.size = 0 210 // Then calculate size of each individual event and group them into ranges. 211 for i, start := 0, 0; i < data.footer; i++ { 212 enc.Encode(data.Events[i]) 213 if cw.size+auxSize > rangeSize || i == data.footer-1 { 214 ranges = append(ranges, Range{ 215 Name: fmt.Sprintf("%v-%v", time.Duration(data.Events[start].Time*1000), time.Duration(data.Events[i].Time*1000)), 216 Start: start, 217 End: i + 1, 218 }) 219 start = i + 1 220 cw.size = 0 221 } 222 } 223 if len(ranges) == 1 { 224 ranges = nil 225 } 226 return ranges 227 } 228 229 type countingWriter struct { 230 size int 231 } 232 233 func (cw *countingWriter) Write(data []byte) (int, error) { 234 cw.size += len(data) 235 return len(data), nil 236 } 237 238 type traceParams struct { 239 events []*trace.Event 240 gtrace bool 241 startTime int64 242 endTime int64 243 maing uint64 244 gs map[uint64]bool 245 } 246 247 type traceContext struct { 248 *traceParams 249 data ViewerData 250 frameTree frameNode 251 frameSeq int 252 arrowSeq uint64 253 heapAlloc uint64 254 nextGC uint64 255 gcount uint64 256 grunnable uint64 257 grunning uint64 258 insyscall uint64 259 prunning uint64 260 } 261 262 type frameNode struct { 263 id int 264 children map[uint64]frameNode 265 } 266 267 type ViewerData struct { 268 Events []*ViewerEvent `json:"traceEvents"` 269 Frames map[string]ViewerFrame `json:"stackFrames"` 270 TimeUnit string `json:"displayTimeUnit"` 271 272 // This is where mandatory part of the trace starts (e.g. thread names) 273 footer int 274 } 275 276 type ViewerEvent struct { 277 Name string `json:"name,omitempty"` 278 Phase string `json:"ph"` 279 Scope string `json:"s,omitempty"` 280 Time float64 `json:"ts"` 281 Dur float64 `json:"dur,omitempty"` 282 Pid uint64 `json:"pid"` 283 Tid uint64 `json:"tid"` 284 ID uint64 `json:"id,omitempty"` 285 Stack int `json:"sf,omitempty"` 286 EndStack int `json:"esf,omitempty"` 287 Arg interface{} `json:"args,omitempty"` 288 } 289 290 type ViewerFrame struct { 291 Name string `json:"name"` 292 Parent int `json:"parent,omitempty"` 293 } 294 295 type NameArg struct { 296 Name string `json:"name"` 297 } 298 299 type SortIndexArg struct { 300 Index int `json:"sort_index"` 301 } 302 303 // generateTrace generates json trace for trace-viewer: 304 // https://github.com/google/trace-viewer 305 // Trace format is described at: 306 // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view 307 // If gtrace=true, generate trace for goroutine goid, otherwise whole trace. 308 // startTime, endTime determine part of the trace that we are interested in. 309 // gset restricts goroutines that are included in the resulting trace. 310 func generateTrace(params *traceParams) ViewerData { 311 ctx := &traceContext{traceParams: params} 312 ctx.frameTree.children = make(map[uint64]frameNode) 313 ctx.data.Frames = make(map[string]ViewerFrame) 314 ctx.data.TimeUnit = "ns" 315 maxProc := 0 316 gnames := make(map[uint64]string) 317 for _, ev := range ctx.events { 318 // Handle trace.EvGoStart separately, because we need the goroutine name 319 // even if ignore the event otherwise. 320 if ev.Type == trace.EvGoStart { 321 if _, ok := gnames[ev.G]; !ok { 322 if len(ev.Stk) > 0 { 323 gnames[ev.G] = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn) 324 } else { 325 gnames[ev.G] = fmt.Sprintf("G%v", ev.G) 326 } 327 } 328 } 329 330 // Ignore events that are from uninteresting goroutines 331 // or outside of the interesting timeframe. 332 if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] { 333 continue 334 } 335 if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime { 336 continue 337 } 338 339 if ev.P < trace.FakeP && ev.P > maxProc { 340 maxProc = ev.P 341 } 342 343 switch ev.Type { 344 case trace.EvProcStart: 345 if ctx.gtrace { 346 continue 347 } 348 ctx.prunning++ 349 ctx.emitThreadCounters(ev) 350 ctx.emitInstant(ev, "proc start") 351 case trace.EvProcStop: 352 if ctx.gtrace { 353 continue 354 } 355 ctx.prunning-- 356 ctx.emitThreadCounters(ev) 357 ctx.emitInstant(ev, "proc stop") 358 case trace.EvGCStart: 359 ctx.emitSlice(ev, "GC") 360 case trace.EvGCDone: 361 case trace.EvGCScanStart: 362 if ctx.gtrace { 363 continue 364 } 365 ctx.emitSlice(ev, "MARK") 366 case trace.EvGCScanDone: 367 case trace.EvGCSweepStart: 368 ctx.emitSlice(ev, "SWEEP") 369 case trace.EvGCSweepDone: 370 case trace.EvGoStart: 371 ctx.grunnable-- 372 ctx.grunning++ 373 ctx.emitGoroutineCounters(ev) 374 ctx.emitSlice(ev, gnames[ev.G]) 375 case trace.EvGoCreate: 376 ctx.gcount++ 377 ctx.grunnable++ 378 ctx.emitGoroutineCounters(ev) 379 ctx.emitArrow(ev, "go") 380 case trace.EvGoEnd: 381 ctx.gcount-- 382 ctx.grunning-- 383 ctx.emitGoroutineCounters(ev) 384 case trace.EvGoUnblock: 385 ctx.grunnable++ 386 ctx.emitGoroutineCounters(ev) 387 ctx.emitArrow(ev, "unblock") 388 case trace.EvGoSysCall: 389 ctx.emitInstant(ev, "syscall") 390 case trace.EvGoSysExit: 391 ctx.grunnable++ 392 ctx.emitGoroutineCounters(ev) 393 ctx.insyscall-- 394 ctx.emitThreadCounters(ev) 395 ctx.emitArrow(ev, "sysexit") 396 case trace.EvGoSysBlock: 397 ctx.grunning-- 398 ctx.emitGoroutineCounters(ev) 399 ctx.insyscall++ 400 ctx.emitThreadCounters(ev) 401 case trace.EvGoSched, trace.EvGoPreempt: 402 ctx.grunnable++ 403 ctx.grunning-- 404 ctx.emitGoroutineCounters(ev) 405 case trace.EvGoStop, 406 trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv, 407 trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet: 408 ctx.grunning-- 409 ctx.emitGoroutineCounters(ev) 410 case trace.EvGoWaiting: 411 ctx.grunnable-- 412 ctx.emitGoroutineCounters(ev) 413 case trace.EvGoInSyscall: 414 ctx.insyscall++ 415 ctx.emitThreadCounters(ev) 416 case trace.EvHeapAlloc: 417 ctx.heapAlloc = ev.Args[0] 418 ctx.emitHeapCounters(ev) 419 case trace.EvNextGC: 420 ctx.nextGC = ev.Args[0] 421 ctx.emitHeapCounters(ev) 422 } 423 } 424 425 ctx.data.footer = len(ctx.data.Events) 426 ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 0, Arg: &NameArg{"PROCS"}}) 427 ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 0, Arg: &SortIndexArg{1}}) 428 429 ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 1, Arg: &NameArg{"STATS"}}) 430 ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 1, Arg: &SortIndexArg{0}}) 431 432 ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &NameArg{"Network"}}) 433 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &SortIndexArg{-5}}) 434 435 ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &NameArg{"Timers"}}) 436 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &SortIndexArg{-4}}) 437 438 ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}}) 439 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}}) 440 441 if !ctx.gtrace { 442 for i := 0; i <= maxProc; i++ { 443 ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}}) 444 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &SortIndexArg{i}}) 445 } 446 } 447 448 if ctx.gtrace && ctx.gs != nil { 449 for k, v := range gnames { 450 if !ctx.gs[k] { 451 continue 452 } 453 ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: k, Arg: &NameArg{v}}) 454 } 455 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: ctx.maing, Arg: &SortIndexArg{-2}}) 456 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: 0, Arg: &SortIndexArg{-1}}) 457 } 458 459 return ctx.data 460 } 461 462 func (ctx *traceContext) emit(e *ViewerEvent) { 463 ctx.data.Events = append(ctx.data.Events, e) 464 } 465 466 func (ctx *traceContext) time(ev *trace.Event) float64 { 467 // Trace viewer wants timestamps in microseconds. 468 return float64(ev.Ts-ctx.startTime) / 1000 469 } 470 471 func (ctx *traceContext) proc(ev *trace.Event) uint64 { 472 if ctx.gtrace && ev.P < trace.FakeP { 473 return ev.G 474 } else { 475 return uint64(ev.P) 476 } 477 } 478 479 func (ctx *traceContext) emitSlice(ev *trace.Event, name string) { 480 ctx.emit(&ViewerEvent{ 481 Name: name, 482 Phase: "X", 483 Time: ctx.time(ev), 484 Dur: ctx.time(ev.Link) - ctx.time(ev), 485 Tid: ctx.proc(ev), 486 Stack: ctx.stack(ev.Stk), 487 EndStack: ctx.stack(ev.Link.Stk), 488 }) 489 } 490 491 func (ctx *traceContext) emitHeapCounters(ev *trace.Event) { 492 type Arg struct { 493 Allocated uint64 494 NextGC uint64 495 } 496 if ctx.gtrace { 497 return 498 } 499 diff := uint64(0) 500 if ctx.nextGC > ctx.heapAlloc { 501 diff = ctx.nextGC - ctx.heapAlloc 502 } 503 ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.heapAlloc, diff}}) 504 } 505 506 func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) { 507 type Arg struct { 508 Running uint64 509 Runnable uint64 510 } 511 if ctx.gtrace { 512 return 513 } 514 ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.grunning, ctx.grunnable}}) 515 } 516 517 func (ctx *traceContext) emitThreadCounters(ev *trace.Event) { 518 type Arg struct { 519 Running uint64 520 InSyscall uint64 521 } 522 if ctx.gtrace { 523 return 524 } 525 ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.prunning, ctx.insyscall}}) 526 } 527 528 func (ctx *traceContext) emitInstant(ev *trace.Event, name string) { 529 var arg interface{} 530 if ev.Type == trace.EvProcStart { 531 type Arg struct { 532 ThreadID uint64 533 } 534 arg = &Arg{ev.Args[0]} 535 } 536 ctx.emit(&ViewerEvent{Name: name, Phase: "I", Scope: "t", Time: ctx.time(ev), Tid: ctx.proc(ev), Stack: ctx.stack(ev.Stk), Arg: arg}) 537 } 538 539 func (ctx *traceContext) emitArrow(ev *trace.Event, name string) { 540 if ev.Link == nil { 541 // The other end of the arrow is not captured in the trace. 542 // For example, a goroutine was unblocked but was not scheduled before trace stop. 543 return 544 } 545 if ctx.gtrace && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) { 546 return 547 } 548 549 if ev.P == trace.NetpollP || ev.P == trace.TimerP || ev.P == trace.SyscallP { 550 // Trace-viewer discards arrows if they don't start/end inside of a slice or instant. 551 // So emit a fake instant at the start of the arrow. 552 ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock") 553 } 554 555 ctx.arrowSeq++ 556 ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk)}) 557 ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link)}) 558 } 559 560 func (ctx *traceContext) stack(stk []*trace.Frame) int { 561 return ctx.buildBranch(ctx.frameTree, stk) 562 } 563 564 // buildBranch builds one branch in the prefix tree rooted at ctx.frameTree. 565 func (ctx *traceContext) buildBranch(parent frameNode, stk []*trace.Frame) int { 566 if len(stk) == 0 { 567 return parent.id 568 } 569 last := len(stk) - 1 570 frame := stk[last] 571 stk = stk[:last] 572 573 node, ok := parent.children[frame.PC] 574 if !ok { 575 ctx.frameSeq++ 576 node.id = ctx.frameSeq 577 node.children = make(map[uint64]frameNode) 578 parent.children[frame.PC] = node 579 ctx.data.Frames[strconv.Itoa(node.id)] = ViewerFrame{fmt.Sprintf("%v:%v", frame.Fn, frame.Line), parent.id} 580 } 581 return ctx.buildBranch(node, stk) 582 }