...
Run Format

Source file src/cmd/trace/pprof.go

Documentation: cmd/trace

     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  // Serving of pprof-like profiles.
     6  
     7  package main
     8  
     9  import (
    10  	"bufio"
    11  	"fmt"
    12  	"internal/trace"
    13  	"io"
    14  	"io/ioutil"
    15  	"net/http"
    16  	"os"
    17  	"os/exec"
    18  	"path/filepath"
    19  	"runtime"
    20  	"sort"
    21  	"strconv"
    22  	"time"
    23  
    24  	"github.com/google/pprof/profile"
    25  )
    26  
    27  func goCmd() string {
    28  	var exeSuffix string
    29  	if runtime.GOOS == "windows" {
    30  		exeSuffix = ".exe"
    31  	}
    32  	path := filepath.Join(runtime.GOROOT(), "bin", "go"+exeSuffix)
    33  	if _, err := os.Stat(path); err == nil {
    34  		return path
    35  	}
    36  	return "go"
    37  }
    38  
    39  func init() {
    40  	http.HandleFunc("/io", serveSVGProfile(pprofByGoroutine(computePprofIO)))
    41  	http.HandleFunc("/block", serveSVGProfile(pprofByGoroutine(computePprofBlock)))
    42  	http.HandleFunc("/syscall", serveSVGProfile(pprofByGoroutine(computePprofSyscall)))
    43  	http.HandleFunc("/sched", serveSVGProfile(pprofByGoroutine(computePprofSched)))
    44  
    45  	http.HandleFunc("/regionio", serveSVGProfile(pprofByRegion(computePprofIO)))
    46  	http.HandleFunc("/regionblock", serveSVGProfile(pprofByRegion(computePprofBlock)))
    47  	http.HandleFunc("/regionsyscall", serveSVGProfile(pprofByRegion(computePprofSyscall)))
    48  	http.HandleFunc("/regionsched", serveSVGProfile(pprofByRegion(computePprofSched)))
    49  }
    50  
    51  // Record represents one entry in pprof-like profiles.
    52  type Record struct {
    53  	stk  []*trace.Frame
    54  	n    uint64
    55  	time int64
    56  }
    57  
    58  // interval represents a time interval in the trace.
    59  type interval struct {
    60  	begin, end int64 // nanoseconds.
    61  }
    62  
    63  func pprofByGoroutine(compute func(io.Writer, map[uint64][]interval, []*trace.Event) error) func(w io.Writer, r *http.Request) error {
    64  	return func(w io.Writer, r *http.Request) error {
    65  		id := r.FormValue("id")
    66  		events, err := parseEvents()
    67  		if err != nil {
    68  			return err
    69  		}
    70  		gToIntervals, err := pprofMatchingGoroutines(id, events)
    71  		if err != nil {
    72  			return err
    73  		}
    74  		return compute(w, gToIntervals, events)
    75  	}
    76  }
    77  
    78  func pprofByRegion(compute func(io.Writer, map[uint64][]interval, []*trace.Event) error) func(w io.Writer, r *http.Request) error {
    79  	return func(w io.Writer, r *http.Request) error {
    80  		filter, err := newRegionFilter(r)
    81  		if err != nil {
    82  			return err
    83  		}
    84  		gToIntervals, err := pprofMatchingRegions(filter)
    85  		if err != nil {
    86  			return err
    87  		}
    88  		events, _ := parseEvents()
    89  
    90  		return compute(w, gToIntervals, events)
    91  	}
    92  }
    93  
    94  // pprofMatchingGoroutines parses the goroutine type id string (i.e. pc)
    95  // and returns the ids of goroutines of the matching type and its interval.
    96  // If the id string is empty, returns nil without an error.
    97  func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64][]interval, error) {
    98  	if id == "" {
    99  		return nil, nil
   100  	}
   101  	pc, err := strconv.ParseUint(id, 10, 64) // id is string
   102  	if err != nil {
   103  		return nil, fmt.Errorf("invalid goroutine type: %v", id)
   104  	}
   105  	analyzeGoroutines(events)
   106  	var res map[uint64][]interval
   107  	for _, g := range gs {
   108  		if g.PC != pc {
   109  			continue
   110  		}
   111  		if res == nil {
   112  			res = make(map[uint64][]interval)
   113  		}
   114  		endTime := g.EndTime
   115  		if g.EndTime == 0 {
   116  			endTime = lastTimestamp() // the trace doesn't include the goroutine end event. Use the trace end time.
   117  		}
   118  		res[g.ID] = []interval{{begin: g.StartTime, end: endTime}}
   119  	}
   120  	if len(res) == 0 && id != "" {
   121  		return nil, fmt.Errorf("failed to find matching goroutines for id: %s", id)
   122  	}
   123  	return res, nil
   124  }
   125  
   126  // pprofMatchingRegions returns the time intervals of matching regions
   127  // grouped by the goroutine id. If the filter is nil, returns nil without an error.
   128  func pprofMatchingRegions(filter *regionFilter) (map[uint64][]interval, error) {
   129  	res, err := analyzeAnnotations()
   130  	if err != nil {
   131  		return nil, err
   132  	}
   133  	if filter == nil {
   134  		return nil, nil
   135  	}
   136  
   137  	gToIntervals := make(map[uint64][]interval)
   138  	for id, regions := range res.regions {
   139  		for _, s := range regions {
   140  			if filter.match(id, s) {
   141  				gToIntervals[s.G] = append(gToIntervals[s.G], interval{begin: s.firstTimestamp(), end: s.lastTimestamp()})
   142  			}
   143  		}
   144  	}
   145  
   146  	for g, intervals := range gToIntervals {
   147  		// in order to remove nested regions and
   148  		// consider only the outermost regions,
   149  		// first, we sort based on the start time
   150  		// and then scan through to select only the outermost regions.
   151  		sort.Slice(intervals, func(i, j int) bool {
   152  			x := intervals[i].begin
   153  			y := intervals[j].begin
   154  			if x == y {
   155  				return intervals[i].end < intervals[j].end
   156  			}
   157  			return x < y
   158  		})
   159  		var lastTimestamp int64
   160  		var n int
   161  		// select only the outermost regions.
   162  		for _, i := range intervals {
   163  			if lastTimestamp <= i.begin {
   164  				intervals[n] = i // new non-overlapping region starts.
   165  				lastTimestamp = i.end
   166  				n++
   167  			} // otherwise, skip because this region overlaps with a previous region.
   168  		}
   169  		gToIntervals[g] = intervals[:n]
   170  	}
   171  	return gToIntervals, nil
   172  }
   173  
   174  // computePprofIO generates IO pprof-like profile (time spent in IO wait, currently only network blocking event).
   175  func computePprofIO(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
   176  	prof := make(map[uint64]Record)
   177  	for _, ev := range events {
   178  		if ev.Type != trace.EvGoBlockNet || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   179  			continue
   180  		}
   181  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   182  		if overlapping > 0 {
   183  			rec := prof[ev.StkID]
   184  			rec.stk = ev.Stk
   185  			rec.n++
   186  			rec.time += overlapping.Nanoseconds()
   187  			prof[ev.StkID] = rec
   188  		}
   189  	}
   190  	return buildProfile(prof).Write(w)
   191  }
   192  
   193  // computePprofBlock generates blocking pprof-like profile (time spent blocked on synchronization primitives).
   194  func computePprofBlock(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
   195  	prof := make(map[uint64]Record)
   196  	for _, ev := range events {
   197  		switch ev.Type {
   198  		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect,
   199  			trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockGC:
   200  			// TODO(hyangah): figure out why EvGoBlockGC should be here.
   201  			// EvGoBlockGC indicates the goroutine blocks on GC assist, not
   202  			// on synchronization primitives.
   203  		default:
   204  			continue
   205  		}
   206  		if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   207  			continue
   208  		}
   209  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   210  		if overlapping > 0 {
   211  			rec := prof[ev.StkID]
   212  			rec.stk = ev.Stk
   213  			rec.n++
   214  			rec.time += overlapping.Nanoseconds()
   215  			prof[ev.StkID] = rec
   216  		}
   217  	}
   218  	return buildProfile(prof).Write(w)
   219  }
   220  
   221  // computePprofSyscall generates syscall pprof-like profile (time spent blocked in syscalls).
   222  func computePprofSyscall(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
   223  	prof := make(map[uint64]Record)
   224  	for _, ev := range events {
   225  		if ev.Type != trace.EvGoSysCall || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   226  			continue
   227  		}
   228  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   229  		if overlapping > 0 {
   230  			rec := prof[ev.StkID]
   231  			rec.stk = ev.Stk
   232  			rec.n++
   233  			rec.time += overlapping.Nanoseconds()
   234  			prof[ev.StkID] = rec
   235  		}
   236  	}
   237  	return buildProfile(prof).Write(w)
   238  }
   239  
   240  // computePprofSched generates scheduler latency pprof-like profile
   241  // (time between a goroutine become runnable and actually scheduled for execution).
   242  func computePprofSched(w io.Writer, gToIntervals map[uint64][]interval, events []*trace.Event) error {
   243  	prof := make(map[uint64]Record)
   244  	for _, ev := range events {
   245  		if (ev.Type != trace.EvGoUnblock && ev.Type != trace.EvGoCreate) ||
   246  			ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   247  			continue
   248  		}
   249  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   250  		if overlapping > 0 {
   251  			rec := prof[ev.StkID]
   252  			rec.stk = ev.Stk
   253  			rec.n++
   254  			rec.time += overlapping.Nanoseconds()
   255  			prof[ev.StkID] = rec
   256  		}
   257  	}
   258  	return buildProfile(prof).Write(w)
   259  }
   260  
   261  // pprofOverlappingDuration returns the overlapping duration between
   262  // the time intervals in gToIntervals and the specified event.
   263  // If gToIntervals is nil, this simply returns the event's duration.
   264  func pprofOverlappingDuration(gToIntervals map[uint64][]interval, ev *trace.Event) time.Duration {
   265  	if gToIntervals == nil { // No filtering.
   266  		return time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond
   267  	}
   268  	intervals := gToIntervals[ev.G]
   269  	if len(intervals) == 0 {
   270  		return 0
   271  	}
   272  
   273  	var overlapping time.Duration
   274  	for _, i := range intervals {
   275  		if o := overlappingDuration(i.begin, i.end, ev.Ts, ev.Link.Ts); o > 0 {
   276  			overlapping += o
   277  		}
   278  	}
   279  	return overlapping
   280  }
   281  
   282  // serveSVGProfile serves pprof-like profile generated by prof as svg.
   283  func serveSVGProfile(prof func(w io.Writer, r *http.Request) error) http.HandlerFunc {
   284  	return func(w http.ResponseWriter, r *http.Request) {
   285  
   286  		if r.FormValue("raw") != "" {
   287  			w.Header().Set("Content-Type", "application/octet-stream")
   288  			if err := prof(w, r); err != nil {
   289  				w.Header().Set("Content-Type", "text/plain; charset=utf-8")
   290  				w.Header().Set("X-Go-Pprof", "1")
   291  				http.Error(w, fmt.Sprintf("failed to get profile: %v", err), http.StatusInternalServerError)
   292  				return
   293  			}
   294  			return
   295  		}
   296  
   297  		blockf, err := ioutil.TempFile("", "block")
   298  		if err != nil {
   299  			http.Error(w, fmt.Sprintf("failed to create temp file: %v", err), http.StatusInternalServerError)
   300  			return
   301  		}
   302  		defer func() {
   303  			blockf.Close()
   304  			os.Remove(blockf.Name())
   305  		}()
   306  		blockb := bufio.NewWriter(blockf)
   307  		if err := prof(blockb, r); err != nil {
   308  			http.Error(w, fmt.Sprintf("failed to generate profile: %v", err), http.StatusInternalServerError)
   309  			return
   310  		}
   311  		if err := blockb.Flush(); err != nil {
   312  			http.Error(w, fmt.Sprintf("failed to flush temp file: %v", err), http.StatusInternalServerError)
   313  			return
   314  		}
   315  		if err := blockf.Close(); err != nil {
   316  			http.Error(w, fmt.Sprintf("failed to close temp file: %v", err), http.StatusInternalServerError)
   317  			return
   318  		}
   319  		svgFilename := blockf.Name() + ".svg"
   320  		if output, err := exec.Command(goCmd(), "tool", "pprof", "-svg", "-output", svgFilename, blockf.Name()).CombinedOutput(); err != nil {
   321  			http.Error(w, fmt.Sprintf("failed to execute go tool pprof: %v\n%s", err, output), http.StatusInternalServerError)
   322  			return
   323  		}
   324  		defer os.Remove(svgFilename)
   325  		w.Header().Set("Content-Type", "image/svg+xml")
   326  		http.ServeFile(w, r, svgFilename)
   327  	}
   328  }
   329  
   330  func buildProfile(prof map[uint64]Record) *profile.Profile {
   331  	p := &profile.Profile{
   332  		PeriodType: &profile.ValueType{Type: "trace", Unit: "count"},
   333  		Period:     1,
   334  		SampleType: []*profile.ValueType{
   335  			{Type: "contentions", Unit: "count"},
   336  			{Type: "delay", Unit: "nanoseconds"},
   337  		},
   338  	}
   339  	locs := make(map[uint64]*profile.Location)
   340  	funcs := make(map[string]*profile.Function)
   341  	for _, rec := range prof {
   342  		var sloc []*profile.Location
   343  		for _, frame := range rec.stk {
   344  			loc := locs[frame.PC]
   345  			if loc == nil {
   346  				fn := funcs[frame.File+frame.Fn]
   347  				if fn == nil {
   348  					fn = &profile.Function{
   349  						ID:         uint64(len(p.Function) + 1),
   350  						Name:       frame.Fn,
   351  						SystemName: frame.Fn,
   352  						Filename:   frame.File,
   353  					}
   354  					p.Function = append(p.Function, fn)
   355  					funcs[frame.File+frame.Fn] = fn
   356  				}
   357  				loc = &profile.Location{
   358  					ID:      uint64(len(p.Location) + 1),
   359  					Address: frame.PC,
   360  					Line: []profile.Line{
   361  						profile.Line{
   362  							Function: fn,
   363  							Line:     int64(frame.Line),
   364  						},
   365  					},
   366  				}
   367  				p.Location = append(p.Location, loc)
   368  				locs[frame.PC] = loc
   369  			}
   370  			sloc = append(sloc, loc)
   371  		}
   372  		p.Sample = append(p.Sample, &profile.Sample{
   373  			Value:    []int64{int64(rec.n), rec.time},
   374  			Location: sloc,
   375  		})
   376  	}
   377  	return p
   378  }
   379  

View as plain text