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