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  	"fmt"
    11  	"internal/trace"
    12  	"internal/trace/traceviewer"
    13  	"net/http"
    14  	"sort"
    15  	"strconv"
    16  	"time"
    17  )
    18  
    19  func init() {
    20  	http.HandleFunc("/io", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofIO)))
    21  	http.HandleFunc("/block", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofBlock)))
    22  	http.HandleFunc("/syscall", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSyscall)))
    23  	http.HandleFunc("/sched", traceviewer.SVGProfileHandlerFunc(pprofByGoroutine(computePprofSched)))
    24  
    25  	http.HandleFunc("/regionio", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofIO)))
    26  	http.HandleFunc("/regionblock", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofBlock)))
    27  	http.HandleFunc("/regionsyscall", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSyscall)))
    28  	http.HandleFunc("/regionsched", traceviewer.SVGProfileHandlerFunc(pprofByRegion(computePprofSched)))
    29  }
    30  
    31  // interval represents a time interval in the trace.
    32  type interval struct {
    33  	begin, end int64 // nanoseconds.
    34  }
    35  
    36  func pprofByGoroutine(compute computePprofFunc) traceviewer.ProfileFunc {
    37  	return func(r *http.Request) ([]traceviewer.ProfileRecord, error) {
    38  		id := r.FormValue("id")
    39  		events, err := parseEvents()
    40  		if err != nil {
    41  			return nil, err
    42  		}
    43  		gToIntervals, err := pprofMatchingGoroutines(id, events)
    44  		if err != nil {
    45  			return nil, err
    46  		}
    47  		return compute(gToIntervals, events)
    48  	}
    49  }
    50  
    51  func pprofByRegion(compute computePprofFunc) traceviewer.ProfileFunc {
    52  	return func(r *http.Request) ([]traceviewer.ProfileRecord, error) {
    53  		filter, err := newRegionFilter(r)
    54  		if err != nil {
    55  			return nil, err
    56  		}
    57  		gToIntervals, err := pprofMatchingRegions(filter)
    58  		if err != nil {
    59  			return nil, err
    60  		}
    61  		events, _ := parseEvents()
    62  
    63  		return compute(gToIntervals, events)
    64  	}
    65  }
    66  
    67  // pprofMatchingGoroutines parses the goroutine type id string (i.e. pc)
    68  // and returns the ids of goroutines of the matching type and its interval.
    69  // If the id string is empty, returns nil without an error.
    70  func pprofMatchingGoroutines(id string, events []*trace.Event) (map[uint64][]interval, error) {
    71  	if id == "" {
    72  		return nil, nil
    73  	}
    74  	pc, err := strconv.ParseUint(id, 10, 64) // id is string
    75  	if err != nil {
    76  		return nil, fmt.Errorf("invalid goroutine type: %v", id)
    77  	}
    78  	analyzeGoroutines(events)
    79  	var res map[uint64][]interval
    80  	for _, g := range gs {
    81  		if g.PC != pc {
    82  			continue
    83  		}
    84  		if res == nil {
    85  			res = make(map[uint64][]interval)
    86  		}
    87  		endTime := g.EndTime
    88  		if g.EndTime == 0 {
    89  			endTime = lastTimestamp() // the trace doesn't include the goroutine end event. Use the trace end time.
    90  		}
    91  		res[g.ID] = []interval{{begin: g.StartTime, end: endTime}}
    92  	}
    93  	if len(res) == 0 && id != "" {
    94  		return nil, fmt.Errorf("failed to find matching goroutines for id: %s", id)
    95  	}
    96  	return res, nil
    97  }
    98  
    99  // pprofMatchingRegions returns the time intervals of matching regions
   100  // grouped by the goroutine id. If the filter is nil, returns nil without an error.
   101  func pprofMatchingRegions(filter *regionFilter) (map[uint64][]interval, error) {
   102  	res, err := analyzeAnnotations()
   103  	if err != nil {
   104  		return nil, err
   105  	}
   106  	if filter == nil {
   107  		return nil, nil
   108  	}
   109  
   110  	gToIntervals := make(map[uint64][]interval)
   111  	for id, regions := range res.regions {
   112  		for _, s := range regions {
   113  			if filter.match(id, s) {
   114  				gToIntervals[s.G] = append(gToIntervals[s.G], interval{begin: s.firstTimestamp(), end: s.lastTimestamp()})
   115  			}
   116  		}
   117  	}
   118  
   119  	for g, intervals := range gToIntervals {
   120  		// in order to remove nested regions and
   121  		// consider only the outermost regions,
   122  		// first, we sort based on the start time
   123  		// and then scan through to select only the outermost regions.
   124  		sort.Slice(intervals, func(i, j int) bool {
   125  			x := intervals[i].begin
   126  			y := intervals[j].begin
   127  			if x == y {
   128  				return intervals[i].end < intervals[j].end
   129  			}
   130  			return x < y
   131  		})
   132  		var lastTimestamp int64
   133  		var n int
   134  		// select only the outermost regions.
   135  		for _, i := range intervals {
   136  			if lastTimestamp <= i.begin {
   137  				intervals[n] = i // new non-overlapping region starts.
   138  				lastTimestamp = i.end
   139  				n++
   140  			} // otherwise, skip because this region overlaps with a previous region.
   141  		}
   142  		gToIntervals[g] = intervals[:n]
   143  	}
   144  	return gToIntervals, nil
   145  }
   146  
   147  type computePprofFunc func(gToIntervals map[uint64][]interval, events []*trace.Event) ([]traceviewer.ProfileRecord, error)
   148  
   149  // computePprofIO generates IO pprof-like profile (time spent in IO wait, currently only network blocking event).
   150  func computePprofIO(gToIntervals map[uint64][]interval, events []*trace.Event) ([]traceviewer.ProfileRecord, error) {
   151  	prof := make(map[uint64]traceviewer.ProfileRecord)
   152  	for _, ev := range events {
   153  		if ev.Type != trace.EvGoBlockNet || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   154  			continue
   155  		}
   156  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   157  		if overlapping > 0 {
   158  			rec := prof[ev.StkID]
   159  			rec.Stack = ev.Stk
   160  			rec.Count++
   161  			rec.Time += overlapping
   162  			prof[ev.StkID] = rec
   163  		}
   164  	}
   165  	return recordsOf(prof), nil
   166  }
   167  
   168  // computePprofBlock generates blocking pprof-like profile (time spent blocked on synchronization primitives).
   169  func computePprofBlock(gToIntervals map[uint64][]interval, events []*trace.Event) ([]traceviewer.ProfileRecord, error) {
   170  	prof := make(map[uint64]traceviewer.ProfileRecord)
   171  	for _, ev := range events {
   172  		switch ev.Type {
   173  		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect,
   174  			trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockGC:
   175  			// TODO(hyangah): figure out why EvGoBlockGC should be here.
   176  			// EvGoBlockGC indicates the goroutine blocks on GC assist, not
   177  			// on synchronization primitives.
   178  		default:
   179  			continue
   180  		}
   181  		if ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   182  			continue
   183  		}
   184  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   185  		if overlapping > 0 {
   186  			rec := prof[ev.StkID]
   187  			rec.Stack = ev.Stk
   188  			rec.Count++
   189  			rec.Time += overlapping
   190  			prof[ev.StkID] = rec
   191  		}
   192  	}
   193  	return recordsOf(prof), nil
   194  }
   195  
   196  // computePprofSyscall generates syscall pprof-like profile (time spent blocked in syscalls).
   197  func computePprofSyscall(gToIntervals map[uint64][]interval, events []*trace.Event) ([]traceviewer.ProfileRecord, error) {
   198  	prof := make(map[uint64]traceviewer.ProfileRecord)
   199  	for _, ev := range events {
   200  		if ev.Type != trace.EvGoSysCall || ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   201  			continue
   202  		}
   203  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   204  		if overlapping > 0 {
   205  			rec := prof[ev.StkID]
   206  			rec.Stack = ev.Stk
   207  			rec.Count++
   208  			rec.Time += overlapping
   209  			prof[ev.StkID] = rec
   210  		}
   211  	}
   212  	return recordsOf(prof), nil
   213  }
   214  
   215  // computePprofSched generates scheduler latency pprof-like profile
   216  // (time between a goroutine become runnable and actually scheduled for execution).
   217  func computePprofSched(gToIntervals map[uint64][]interval, events []*trace.Event) ([]traceviewer.ProfileRecord, error) {
   218  	prof := make(map[uint64]traceviewer.ProfileRecord)
   219  	for _, ev := range events {
   220  		if (ev.Type != trace.EvGoUnblock && ev.Type != trace.EvGoCreate) ||
   221  			ev.Link == nil || ev.StkID == 0 || len(ev.Stk) == 0 {
   222  			continue
   223  		}
   224  		overlapping := pprofOverlappingDuration(gToIntervals, ev)
   225  		if overlapping > 0 {
   226  			rec := prof[ev.StkID]
   227  			rec.Stack = ev.Stk
   228  			rec.Count++
   229  			rec.Time += overlapping
   230  			prof[ev.StkID] = rec
   231  		}
   232  	}
   233  	return recordsOf(prof), nil
   234  }
   235  
   236  // pprofOverlappingDuration returns the overlapping duration between
   237  // the time intervals in gToIntervals and the specified event.
   238  // If gToIntervals is nil, this simply returns the event's duration.
   239  func pprofOverlappingDuration(gToIntervals map[uint64][]interval, ev *trace.Event) time.Duration {
   240  	if gToIntervals == nil { // No filtering.
   241  		return time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond
   242  	}
   243  	intervals := gToIntervals[ev.G]
   244  	if len(intervals) == 0 {
   245  		return 0
   246  	}
   247  
   248  	var overlapping time.Duration
   249  	for _, i := range intervals {
   250  		if o := overlappingDuration(i.begin, i.end, ev.Ts, ev.Link.Ts); o > 0 {
   251  			overlapping += o
   252  		}
   253  	}
   254  	return overlapping
   255  }
   256  
   257  func recordsOf(records map[uint64]traceviewer.ProfileRecord) []traceviewer.ProfileRecord {
   258  	result := make([]traceviewer.ProfileRecord, 0, len(records))
   259  	for _, record := range records {
   260  		result = append(result, record)
   261  	}
   262  	return result
   263  }
   264
View as plain text