pprof_test.go

     1  // Copyright 2018 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 pprof
     6  
     7  import (
     8  	"bytes"
     9  	"encoding/base64"
    10  	"fmt"
    11  	"internal/profile"
    12  	"internal/testenv"
    13  	"io"
    14  	"net/http"
    15  	"net/http/httptest"
    16  	"path/filepath"
    17  	"runtime"
    18  	"runtime/pprof"
    19  	"strings"
    20  	"sync"
    21  	"sync/atomic"
    22  	"testing"
    23  	"time"
    24  )
    25  
    26  // TestDescriptions checks that the profile names under runtime/pprof package
    27  // have a key in the description map.
    28  func TestDescriptions(t *testing.T) {
    29  	for _, p := range pprof.Profiles() {
    30  		_, ok := profileDescriptions[p.Name()]
    31  		if ok != true {
    32  			t.Errorf("%s does not exist in profileDescriptions map\n", p.Name())
    33  		}
    34  	}
    35  }
    36  
    37  func TestHandlers(t *testing.T) {
    38  	testCases := []struct {
    39  		path               string
    40  		handler            http.HandlerFunc
    41  		statusCode         int
    42  		contentType        string
    43  		contentDisposition string
    44  		resp               []byte
    45  	}{
    46  		{"/debug/pprof/<script>scripty<script>", Index, http.StatusNotFound, "text/plain; charset=utf-8", "", []byte("Unknown profile\n")},
    47  		{"/debug/pprof/heap", Index, http.StatusOK, "application/octet-stream", `attachment; filename="heap"`, nil},
    48  		{"/debug/pprof/heap?debug=1", Index, http.StatusOK, "text/plain; charset=utf-8", "", nil},
    49  		{"/debug/pprof/cmdline", Cmdline, http.StatusOK, "text/plain; charset=utf-8", "", nil},
    50  		{"/debug/pprof/profile?seconds=1", Profile, http.StatusOK, "application/octet-stream", `attachment; filename="profile"`, nil},
    51  		{"/debug/pprof/symbol", Symbol, http.StatusOK, "text/plain; charset=utf-8", "", nil},
    52  		{"/debug/pprof/trace", Trace, http.StatusOK, "application/octet-stream", `attachment; filename="trace"`, nil},
    53  		{"/debug/pprof/mutex", Index, http.StatusOK, "application/octet-stream", `attachment; filename="mutex"`, nil},
    54  		{"/debug/pprof/block?seconds=1", Index, http.StatusOK, "application/octet-stream", `attachment; filename="block-delta"`, nil},
    55  		{"/debug/pprof/goroutine?seconds=1", Index, http.StatusOK, "application/octet-stream", `attachment; filename="goroutine-delta"`, nil},
    56  		{"/debug/pprof/", Index, http.StatusOK, "text/html; charset=utf-8", "", []byte("Types of profiles available:")},
    57  	}
    58  	for _, tc := range testCases {
    59  		t.Run(tc.path, func(t *testing.T) {
    60  			req := httptest.NewRequest("GET", "http://example.com"+tc.path, nil)
    61  			w := httptest.NewRecorder()
    62  			tc.handler(w, req)
    63  
    64  			resp := w.Result()
    65  			if got, want := resp.StatusCode, tc.statusCode; got != want {
    66  				t.Errorf("status code: got %d; want %d", got, want)
    67  			}
    68  
    69  			body, err := io.ReadAll(resp.Body)
    70  			if err != nil {
    71  				t.Errorf("when reading response body, expected non-nil err; got %v", err)
    72  			}
    73  			if got, want := resp.Header.Get("X-Content-Type-Options"), "nosniff"; got != want {
    74  				t.Errorf("X-Content-Type-Options: got %q; want %q", got, want)
    75  			}
    76  			if got, want := resp.Header.Get("Content-Type"), tc.contentType; got != want {
    77  				t.Errorf("Content-Type: got %q; want %q", got, want)
    78  			}
    79  			if got, want := resp.Header.Get("Content-Disposition"), tc.contentDisposition; got != want {
    80  				t.Errorf("Content-Disposition: got %q; want %q", got, want)
    81  			}
    82  
    83  			if resp.StatusCode == http.StatusOK {
    84  				return
    85  			}
    86  			if got, want := resp.Header.Get("X-Go-Pprof"), "1"; got != want {
    87  				t.Errorf("X-Go-Pprof: got %q; want %q", got, want)
    88  			}
    89  			if !bytes.Equal(body, tc.resp) {
    90  				t.Errorf("response: got %q; want %q", body, tc.resp)
    91  			}
    92  		})
    93  	}
    94  }
    95  
    96  var Sink uint32
    97  
    98  func mutexHog1(mu1, mu2 *sync.Mutex, start time.Time, dt time.Duration) {
    99  	atomic.AddUint32(&Sink, 1)
   100  	for time.Since(start) < dt {
   101  		// When using gccgo the loop of mutex operations is
   102  		// not preemptible. This can cause the loop to block a GC,
   103  		// causing the time limits in TestDeltaContentionz to fail.
   104  		// Since this loop is not very realistic, when using
   105  		// gccgo add preemption points 100 times a second.
   106  		t1 := time.Now()
   107  		for time.Since(start) < dt && time.Since(t1) < 10*time.Millisecond {
   108  			mu1.Lock()
   109  			mu2.Lock()
   110  			mu1.Unlock()
   111  			mu2.Unlock()
   112  		}
   113  		if runtime.Compiler == "gccgo" {
   114  			runtime.Gosched()
   115  		}
   116  	}
   117  }
   118  
   119  // mutexHog2 is almost identical to mutexHog but we keep them separate
   120  // in order to distinguish them with function names in the stack trace.
   121  // We make them slightly different, using Sink, because otherwise
   122  // gccgo -c opt will merge them.
   123  func mutexHog2(mu1, mu2 *sync.Mutex, start time.Time, dt time.Duration) {
   124  	atomic.AddUint32(&Sink, 2)
   125  	for time.Since(start) < dt {
   126  		// See comment in mutexHog.
   127  		t1 := time.Now()
   128  		for time.Since(start) < dt && time.Since(t1) < 10*time.Millisecond {
   129  			mu1.Lock()
   130  			mu2.Lock()
   131  			mu1.Unlock()
   132  			mu2.Unlock()
   133  		}
   134  		if runtime.Compiler == "gccgo" {
   135  			runtime.Gosched()
   136  		}
   137  	}
   138  }
   139  
   140  // mutexHog starts multiple goroutines that runs the given hogger function for the specified duration.
   141  // The hogger function will be given two mutexes to lock & unlock.
   142  func mutexHog(duration time.Duration, hogger func(mu1, mu2 *sync.Mutex, start time.Time, dt time.Duration)) {
   143  	start := time.Now()
   144  	mu1 := new(sync.Mutex)
   145  	mu2 := new(sync.Mutex)
   146  	var wg sync.WaitGroup
   147  	wg.Add(10)
   148  	for i := 0; i < 10; i++ {
   149  		go func() {
   150  			defer wg.Done()
   151  			hogger(mu1, mu2, start, duration)
   152  		}()
   153  	}
   154  	wg.Wait()
   155  }
   156  
   157  func TestDeltaProfile(t *testing.T) {
   158  	if strings.HasPrefix(runtime.GOARCH, "arm") {
   159  		testenv.SkipFlaky(t, 50218)
   160  	}
   161  
   162  	rate := runtime.SetMutexProfileFraction(1)
   163  	defer func() {
   164  		runtime.SetMutexProfileFraction(rate)
   165  	}()
   166  
   167  	// mutexHog1 will appear in non-delta mutex profile
   168  	// if the mutex profile works.
   169  	mutexHog(20*time.Millisecond, mutexHog1)
   170  
   171  	// If mutexHog1 does not appear in the mutex profile,
   172  	// skip this test. Mutex profile is likely not working,
   173  	// so is the delta profile.
   174  
   175  	p, err := query("/debug/pprof/mutex")
   176  	if err != nil {
   177  		t.Skipf("mutex profile is unsupported: %v", err)
   178  	}
   179  
   180  	if !seen(p, "mutexHog1") {
   181  		t.Skipf("mutex profile is not working: %v", p)
   182  	}
   183  
   184  	// causes mutexHog2 call stacks to appear in the mutex profile.
   185  	done := make(chan bool)
   186  	go func() {
   187  		for {
   188  			mutexHog(20*time.Millisecond, mutexHog2)
   189  			select {
   190  			case <-done:
   191  				done <- true
   192  				return
   193  			default:
   194  				time.Sleep(10 * time.Millisecond)
   195  			}
   196  		}
   197  	}()
   198  	defer func() { // cleanup the above goroutine.
   199  		done <- true
   200  		<-done // wait for the goroutine to exit.
   201  	}()
   202  
   203  	for _, d := range []int{1, 4, 16, 32} {
   204  		endpoint := fmt.Sprintf("/debug/pprof/mutex?seconds=%d", d)
   205  		p, err := query(endpoint)
   206  		if err != nil {
   207  			t.Fatalf("failed to query %q: %v", endpoint, err)
   208  		}
   209  		if !seen(p, "mutexHog1") && seen(p, "mutexHog2") && p.DurationNanos > 0 {
   210  			break // pass
   211  		}
   212  		if d == 32 {
   213  			t.Errorf("want mutexHog2 but no mutexHog1 in the profile, and non-zero p.DurationNanos, got %v", p)
   214  		}
   215  	}
   216  	p, err = query("/debug/pprof/mutex")
   217  	if err != nil {
   218  		t.Fatalf("failed to query mutex profile: %v", err)
   219  	}
   220  	if !seen(p, "mutexHog1") || !seen(p, "mutexHog2") {
   221  		t.Errorf("want both mutexHog1 and mutexHog2 in the profile, got %v", p)
   222  	}
   223  }
   224  
   225  var srv = httptest.NewServer(nil)
   226  
   227  func query(endpoint string) (*profile.Profile, error) {
   228  	url := srv.URL + endpoint
   229  	r, err := http.Get(url)
   230  	if err != nil {
   231  		return nil, fmt.Errorf("failed to fetch %q: %v", url, err)
   232  	}
   233  	if r.StatusCode != http.StatusOK {
   234  		return nil, fmt.Errorf("failed to fetch %q: %v", url, r.Status)
   235  	}
   236  
   237  	b, err := io.ReadAll(r.Body)
   238  	r.Body.Close()
   239  	if err != nil {
   240  		return nil, fmt.Errorf("failed to read and parse the result from %q: %v", url, err)
   241  	}
   242  	return profile.Parse(bytes.NewBuffer(b))
   243  }
   244  
   245  // seen returns true if the profile includes samples whose stacks include
   246  // the specified function name (fname).
   247  func seen(p *profile.Profile, fname string) bool {
   248  	locIDs := map[*profile.Location]bool{}
   249  	for _, loc := range p.Location {
   250  		for _, l := range loc.Line {
   251  			if strings.Contains(l.Function.Name, fname) {
   252  				locIDs[loc] = true
   253  				break
   254  			}
   255  		}
   256  	}
   257  	for _, sample := range p.Sample {
   258  		for _, loc := range sample.Location {
   259  			if locIDs[loc] {
   260  				return true
   261  			}
   262  		}
   263  	}
   264  	return false
   265  }
   266  
   267  // TestDeltaProfileEmptyBase validates that we still receive a valid delta
   268  // profile even if the base contains no samples.
   269  //
   270  // Regression test for https://go.dev/issue/64566.
   271  func TestDeltaProfileEmptyBase(t *testing.T) {
   272  	if testing.Short() {
   273  		// Delta profile collection has a 1s minimum.
   274  		t.Skip("skipping in -short mode")
   275  	}
   276  
   277  	testenv.MustHaveGoRun(t)
   278  
   279  	gotool, err := testenv.GoTool()
   280  	if err != nil {
   281  		t.Fatalf("error finding go tool: %v", err)
   282  	}
   283  
   284  	out, err := testenv.Command(t, gotool, "run", filepath.Join("testdata", "delta_mutex.go")).CombinedOutput()
   285  	if err != nil {
   286  		t.Fatalf("error running profile collection: %v\noutput: %s", err, out)
   287  	}
   288  
   289  	// Log the binary output for debugging failures.
   290  	b64 := make([]byte, base64.StdEncoding.EncodedLen(len(out)))
   291  	base64.StdEncoding.Encode(b64, out)
   292  	t.Logf("Output in base64.StdEncoding: %s", b64)
   293  
   294  	p, err := profile.Parse(bytes.NewReader(out))
   295  	if err != nil {
   296  		t.Fatalf("Parse got err %v want nil", err)
   297  	}
   298  
   299  	t.Logf("Output as parsed Profile: %s", p)
   300  
   301  	if len(p.SampleType) != 2 {
   302  		t.Errorf("len(p.SampleType) got %d want 2", len(p.SampleType))
   303  	}
   304  	if p.SampleType[0].Type != "contentions" {
   305  		t.Errorf(`p.SampleType[0].Type got %q want "contentions"`, p.SampleType[0].Type)
   306  	}
   307  	if p.SampleType[0].Unit != "count" {
   308  		t.Errorf(`p.SampleType[0].Unit got %q want "count"`, p.SampleType[0].Unit)
   309  	}
   310  	if p.SampleType[1].Type != "delay" {
   311  		t.Errorf(`p.SampleType[1].Type got %q want "delay"`, p.SampleType[1].Type)
   312  	}
   313  	if p.SampleType[1].Unit != "nanoseconds" {
   314  		t.Errorf(`p.SampleType[1].Unit got %q want "nanoseconds"`, p.SampleType[1].Unit)
   315  	}
   316  
   317  	if p.PeriodType == nil {
   318  		t.Fatal("p.PeriodType got nil want not nil")
   319  	}
   320  	if p.PeriodType.Type != "contentions" {
   321  		t.Errorf(`p.PeriodType.Type got %q want "contentions"`, p.PeriodType.Type)
   322  	}
   323  	if p.PeriodType.Unit != "count" {
   324  		t.Errorf(`p.PeriodType.Unit got %q want "count"`, p.PeriodType.Unit)
   325  	}
   326  }
   327
View as plain text