Source file src/pkg/cmd/trace/pprof.go

     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							{
   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