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