rsc.io/go@v0.0.0-20150416155037-e040fd465409/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  	"net/http"
    12  	"os"
    13  	"path/filepath"
    14  	"strconv"
    15  	"strings"
    16  )
    17  
    18  func init() {
    19  	http.HandleFunc("/trace", httpTrace)
    20  	http.HandleFunc("/jsontrace", httpJsonTrace)
    21  	http.HandleFunc("/trace_viewer_html", httpTraceViewerHTML)
    22  }
    23  
    24  // httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
    25  func httpTrace(w http.ResponseWriter, r *http.Request) {
    26  	_, err := parseEvents()
    27  	if err != nil {
    28  		http.Error(w, err.Error(), http.StatusInternalServerError)
    29  		return
    30  	}
    31  
    32  	params := ""
    33  	if goids := r.FormValue("goid"); goids != "" {
    34  		goid, err := strconv.ParseUint(goids, 10, 64)
    35  		if err != nil {
    36  			http.Error(w, fmt.Sprintf("failed to parse goid parameter '%v': %v", goids, err), http.StatusInternalServerError)
    37  			return
    38  		}
    39  		params = fmt.Sprintf("?goid=%v", goid)
    40  	}
    41  	html := strings.Replace(templTrace, "{{PARAMS}}", params, -1)
    42  	w.Write([]byte(html))
    43  
    44  }
    45  
    46  var templTrace = `
    47  <html>
    48  	<head>
    49  		<link href="/trace_viewer_html" rel="import">
    50  		<script>
    51  			document.addEventListener("DOMContentLoaded", function(event) {
    52  				var viewer = new tv.TraceViewer('/jsontrace{{PARAMS}}');
    53  				document.body.appendChild(viewer);
    54  			});
    55  		</script>
    56  	</head>
    57  	<body>
    58  	</body>
    59  </html>
    60  `
    61  
    62  // httpTraceViewerHTML serves static part of trace-viewer.
    63  // This URL is queried from templTrace HTML.
    64  func httpTraceViewerHTML(w http.ResponseWriter, r *http.Request) {
    65  	http.ServeFile(w, r, filepath.Join(os.Getenv("GOROOT"), "misc", "trace", "trace_viewer_lean.html"))
    66  }
    67  
    68  // httpJsonTrace serves json trace, requested from within templTrace HTML.
    69  func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
    70  	events, err := parseEvents()
    71  	if err != nil {
    72  		http.Error(w, err.Error(), http.StatusInternalServerError)
    73  		return
    74  	}
    75  
    76  	params := &traceParams{
    77  		events:  events,
    78  		endTime: int64(1<<63 - 1),
    79  	}
    80  
    81  	if goids := r.FormValue("goid"); goids != "" {
    82  		goid, err := strconv.ParseUint(goids, 10, 64)
    83  		if err != nil {
    84  			http.Error(w, fmt.Sprintf("failed to parse goid parameter '%v': %v", goids, err), http.StatusInternalServerError)
    85  			return
    86  		}
    87  		analyzeGoroutines(events)
    88  		g := gs[goid]
    89  		params.gtrace = true
    90  		params.startTime = g.StartTime
    91  		params.endTime = g.EndTime
    92  		params.maing = goid
    93  		params.gs = trace.RelatedGoroutines(events, goid)
    94  	}
    95  
    96  	err = json.NewEncoder(w).Encode(generateTrace(params))
    97  	if err != nil {
    98  		http.Error(w, fmt.Sprintf("failed to serialize trace: %v", err), http.StatusInternalServerError)
    99  		return
   100  	}
   101  }
   102  
   103  type traceParams struct {
   104  	events    []*trace.Event
   105  	gtrace    bool
   106  	startTime int64
   107  	endTime   int64
   108  	maing     uint64
   109  	gs        map[uint64]bool
   110  }
   111  
   112  type traceContext struct {
   113  	*traceParams
   114  	data      ViewerData
   115  	frameTree frameNode
   116  	frameSeq  int
   117  	arrowSeq  uint64
   118  	heapAlloc uint64
   119  	nextGC    uint64
   120  	gcount    uint64
   121  	grunnable uint64
   122  	grunning  uint64
   123  	insyscall uint64
   124  	prunning  uint64
   125  }
   126  
   127  type frameNode struct {
   128  	id       int
   129  	children map[uint64]frameNode
   130  }
   131  
   132  type ViewerData struct {
   133  	Events []*ViewerEvent         `json:"traceEvents"`
   134  	Frames map[string]ViewerFrame `json:"stackFrames"`
   135  }
   136  
   137  type ViewerEvent struct {
   138  	Name     string      `json:"name,omitempty"`
   139  	Phase    string      `json:"ph"`
   140  	Scope    string      `json:"s,omitempty"`
   141  	Time     int64       `json:"ts"`
   142  	Dur      int64       `json:"dur,omitempty"`
   143  	Pid      uint64      `json:"pid"`
   144  	Tid      uint64      `json:"tid"`
   145  	ID       uint64      `json:"id,omitempty"`
   146  	Stack    int         `json:"sf,omitempty"`
   147  	EndStack int         `json:"esf,omitempty"`
   148  	Arg      interface{} `json:"args,omitempty"`
   149  }
   150  
   151  type ViewerFrame struct {
   152  	Name   string `json:"name"`
   153  	Parent int    `json:"parent,omitempty"`
   154  }
   155  
   156  type NameArg struct {
   157  	Name string `json:"name"`
   158  }
   159  
   160  type SortIndexArg struct {
   161  	Index int `json:"sort_index"`
   162  }
   163  
   164  // generateTrace generates json trace for trace-viewer:
   165  // https://github.com/google/trace-viewer
   166  // Trace format is described at:
   167  // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view
   168  // If gtrace=true, generate trace for goroutine goid, otherwise whole trace.
   169  // startTime, endTime determine part of the trace that we are interested in.
   170  // gset restricts goroutines that are included in the resulting trace.
   171  func generateTrace(params *traceParams) ViewerData {
   172  	ctx := &traceContext{traceParams: params}
   173  	ctx.frameTree.children = make(map[uint64]frameNode)
   174  	ctx.data.Frames = make(map[string]ViewerFrame)
   175  	maxProc := 0
   176  	gnames := make(map[uint64]string)
   177  	for _, ev := range ctx.events {
   178  		// Handle trace.EvGoStart separately, because we need the goroutine name
   179  		// even if ignore the event otherwise.
   180  		if ev.Type == trace.EvGoStart {
   181  			if _, ok := gnames[ev.G]; !ok {
   182  				if len(ev.Stk) > 0 {
   183  					gnames[ev.G] = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn)
   184  				} else {
   185  					gnames[ev.G] = fmt.Sprintf("G%v", ev.G)
   186  				}
   187  			}
   188  		}
   189  
   190  		// Ignore events that are from uninteresting goroutines
   191  		// or outside of the interesting timeframe.
   192  		if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] {
   193  			continue
   194  		}
   195  		if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime {
   196  			continue
   197  		}
   198  
   199  		if ev.P < trace.FakeP && ev.P > maxProc {
   200  			maxProc = ev.P
   201  		}
   202  
   203  		switch ev.Type {
   204  		case trace.EvProcStart:
   205  			if ctx.gtrace {
   206  				continue
   207  			}
   208  			ctx.prunning++
   209  			ctx.emitThreadCounters(ev)
   210  			ctx.emitInstant(ev, "proc start")
   211  		case trace.EvProcStop:
   212  			if ctx.gtrace {
   213  				continue
   214  			}
   215  			ctx.prunning--
   216  			ctx.emitThreadCounters(ev)
   217  			ctx.emitInstant(ev, "proc stop")
   218  		case trace.EvGCStart:
   219  			ctx.emitSlice(ev, "GC")
   220  		case trace.EvGCDone:
   221  		case trace.EvGCScanStart:
   222  			if ctx.gtrace {
   223  				continue
   224  			}
   225  			ctx.emitSlice(ev, "MARK")
   226  		case trace.EvGCScanDone:
   227  		case trace.EvGCSweepStart:
   228  			ctx.emitSlice(ev, "SWEEP")
   229  		case trace.EvGCSweepDone:
   230  		case trace.EvGoStart:
   231  			ctx.grunnable--
   232  			ctx.grunning++
   233  			ctx.emitGoroutineCounters(ev)
   234  			ctx.emitSlice(ev, gnames[ev.G])
   235  		case trace.EvGoCreate:
   236  			ctx.gcount++
   237  			ctx.grunnable++
   238  			ctx.emitGoroutineCounters(ev)
   239  			ctx.emitArrow(ev, "go")
   240  		case trace.EvGoEnd:
   241  			ctx.gcount--
   242  			ctx.grunning--
   243  			ctx.emitGoroutineCounters(ev)
   244  		case trace.EvGoUnblock:
   245  			ctx.grunnable++
   246  			ctx.emitGoroutineCounters(ev)
   247  			ctx.emitArrow(ev, "unblock")
   248  		case trace.EvGoSysCall:
   249  			ctx.emitInstant(ev, "syscall")
   250  		case trace.EvGoSysExit:
   251  			ctx.grunnable++
   252  			ctx.emitGoroutineCounters(ev)
   253  			ctx.insyscall--
   254  			ctx.emitThreadCounters(ev)
   255  			ctx.emitArrow(ev, "sysexit")
   256  		case trace.EvGoSysBlock:
   257  			ctx.grunning--
   258  			ctx.emitGoroutineCounters(ev)
   259  			ctx.insyscall++
   260  			ctx.emitThreadCounters(ev)
   261  		case trace.EvGoSched, trace.EvGoPreempt:
   262  			ctx.grunnable++
   263  			ctx.grunning--
   264  			ctx.emitGoroutineCounters(ev)
   265  		case trace.EvGoStop,
   266  			trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv,
   267  			trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet:
   268  			ctx.grunning--
   269  			ctx.emitGoroutineCounters(ev)
   270  		case trace.EvGoWaiting:
   271  			ctx.grunnable--
   272  			ctx.emitGoroutineCounters(ev)
   273  		case trace.EvGoInSyscall:
   274  			ctx.insyscall++
   275  			ctx.emitThreadCounters(ev)
   276  		case trace.EvHeapAlloc:
   277  			ctx.heapAlloc = ev.Args[0]
   278  			ctx.emitHeapCounters(ev)
   279  		case trace.EvNextGC:
   280  			ctx.nextGC = ev.Args[0]
   281  			ctx.emitHeapCounters(ev)
   282  		}
   283  	}
   284  
   285  	ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 0, Arg: &NameArg{"PROCS"}})
   286  	ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 0, Arg: &SortIndexArg{1}})
   287  
   288  	ctx.emit(&ViewerEvent{Name: "process_name", Phase: "M", Pid: 1, Arg: &NameArg{"STATS"}})
   289  	ctx.emit(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: 1, Arg: &SortIndexArg{0}})
   290  
   291  	ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &NameArg{"Network"}})
   292  	ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.NetpollP, Arg: &SortIndexArg{-5}})
   293  
   294  	ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &NameArg{"Timers"}})
   295  	ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.TimerP, Arg: &SortIndexArg{-4}})
   296  
   297  	ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}})
   298  	ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}})
   299  
   300  	if !ctx.gtrace {
   301  		for i := 0; i <= maxProc; i++ {
   302  			ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}})
   303  		}
   304  	}
   305  
   306  	if ctx.gtrace && ctx.gs != nil {
   307  		for k, v := range gnames {
   308  			if !ctx.gs[k] {
   309  				continue
   310  			}
   311  			ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: k, Arg: &NameArg{v}})
   312  		}
   313  		ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: ctx.maing, Arg: &SortIndexArg{-2}})
   314  		ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: 0, Arg: &SortIndexArg{-1}})
   315  	}
   316  
   317  	return ctx.data
   318  }
   319  
   320  func (ctx *traceContext) emit(e *ViewerEvent) {
   321  	ctx.data.Events = append(ctx.data.Events, e)
   322  }
   323  
   324  func (ctx *traceContext) time(ev *trace.Event) int64 {
   325  	if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime {
   326  		fmt.Printf("ts=%v startTime=%v endTime\n", ev.Ts, ctx.startTime, ctx.endTime)
   327  		panic("timestamp is outside of trace range")
   328  	}
   329  	// NOTE: trace viewer wants timestamps in microseconds and it does not
   330  	// handle fractional timestamps (rounds them). We give it timestamps
   331  	// in nanoseconds to avoid rounding. See:
   332  	// https://github.com/google/trace-viewer/issues/624
   333  	return ev.Ts - ctx.startTime
   334  }
   335  
   336  func (ctx *traceContext) proc(ev *trace.Event) uint64 {
   337  	if ctx.gtrace && ev.P < trace.FakeP {
   338  		return ev.G
   339  	} else {
   340  		return uint64(ev.P)
   341  	}
   342  }
   343  
   344  func (ctx *traceContext) emitSlice(ev *trace.Event, name string) {
   345  	ctx.emit(&ViewerEvent{
   346  		Name:     name,
   347  		Phase:    "X",
   348  		Time:     ctx.time(ev),
   349  		Dur:      ctx.time(ev.Link) - ctx.time(ev),
   350  		Tid:      ctx.proc(ev),
   351  		Stack:    ctx.stack(ev.Stk),
   352  		EndStack: ctx.stack(ev.Link.Stk),
   353  	})
   354  }
   355  
   356  func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
   357  	type Arg struct {
   358  		Allocated uint64
   359  		NextGC    uint64
   360  	}
   361  	if ctx.gtrace {
   362  		return
   363  	}
   364  	diff := uint64(0)
   365  	if ctx.nextGC > ctx.heapAlloc {
   366  		diff = ctx.nextGC - ctx.heapAlloc
   367  	}
   368  	ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.heapAlloc, diff}})
   369  }
   370  
   371  func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) {
   372  	type Arg struct {
   373  		Running  uint64
   374  		Runnable uint64
   375  	}
   376  	if ctx.gtrace {
   377  		return
   378  	}
   379  	ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.grunning, ctx.grunnable}})
   380  }
   381  
   382  func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
   383  	type Arg struct {
   384  		Running   uint64
   385  		InSyscall uint64
   386  	}
   387  	if ctx.gtrace {
   388  		return
   389  	}
   390  	ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &Arg{ctx.prunning, ctx.insyscall}})
   391  }
   392  
   393  func (ctx *traceContext) emitInstant(ev *trace.Event, name string) {
   394  	var arg interface{}
   395  	if ev.Type == trace.EvProcStart {
   396  		type Arg struct {
   397  			ThreadID uint64
   398  		}
   399  		arg = &Arg{ev.Args[0]}
   400  	}
   401  	ctx.emit(&ViewerEvent{Name: name, Phase: "I", Scope: "t", Time: ctx.time(ev), Tid: ctx.proc(ev), Stack: ctx.stack(ev.Stk), Arg: arg})
   402  }
   403  
   404  func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
   405  	if ev.Link == nil {
   406  		// The other end of the arrow is not captured in the trace.
   407  		// For example, a goroutine was unblocked but was not scheduled before trace stop.
   408  		return
   409  	}
   410  	if ctx.gtrace && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
   411  		return
   412  	}
   413  
   414  	ctx.arrowSeq++
   415  	ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk)})
   416  	ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link)})
   417  }
   418  
   419  func (ctx *traceContext) stack(stk []*trace.Frame) int {
   420  	return ctx.buildBranch(ctx.frameTree, stk)
   421  }
   422  
   423  // buildBranch builds one branch in the prefix tree rooted at ctx.frameTree.
   424  func (ctx *traceContext) buildBranch(parent frameNode, stk []*trace.Frame) int {
   425  	if len(stk) == 0 {
   426  		return parent.id
   427  	}
   428  	last := len(stk) - 1
   429  	frame := stk[last]
   430  	stk = stk[:last]
   431  
   432  	node, ok := parent.children[frame.PC]
   433  	if !ok {
   434  		ctx.frameSeq++
   435  		node.id = ctx.frameSeq
   436  		node.children = make(map[uint64]frameNode)
   437  		parent.children[frame.PC] = node
   438  		ctx.data.Frames[strconv.Itoa(node.id)] = ViewerFrame{fmt.Sprintf("%v:%v", frame.Fn, frame.Line), parent.id}
   439  	}
   440  	return ctx.buildBranch(node, stk)
   441  }