diff options
author | Ian Lance Taylor <iant@golang.org> | 2017-01-14 00:05:42 +0000 |
---|---|---|
committer | Ian Lance Taylor <ian@gcc.gnu.org> | 2017-01-14 00:05:42 +0000 |
commit | c2047754c300b68c05d65faa8dc2925fe67b71b4 (patch) | |
tree | e183ae81a1f48a02945cb6de463a70c5be1b06f6 /libgo/go/runtime/pprof | |
parent | 829afb8f05602bb31c9c597b24df7377fed4f059 (diff) | |
download | gcc-c2047754c300b68c05d65faa8dc2925fe67b71b4.zip gcc-c2047754c300b68c05d65faa8dc2925fe67b71b4.tar.gz gcc-c2047754c300b68c05d65faa8dc2925fe67b71b4.tar.bz2 |
libgo: update to Go 1.8 release candidate 1
Compiler changes:
* Change map assignment to use mapassign and assign value directly.
* Change string iteration to use decoderune, faster for ASCII strings.
* Change makeslice to take int, and use makeslice64 for larger values.
* Add new noverflow field to hmap struct used for maps.
Unresolved problems, to be fixed later:
* Commented out test in go/types/sizes_test.go that doesn't compile.
* Commented out reflect.TestStructOf test for padding after zero-sized field.
Reviewed-on: https://go-review.googlesource.com/35231
gotools/:
Updates for Go 1.8rc1.
* Makefile.am (go_cmd_go_files): Add bug.go.
(s-zdefaultcc): Write defaultPkgConfig.
* Makefile.in: Rebuild.
From-SVN: r244456
Diffstat (limited to 'libgo/go/runtime/pprof')
-rw-r--r-- | libgo/go/runtime/pprof/internal/protopprof/protomemprofile.go | 83 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/internal/protopprof/protomemprofile_test.go | 104 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/internal/protopprof/protopprof.go | 105 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/internal/protopprof/protopprof_test.go | 171 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/mprof_test.go | 29 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/pprof.go | 221 | ||||
-rw-r--r-- | libgo/go/runtime/pprof/pprof_test.go | 185 |
7 files changed, 767 insertions, 131 deletions
diff --git a/libgo/go/runtime/pprof/internal/protopprof/protomemprofile.go b/libgo/go/runtime/pprof/internal/protopprof/protomemprofile.go new file mode 100644 index 0000000..c2ab5b5 --- /dev/null +++ b/libgo/go/runtime/pprof/internal/protopprof/protomemprofile.go @@ -0,0 +1,83 @@ +// Copyright 2016 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package protopprof + +import ( + "internal/pprof/profile" + "math" + "runtime" + "time" +) + +// EncodeMemProfile converts MemProfileRecords to a Profile. +func EncodeMemProfile(mr []runtime.MemProfileRecord, rate int64, t time.Time) *profile.Profile { + p := &profile.Profile{ + Period: rate, + PeriodType: &profile.ValueType{Type: "space", Unit: "bytes"}, + SampleType: []*profile.ValueType{ + {Type: "alloc_objects", Unit: "count"}, + {Type: "alloc_space", Unit: "bytes"}, + {Type: "inuse_objects", Unit: "count"}, + {Type: "inuse_space", Unit: "bytes"}, + }, + TimeNanos: int64(t.UnixNano()), + } + + locs := make(map[uintptr]*profile.Location) + for _, r := range mr { + stack := r.Stack() + sloc := make([]*profile.Location, len(stack)) + for i, addr := range stack { + loc := locs[addr] + if loc == nil { + loc = &profile.Location{ + ID: uint64(len(p.Location) + 1), + Address: uint64(addr), + } + locs[addr] = loc + p.Location = append(p.Location, loc) + } + sloc[i] = loc + } + + ao, ab := scaleHeapSample(r.AllocObjects, r.AllocBytes, rate) + uo, ub := scaleHeapSample(r.InUseObjects(), r.InUseBytes(), rate) + + p.Sample = append(p.Sample, &profile.Sample{ + Value: []int64{ao, ab, uo, ub}, + Location: sloc, + }) + } + if runtime.GOOS == "linux" { + addMappings(p) + } + return p +} + +// scaleHeapSample adjusts the data from a heap Sample to +// account for its probability of appearing in the collected +// data. heap profiles are a sampling of the memory allocations +// requests in a program. We estimate the unsampled value by dividing +// each collected sample by its probability of appearing in the +// profile. heap profiles rely on a poisson process to determine +// which samples to collect, based on the desired average collection +// rate R. The probability of a sample of size S to appear in that +// profile is 1-exp(-S/R). +func scaleHeapSample(count, size, rate int64) (int64, int64) { + if count == 0 || size == 0 { + return 0, 0 + } + + if rate <= 1 { + // if rate==1 all samples were collected so no adjustment is needed. + // if rate<1 treat as unknown and skip scaling. + return count, size + } + + avgSize := float64(size) / float64(count) + scale := 1 / (1 - math.Exp(-avgSize/float64(rate))) + + return int64(float64(count) * scale), int64(float64(size) * scale) +} diff --git a/libgo/go/runtime/pprof/internal/protopprof/protomemprofile_test.go b/libgo/go/runtime/pprof/internal/protopprof/protomemprofile_test.go new file mode 100644 index 0000000..a10fe77 --- /dev/null +++ b/libgo/go/runtime/pprof/internal/protopprof/protomemprofile_test.go @@ -0,0 +1,104 @@ +// Copyright 2016 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package protopprof + +import ( + "bytes" + "internal/pprof/profile" + "io/ioutil" + "reflect" + "runtime" + "testing" + "time" +) + +// TestSampledHeapAllocProfile tests encoding of a memory profile from +// runtime.MemProfileRecord data. +func TestSampledHeapAllocProfile(t *testing.T) { + if runtime.GOOS != "linux" { + t.Skip("Test requires a system with /proc/self/maps") + } + + // Figure out two addresses from /proc/self/maps. + mmap, err := ioutil.ReadFile("/proc/self/maps") + if err != nil { + t.Fatal("Cannot read /proc/self/maps") + } + rd := bytes.NewReader(mmap) + mprof := &profile.Profile{} + if err = mprof.ParseMemoryMap(rd); err != nil { + t.Fatalf("Cannot parse /proc/self/maps") + } + if len(mprof.Mapping) < 2 { + // It is possible for a binary to only have 1 executable + // region of memory. + t.Skipf("need 2 or more mappings, got %v", len(mprof.Mapping)) + } + address1 := mprof.Mapping[0].Start + address2 := mprof.Mapping[1].Start + + var buf bytes.Buffer + + rec, rate := testMemRecords(address1, address2) + p := EncodeMemProfile(rec, rate, time.Now()) + if err := p.Write(&buf); err != nil { + t.Fatalf("Failed to write profile: %v", err) + } + + p, err = profile.Parse(&buf) + if err != nil { + t.Fatalf("Could not parse Profile profile: %v", err) + } + + // Expected PeriodType, SampleType and Sample. + expectedPeriodType := &profile.ValueType{Type: "space", Unit: "bytes"} + expectedSampleType := []*profile.ValueType{ + {Type: "alloc_objects", Unit: "count"}, + {Type: "alloc_space", Unit: "bytes"}, + {Type: "inuse_objects", Unit: "count"}, + {Type: "inuse_space", Unit: "bytes"}, + } + // Expected samples, with values unsampled according to the profiling rate. + expectedSample := []*profile.Sample{ + {Value: []int64{2050, 2099200, 1537, 1574400}, Location: []*profile.Location{ + {ID: 1, Mapping: mprof.Mapping[0], Address: address1}, + {ID: 2, Mapping: mprof.Mapping[1], Address: address2}, + }}, + {Value: []int64{1, 829411, 1, 829411}, Location: []*profile.Location{ + {ID: 3, Mapping: mprof.Mapping[1], Address: address2 + 1}, + {ID: 4, Mapping: mprof.Mapping[1], Address: address2 + 2}, + }}, + {Value: []int64{1, 829411, 0, 0}, Location: []*profile.Location{ + {ID: 5, Mapping: mprof.Mapping[0], Address: address1 + 1}, + {ID: 6, Mapping: mprof.Mapping[0], Address: address1 + 2}, + {ID: 7, Mapping: mprof.Mapping[1], Address: address2 + 3}, + }}, + } + + if p.Period != 512*1024 { + t.Fatalf("Sampling periods do not match") + } + if !reflect.DeepEqual(p.PeriodType, expectedPeriodType) { + t.Fatalf("Period types do not match") + } + if !reflect.DeepEqual(p.SampleType, expectedSampleType) { + t.Fatalf("Sample types do not match") + } + if !reflect.DeepEqual(p.Sample, expectedSample) { + t.Fatalf("Samples do not match: Expected: %v, Got:%v", getSampleAsString(expectedSample), + getSampleAsString(p.Sample)) + } +} + +func testMemRecords(a1, a2 uint64) ([]runtime.MemProfileRecord, int64) { + addr1, addr2 := uintptr(a1), uintptr(a2) + rate := int64(512 * 1024) + rec := []runtime.MemProfileRecord{ + {4096, 1024, 4, 1, [32]uintptr{addr1, addr2}}, + {512 * 1024, 0, 1, 0, [32]uintptr{addr2 + 1, addr2 + 2}}, + {512 * 1024, 512 * 1024, 1, 1, [32]uintptr{addr1 + 1, addr1 + 2, addr2 + 3}}, + } + return rec, rate +} diff --git a/libgo/go/runtime/pprof/internal/protopprof/protopprof.go b/libgo/go/runtime/pprof/internal/protopprof/protopprof.go new file mode 100644 index 0000000..5d269c4 --- /dev/null +++ b/libgo/go/runtime/pprof/internal/protopprof/protopprof.go @@ -0,0 +1,105 @@ +// Copyright 2016 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package protopprof converts the runtime's raw profile logs +// to Profile structs containing a representation of the pprof +// protocol buffer profile format. +package protopprof + +import ( + "fmt" + "os" + "runtime" + "time" + "unsafe" + + "internal/pprof/profile" +) + +// TranslateCPUProfile parses binary CPU profiling stack trace data +// generated by runtime.CPUProfile() into a profile struct. +func TranslateCPUProfile(b []byte, startTime time.Time) (*profile.Profile, error) { + const wordSize = unsafe.Sizeof(uintptr(0)) + const minRawProfile = 5 * wordSize // Need a minimum of 5 words. + if uintptr(len(b)) < minRawProfile { + return nil, fmt.Errorf("truncated profile") + } + n := int(uintptr(len(b)) / wordSize) + data := ((*[1 << 28]uintptr)(unsafe.Pointer(&b[0])))[:n:n] + period := data[3] + data = data[5:] // skip header + + // profile initialization taken from pprof tool + p := &profile.Profile{ + Period: int64(period) * 1000, + PeriodType: &profile.ValueType{Type: "cpu", Unit: "nanoseconds"}, + SampleType: []*profile.ValueType{ + {Type: "samples", Unit: "count"}, + {Type: "cpu", Unit: "nanoseconds"}, + }, + TimeNanos: int64(startTime.UnixNano()), + DurationNanos: time.Since(startTime).Nanoseconds(), + } + // Parse CPU samples from the profile. + locs := make(map[uint64]*profile.Location) + for len(b) > 0 { + if len(data) < 2 || uintptr(len(data)) < 2+data[1] { + return nil, fmt.Errorf("truncated profile") + } + count := data[0] + nstk := data[1] + if uintptr(len(data)) < 2+nstk { + return nil, fmt.Errorf("truncated profile") + } + stk := data[2 : 2+nstk] + data = data[2+nstk:] + + if count == 0 && nstk == 1 && stk[0] == 0 { + // end of data marker + break + } + + sloc := make([]*profile.Location, len(stk)) + for i, addr := range stk { + addr := uint64(addr) + // Addresses from stack traces point to the next instruction after + // each call. Adjust by -1 to land somewhere on the actual call + // (except for the leaf, which is not a call). + if i > 0 { + addr-- + } + loc := locs[addr] + if loc == nil { + loc = &profile.Location{ + ID: uint64(len(p.Location) + 1), + Address: addr, + } + locs[addr] = loc + p.Location = append(p.Location, loc) + } + sloc[i] = loc + } + p.Sample = append(p.Sample, &profile.Sample{ + Value: []int64{int64(count), int64(count) * int64(p.Period)}, + Location: sloc, + }) + } + + if runtime.GOOS == "linux" { + if err := addMappings(p); err != nil { + return nil, err + } + } + return p, nil +} + +func addMappings(p *profile.Profile) error { + // Parse memory map from /proc/self/maps + f, err := os.Open("/proc/self/maps") + if err != nil { + return err + } + defer f.Close() + return p.ParseMemoryMap(f) +} diff --git a/libgo/go/runtime/pprof/internal/protopprof/protopprof_test.go b/libgo/go/runtime/pprof/internal/protopprof/protopprof_test.go new file mode 100644 index 0000000..f1937b5 --- /dev/null +++ b/libgo/go/runtime/pprof/internal/protopprof/protopprof_test.go @@ -0,0 +1,171 @@ +// Copyright 2016 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package protopprof + +import ( + "bytes" + "fmt" + "internal/pprof/profile" + "io/ioutil" + "reflect" + "runtime" + "testing" + "time" + "unsafe" +) + +// Helper function to initialize empty cpu profile with sampling period provided. +func createEmptyProfileWithPeriod(t *testing.T, periodMs uint64) bytes.Buffer { + // Mock the sample header produced by cpu profiler. Write a sample + // period of 2000 microseconds, followed by no samples. + buf := new(bytes.Buffer) + // Profile header is as follows: + // The first, third and fifth words are 0. The second word is 3. + // The fourth word is the period. + // EOD marker: + // The sixth word -- count is initialized to 0 above. + // The code below sets the seventh word -- nstk to 1 + // The eighth word -- addr is initialized to 0 above. + words := []int{0, 3, 0, int(periodMs), 0, 0, 1, 0} + n := int(unsafe.Sizeof(0)) * len(words) + data := ((*[1 << 29]byte)(unsafe.Pointer(&words[0])))[:n:n] + if _, err := buf.Write(data); err != nil { + t.Fatalf("createEmptyProfileWithPeriod failed: %v", err) + } + return *buf +} + +// Helper function to initialize cpu profile with two sample values. +func createProfileWithTwoSamples(t *testing.T, periodMs uintptr, count1 uintptr, count2 uintptr, + address1 uintptr, address2 uintptr) bytes.Buffer { + // Mock the sample header produced by cpu profiler. Write a sample + // period of 2000 microseconds, followed by no samples. + buf := new(bytes.Buffer) + words := []uintptr{0, 3, 0, uintptr(periodMs), 0, uintptr(count1), 2, + uintptr(address1), uintptr(address1 + 2), + uintptr(count2), 2, uintptr(address2), uintptr(address2 + 2), + 0, 1, 0} + for _, n := range words { + var err error + switch unsafe.Sizeof(int(0)) { + case 8: + _, err = buf.Write((*[8]byte)(unsafe.Pointer(&n))[:8:8]) + case 4: + _, err = buf.Write((*[4]byte)(unsafe.Pointer(&n))[:4:4]) + } + if err != nil { + t.Fatalf("createProfileWithTwoSamples failed: %v", err) + } + } + return *buf +} + +// Tests TranslateCPUProfile parses correct sampling period in an otherwise empty cpu profile. +func TestTranlateCPUProfileSamplingPeriod(t *testing.T) { + // A test server with mock cpu profile data. + var buf bytes.Buffer + + startTime := time.Now() + b := createEmptyProfileWithPeriod(t, 2000) + p, err := TranslateCPUProfile(b.Bytes(), startTime) + if err != nil { + t.Fatalf("translate failed: %v", err) + } + if err := p.Write(&buf); err != nil { + t.Fatalf("write failed: %v", err) + } + + p, err = profile.Parse(&buf) + if err != nil { + t.Fatalf("Could not parse Profile profile: %v", err) + } + + // Expected PeriodType and SampleType. + expectedPeriodType := &profile.ValueType{Type: "cpu", Unit: "nanoseconds"} + expectedSampleType := []*profile.ValueType{ + {Type: "samples", Unit: "count"}, + {Type: "cpu", Unit: "nanoseconds"}, + } + if p.Period != 2000*1000 || !reflect.DeepEqual(p.PeriodType, expectedPeriodType) || + !reflect.DeepEqual(p.SampleType, expectedSampleType) || p.Sample != nil { + t.Fatalf("Unexpected Profile fields") + } +} + +func getSampleAsString(sample []*profile.Sample) string { + var str string + for _, x := range sample { + for _, y := range x.Location { + if y.Mapping != nil { + str += fmt.Sprintf("Mapping:%v\n", *y.Mapping) + } + str += fmt.Sprintf("Location:%v\n", y) + } + str += fmt.Sprintf("Sample:%v\n", *x) + } + return str +} + +// Tests TranslateCPUProfile parses a cpu profile with sample values present. +func TestTranslateCPUProfileWithSamples(t *testing.T) { + if runtime.GOOS != "linux" { + t.Skip("test requires a system with /proc/self/maps") + } + // Figure out two addresses from /proc/self/maps. + mmap, err := ioutil.ReadFile("/proc/self/maps") + if err != nil { + t.Fatal("Cannot read /proc/self/maps") + } + rd := bytes.NewReader(mmap) + mprof := &profile.Profile{} + if err = mprof.ParseMemoryMap(rd); err != nil { + t.Fatalf("Cannot parse /proc/self/maps") + } + if len(mprof.Mapping) < 2 { + // It is possible for a binary to only have 1 executable + // region of memory. + t.Skipf("need 2 or more mappings, got %v", len(mprof.Mapping)) + } + address1 := mprof.Mapping[0].Start + address2 := mprof.Mapping[1].Start + // A test server with mock cpu profile data. + + startTime := time.Now() + b := createProfileWithTwoSamples(t, 2000, 20, 40, uintptr(address1), uintptr(address2)) + p, err := TranslateCPUProfile(b.Bytes(), startTime) + + if err != nil { + t.Fatalf("Could not parse Profile profile: %v", err) + } + // Expected PeriodType, SampleType and Sample. + expectedPeriodType := &profile.ValueType{Type: "cpu", Unit: "nanoseconds"} + expectedSampleType := []*profile.ValueType{ + {Type: "samples", Unit: "count"}, + {Type: "cpu", Unit: "nanoseconds"}, + } + expectedSample := []*profile.Sample{ + {Value: []int64{20, 20 * 2000 * 1000}, Location: []*profile.Location{ + {ID: 1, Mapping: mprof.Mapping[0], Address: address1}, + {ID: 2, Mapping: mprof.Mapping[0], Address: address1 + 1}, + }}, + {Value: []int64{40, 40 * 2000 * 1000}, Location: []*profile.Location{ + {ID: 3, Mapping: mprof.Mapping[1], Address: address2}, + {ID: 4, Mapping: mprof.Mapping[1], Address: address2 + 1}, + }}, + } + if p.Period != 2000*1000 { + t.Fatalf("Sampling periods do not match") + } + if !reflect.DeepEqual(p.PeriodType, expectedPeriodType) { + t.Fatalf("Period types do not match") + } + if !reflect.DeepEqual(p.SampleType, expectedSampleType) { + t.Fatalf("Sample types do not match") + } + if !reflect.DeepEqual(p.Sample, expectedSample) { + t.Fatalf("Samples do not match: Expected: %v, Got:%v", getSampleAsString(expectedSample), + getSampleAsString(p.Sample)) + } +} diff --git a/libgo/go/runtime/pprof/mprof_test.go b/libgo/go/runtime/pprof/mprof_test.go index 54daefa..079af15 100644 --- a/libgo/go/runtime/pprof/mprof_test.go +++ b/libgo/go/runtime/pprof/mprof_test.go @@ -7,6 +7,7 @@ package pprof_test import ( "bytes" "fmt" + "reflect" "regexp" "runtime" . "runtime/pprof" @@ -42,6 +43,17 @@ func allocatePersistent1K() { } } +// Allocate transient memory using reflect.Call. + +func allocateReflectTransient() { + memSink = make([]byte, 2<<20) +} + +func allocateReflect() { + rv := reflect.ValueOf(allocateReflectTransient) + rv.Call(nil) +} + var memoryProfilerRun = 0 func TestMemoryProfiler(t *testing.T) { @@ -61,6 +73,7 @@ func TestMemoryProfiler(t *testing.T) { allocateTransient1M() allocateTransient2M() allocatePersistent1K() + allocateReflect() memSink = nil runtime.GC() // materialize stats @@ -74,21 +87,25 @@ func TestMemoryProfiler(t *testing.T) { tests := []string{ fmt.Sprintf(`%v: %v \[%v: %v\] @ 0x[0-9,a-f x]+ -# 0x[0-9,a-f]+ pprof_test\.allocatePersistent1K\+0x[0-9,a-f]+ .*/mprof_test\.go:40 -# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test\.go:63 +# 0x[0-9,a-f]+ pprof_test\.allocatePersistent1K\+0x[0-9,a-f]+ .*/mprof_test\.go:41 +# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test\.go:75 `, 32*memoryProfilerRun, 1024*memoryProfilerRun, 32*memoryProfilerRun, 1024*memoryProfilerRun), fmt.Sprintf(`0: 0 \[%v: %v\] @ 0x[0-9,a-f x]+ -# 0x[0-9,a-f]+ pprof_test\.allocateTransient1M\+0x[0-9,a-f]+ .*/mprof_test.go:21 -# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test.go:61 +# 0x[0-9,a-f]+ pprof_test\.allocateTransient1M\+0x[0-9,a-f]+ .*/mprof_test.go:22 +# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test.go:73 `, (1<<10)*memoryProfilerRun, (1<<20)*memoryProfilerRun), // This should start with "0: 0" but gccgo's imprecise // GC means that sometimes the value is not collected. fmt.Sprintf(`(0|%v): (0|%v) \[%v: %v\] @ 0x[0-9,a-f x]+ -# 0x[0-9,a-f]+ pprof_test\.allocateTransient2M\+0x[0-9,a-f]+ .*/mprof_test.go:27 -# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test.go:62 +# 0x[0-9,a-f]+ pprof_test\.allocateTransient2M\+0x[0-9,a-f]+ .*/mprof_test.go:28 +# 0x[0-9,a-f]+ runtime_pprof_test\.TestMemoryProfiler\+0x[0-9,a-f]+ .*/mprof_test.go:74 `, memoryProfilerRun, (2<<20)*memoryProfilerRun, memoryProfilerRun, (2<<20)*memoryProfilerRun), + + fmt.Sprintf(`0: 0 \[%v: %v\] @( 0x[0-9,a-f]+)+ +# 0x[0-9,a-f]+ pprof_test\.allocateReflectTransient\+0x[0-9,a-f]+ .*/mprof_test.go:49 +`, memoryProfilerRun, (2<<20)*memoryProfilerRun), } for _, test := range tests { diff --git a/libgo/go/runtime/pprof/pprof.go b/libgo/go/runtime/pprof/pprof.go index 0a58baf..0db1ded 100644 --- a/libgo/go/runtime/pprof/pprof.go +++ b/libgo/go/runtime/pprof/pprof.go @@ -73,13 +73,15 @@ import ( "bufio" "bytes" "fmt" + "internal/pprof/profile" "io" - "os" "runtime" + "runtime/pprof/internal/protopprof" "sort" "strings" "sync" "text/tabwriter" + "time" ) // BUG(rsc): Profiles are only as good as the kernel support used to generate them. @@ -99,6 +101,7 @@ import ( // heap - a sampling of all heap allocations // threadcreate - stack traces that led to the creation of new OS threads // block - stack traces that led to blocking on synchronization primitives +// mutex - stack traces of holders of contended mutexes // // These predefined profiles maintain themselves and panic on an explicit // Add or Remove method call. @@ -152,6 +155,12 @@ var blockProfile = &Profile{ write: writeBlock, } +var mutexProfile = &Profile{ + name: "mutex", + count: countMutex, + write: writeMutex, +} + func lockProfiles() { profiles.mu.Lock() if profiles.m == nil { @@ -161,6 +170,7 @@ func lockProfiles() { "threadcreate": threadcreateProfile, "heap": heapProfile, "block": blockProfile, + "mutex": mutexProfile, } } } @@ -202,21 +212,15 @@ func Profiles() []*Profile { lockProfiles() defer unlockProfiles() - var all []*Profile + all := make([]*Profile, 0, len(profiles.m)) for _, p := range profiles.m { all = append(all, p) } - sort.Sort(byName(all)) + sort.Slice(all, func(i, j int) bool { return all[i].name < all[j].name }) return all } -type byName []*Profile - -func (x byName) Len() int { return len(x) } -func (x byName) Swap(i, j int) { x[i], x[j] = x[j], x[i] } -func (x byName) Less(i, j int) bool { return x[i].name < x[j].name } - // Name returns this profile's name, which can be passed to Lookup to reobtain the profile. func (p *Profile) Name() string { return p.name @@ -299,7 +303,7 @@ func (p *Profile) WriteTo(w io.Writer, debug int) error { } // Obtain consistent snapshot under lock; then process without lock. - var all [][]uintptr + all := make([][]uintptr, 0, len(p.m)) p.mu.Lock() for _, stk := range p.m { all = append(all, stk) @@ -337,17 +341,8 @@ type countProfile interface { } // printCountProfile prints a countProfile at the specified debug level. +// The profile will be in compressed proto format unless debug is nonzero. func printCountProfile(w io.Writer, debug int, name string, p countProfile) error { - b := bufio.NewWriter(w) - var tw *tabwriter.Writer - w = b - if debug > 0 { - tw = tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) - w = tw - } - - fmt.Fprintf(w, "%s profile: total %d\n", name, p.Len()) - // Build count of each stack. var buf bytes.Buffer key := func(stk []uintptr) string { @@ -373,17 +368,47 @@ func printCountProfile(w io.Writer, debug int, name string, p countProfile) erro sort.Sort(&keysByCount{keys, count}) - for _, k := range keys { - fmt.Fprintf(w, "%d %s\n", count[k], k) - if debug > 0 { - printStackRecord(w, p.Stack(index[k]), false) + if debug > 0 { + // Print debug profile in legacy format + tw := tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) + fmt.Fprintf(tw, "%s profile: total %d\n", name, p.Len()) + for _, k := range keys { + fmt.Fprintf(tw, "%d %s\n", count[k], k) + printStackRecord(tw, p.Stack(index[k]), false) } + return tw.Flush() } - if tw != nil { - tw.Flush() + // Output profile in protobuf form. + prof := &profile.Profile{ + PeriodType: &profile.ValueType{Type: name, Unit: "count"}, + Period: 1, + Sample: make([]*profile.Sample, 0, len(keys)), + SampleType: []*profile.ValueType{{Type: name, Unit: "count"}}, } - return b.Flush() + locMap := make(map[uintptr]*profile.Location) + for _, k := range keys { + stk := p.Stack(index[k]) + c := count[k] + locs := make([]*profile.Location, len(stk)) + for i, addr := range stk { + loc := locMap[addr] + if loc == nil { + loc = &profile.Location{ + ID: uint64(len(locMap) + 1), + Address: uint64(addr - 1), + } + prof.Location = append(prof.Location, loc) + locMap[addr] = loc + } + locs[i] = loc + } + prof.Sample = append(prof.Sample, &profile.Sample{ + Location: locs, + Value: []int64{int64(c)}, + }) + } + return prof.Write(w) } // keysByCount sorts keys with higher counts first, breaking ties by key string order. @@ -449,12 +474,6 @@ func printStackRecord(w io.Writer, stk []uintptr, allFrames bool) { // Interface to system profiles. -type byInUseBytes []runtime.MemProfileRecord - -func (x byInUseBytes) Len() int { return len(x) } -func (x byInUseBytes) Swap(i, j int) { x[i], x[j] = x[j], x[i] } -func (x byInUseBytes) Less(i, j int) bool { return x[i].InUseBytes() > x[j].InUseBytes() } - // WriteHeapProfile is shorthand for Lookup("heap").WriteTo(w, 0). // It is preserved for backwards compatibility. func WriteHeapProfile(w io.Writer) error { @@ -490,15 +509,16 @@ func writeHeap(w io.Writer, debug int) error { // Profile grew; try again. } - sort.Sort(byInUseBytes(p)) + if debug == 0 { + pp := protopprof.EncodeMemProfile(p, int64(runtime.MemProfileRate), time.Now()) + return pp.Write(w) + } + + sort.Slice(p, func(i, j int) bool { return p[i].InUseBytes() > p[j].InUseBytes() }) b := bufio.NewWriter(w) - var tw *tabwriter.Writer - w = b - if debug > 0 { - tw = tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) - w = tw - } + tw := tabwriter.NewWriter(b, 1, 8, 1, '\t', 0) + w = tw var total runtime.MemProfileRecord for i := range p { @@ -526,9 +546,7 @@ func writeHeap(w io.Writer, debug int) error { fmt.Fprintf(w, " %#x", pc) } fmt.Fprintf(w, "\n") - if debug > 0 { - printStackRecord(w, r.Stack(), false) - } + printStackRecord(w, r.Stack(), false) } // Print memstats information too. @@ -554,15 +572,15 @@ func writeHeap(w io.Writer, debug int) error { fmt.Fprintf(w, "# MSpan = %d / %d\n", s.MSpanInuse, s.MSpanSys) fmt.Fprintf(w, "# MCache = %d / %d\n", s.MCacheInuse, s.MCacheSys) fmt.Fprintf(w, "# BuckHashSys = %d\n", s.BuckHashSys) + fmt.Fprintf(w, "# GCSys = %d\n", s.GCSys) + fmt.Fprintf(w, "# OtherSys = %d\n", s.OtherSys) fmt.Fprintf(w, "# NextGC = %d\n", s.NextGC) fmt.Fprintf(w, "# PauseNs = %d\n", s.PauseNs) fmt.Fprintf(w, "# NumGC = %d\n", s.NumGC) fmt.Fprintf(w, "# DebugGC = %v\n", s.DebugGC) - if tw != nil { - tw.Flush() - } + tw.Flush() return b.Flush() } @@ -686,49 +704,29 @@ func StartCPUProfile(w io.Writer) error { } func profileWriter(w io.Writer) { + startTime := time.Now() + // This will buffer the entire profile into buf and then + // translate it into a profile.Profile structure. This will + // create two copies of all the data in the profile in memory. + // TODO(matloob): Convert each chunk of the proto output and + // stream it out instead of converting the entire profile. + var buf bytes.Buffer for { data := runtime.CPUProfile() if data == nil { break } - w.Write(data) - } - - // We are emitting the legacy profiling format, which permits - // a memory map following the CPU samples. The memory map is - // simply a copy of the GNU/Linux /proc/self/maps file. The - // profiler uses the memory map to map PC values in shared - // libraries to a shared library in the filesystem, in order - // to report the correct function and, if the shared library - // has debug info, file/line. This is particularly useful for - // PIE (position independent executables) as on ELF systems a - // PIE is simply an executable shared library. - // - // Because the profiling format expects the memory map in - // GNU/Linux format, we only do this on GNU/Linux for now. To - // add support for profiling PIE on other ELF-based systems, - // it may be necessary to map the system-specific mapping - // information to the GNU/Linux format. For a reasonably - // portable C++ version, see the FillProcSelfMaps function in - // https://github.com/gperftools/gperftools/blob/master/src/base/sysinfo.cc - // - // The code that parses this mapping for the pprof tool is - // ParseMemoryMap in cmd/internal/pprof/legacy_profile.go, but - // don't change that code, as similar code exists in other - // (non-Go) pprof readers. Change this code so that that code works. - // - // We ignore errors reading or copying the memory map; the - // profile is likely usable without it, and we have no good way - // to report errors. - if runtime.GOOS == "linux" { - f, err := os.Open("/proc/self/maps") - if err == nil { - io.WriteString(w, "\nMAPPED_LIBRARIES:\n") - io.Copy(w, f) - f.Close() - } + buf.Write(data) + } + + profile, err := protopprof.TranslateCPUProfile(buf.Bytes(), startTime) + if err != nil { + // The runtime should never produce an invalid or truncated profile. + // It drops records that can't fit into its log buffers. + panic(fmt.Errorf("could not translate binary profile to proto format: %v", err)) } + profile.Write(w) cpu.done <- true } @@ -747,18 +745,18 @@ func StopCPUProfile() { <-cpu.done } -type byCycles []runtime.BlockProfileRecord - -func (x byCycles) Len() int { return len(x) } -func (x byCycles) Swap(i, j int) { x[i], x[j] = x[j], x[i] } -func (x byCycles) Less(i, j int) bool { return x[i].Cycles > x[j].Cycles } - // countBlock returns the number of records in the blocking profile. func countBlock() int { n, _ := runtime.BlockProfile(nil) return n } +// countMutex returns the number of records in the mutex profile. +func countMutex() int { + n, _ := runtime.MutexProfile(nil) + return n +} + // writeBlock writes the current blocking profile to w. func writeBlock(w io.Writer, debug int) error { var p []runtime.BlockProfileRecord @@ -772,7 +770,7 @@ func writeBlock(w io.Writer, debug int) error { } } - sort.Sort(byCycles(p)) + sort.Slice(p, func(i, j int) bool { return p[i].Cycles > p[j].Cycles }) b := bufio.NewWriter(w) var tw *tabwriter.Writer @@ -802,4 +800,49 @@ func writeBlock(w io.Writer, debug int) error { return b.Flush() } +// writeMutex writes the current mutex profile to w. +func writeMutex(w io.Writer, debug int) error { + // TODO(pjw): too much common code with writeBlock. FIX! + var p []runtime.BlockProfileRecord + n, ok := runtime.MutexProfile(nil) + for { + p = make([]runtime.BlockProfileRecord, n+50) + n, ok = runtime.MutexProfile(p) + if ok { + p = p[:n] + break + } + } + + sort.Slice(p, func(i, j int) bool { return p[i].Cycles > p[j].Cycles }) + + b := bufio.NewWriter(w) + var tw *tabwriter.Writer + w = b + if debug > 0 { + tw = tabwriter.NewWriter(w, 1, 8, 1, '\t', 0) + w = tw + } + + fmt.Fprintf(w, "--- mutex:\n") + fmt.Fprintf(w, "cycles/second=%v\n", runtime_cyclesPerSecond()) + fmt.Fprintf(w, "sampling period=%d\n", runtime.SetMutexProfileFraction(-1)) + for i := range p { + r := &p[i] + fmt.Fprintf(w, "%v %v @", r.Cycles, r.Count) + for _, pc := range r.Stack() { + fmt.Fprintf(w, " %#x", pc) + } + fmt.Fprint(w, "\n") + if debug > 0 { + printStackRecord(w, r.Stack(), true) + } + } + + if tw != nil { + tw.Flush() + } + return b.Flush() +} + func runtime_cyclesPerSecond() int64 diff --git a/libgo/go/runtime/pprof/pprof_test.go b/libgo/go/runtime/pprof/pprof_test.go index 1692d42..6034058 100644 --- a/libgo/go/runtime/pprof/pprof_test.go +++ b/libgo/go/runtime/pprof/pprof_test.go @@ -8,8 +8,12 @@ package pprof_test import ( "bytes" + "compress/gzip" "fmt" + "internal/pprof/profile" "internal/testenv" + "io" + "io/ioutil" "math/big" "os" "os/exec" @@ -20,7 +24,6 @@ import ( "sync" "testing" "time" - "unsafe" ) func cpuHogger(f func(), dur time.Duration) { @@ -87,40 +90,17 @@ func TestCPUProfileMultithreaded(t *testing.T) { } func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []uintptr)) { - // Convert []byte to []uintptr. - l := len(valBytes) - if i := bytes.Index(valBytes, []byte("\nMAPPED_LIBRARIES:\n")); i >= 0 { - l = i - } - l /= int(unsafe.Sizeof(uintptr(0))) - val := *(*[]uintptr)(unsafe.Pointer(&valBytes)) - val = val[:l] - - // 5 for the header, 3 for the trailer. - if l < 5+3 { - t.Logf("profile too short: %#x", val) - if badOS[runtime.GOOS] { - t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS) - return - } - t.FailNow() - } - - hd, val, tl := val[:5], val[5:l-3], val[l-3:] - if hd[0] != 0 || hd[1] != 3 || hd[2] != 0 || hd[3] != 1e6/100 || hd[4] != 0 { - t.Fatalf("unexpected header %#x", hd) - } - - if tl[0] != 0 || tl[1] != 1 || tl[2] != 0 { - t.Fatalf("malformed end-of-data marker %#x", tl) + p, err := profile.Parse(bytes.NewReader(valBytes)) + if err != nil { + t.Fatal(err) } - - for len(val) > 0 { - if len(val) < 2 || val[0] < 1 || val[1] < 1 || uintptr(len(val)) < 2+val[1] { - t.Fatalf("malformed profile. leftover: %#x", val) + for _, sample := range p.Sample { + count := uintptr(sample.Value[0]) + stk := make([]uintptr, len(sample.Location)) + for i := range sample.Location { + stk[i] = uintptr(sample.Location[i].Address) } - f(val[0], val[2:2+val[1]]) - val = val[2+val[1]:] + f(count, stk) } } @@ -225,7 +205,11 @@ func profileOk(t *testing.T, need []string, prof bytes.Buffer, duration time.Dur } // Check that we got a reasonable number of samples. - if ideal := uintptr(duration * 100 / time.Second); samples == 0 || samples < ideal/4 { + // We used to always require at least ideal/4 samples, + // but that is too hard to guarantee on a loaded system. + // Now we accept 10 or more samples, which we take to be + // enough to show that at least some profiling is occurring. + if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) { t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal) ok = false } @@ -367,8 +351,49 @@ func TestMathBigDivide(t *testing.T) { }) } +func slurpString(r io.Reader) string { + slurp, _ := ioutil.ReadAll(r) + return string(slurp) +} + +func getLinuxKernelConfig() string { + if f, err := os.Open("/proc/config"); err == nil { + defer f.Close() + return slurpString(f) + } + if f, err := os.Open("/proc/config.gz"); err == nil { + defer f.Close() + r, err := gzip.NewReader(f) + if err != nil { + return "" + } + return slurpString(r) + } + if f, err := os.Open("/boot/config"); err == nil { + defer f.Close() + return slurpString(f) + } + uname, _ := exec.Command("uname", "-r").Output() + if len(uname) > 0 { + if f, err := os.Open("/boot/config-" + strings.TrimSpace(string(uname))); err == nil { + defer f.Close() + return slurpString(f) + } + } + return "" +} + +func haveLinuxHiresTimers() bool { + config := getLinuxKernelConfig() + return strings.Contains(config, "CONFIG_HIGH_RES_TIMERS=y") +} + func TestStackBarrierProfiling(t *testing.T) { - if (runtime.GOOS == "linux" && runtime.GOARCH == "arm") || runtime.GOOS == "openbsd" || runtime.GOOS == "solaris" || runtime.GOOS == "dragonfly" || runtime.GOOS == "freebsd" { + if (runtime.GOOS == "linux" && runtime.GOARCH == "arm") || + runtime.GOOS == "openbsd" || + runtime.GOOS == "solaris" || + runtime.GOOS == "dragonfly" || + runtime.GOOS == "freebsd" { // This test currently triggers a large number of // usleep(100)s. These kernels/arches have poor // resolution timers, so this gives up a whole @@ -381,6 +406,12 @@ func TestStackBarrierProfiling(t *testing.T) { return } + if runtime.GOOS == "linux" && strings.HasPrefix(runtime.GOARCH, "mips") { + if !haveLinuxHiresTimers() { + t.Skipf("low resolution timers inhibit profiling signals (golang.org/issue/13405, golang.org/issue/17936)") + } + } + if !strings.Contains(os.Getenv("GODEBUG"), "gcstackbarrierall=1") { // Re-execute this test with constant GC and stack // barriers at every frame. @@ -594,6 +625,50 @@ func blockCond() { mu.Unlock() } +func TestMutexProfile(t *testing.T) { + old := runtime.SetMutexProfileFraction(1) + defer runtime.SetMutexProfileFraction(old) + if old != 0 { + t.Fatalf("need MutexProfileRate 0, got %d", old) + } + + blockMutex() + + var w bytes.Buffer + Lookup("mutex").WriteTo(&w, 1) + prof := w.String() + + if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") { + t.Errorf("Bad profile header:\n%v", prof) + } + prof = strings.Trim(prof, "\n") + lines := strings.Split(prof, "\n") + // gccgo adds an extra line in the stack trace, not sure why. + if len(lines) < 6 { + t.Errorf("expected 6 lines, got %d %q\n%s", len(lines), prof, prof) + } + if len(lines) < 6 { + return + } + // checking that the line is like "35258904 1 @ 0x48288d 0x47cd28 0x458931" + r2 := `^\d+ 1 @(?: 0x[[:xdigit:]]+)+` + //r2 := "^[0-9]+ 1 @ 0x[0-9a-f x]+$" + if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok { + t.Errorf("%q didn't match %q", lines[3], r2) + } + r3 := "^#.*pprof_test.\\$nested.*$" + match := false + for _, i := range []int{5, 6} { + if ok, _ := regexp.MatchString(r3, lines[i]); ok { + match = true + break + } + } + if !match { + t.Errorf("neither %q nor %q matched %q", lines[5], lines[6], r3) + } +} + func func1(c chan int) { <-c } func func2(c chan int) { <-c } func func3(c chan int) { <-c } @@ -621,13 +696,31 @@ func TestGoroutineCounts(t *testing.T) { time.Sleep(10 * time.Millisecond) // let goroutines block on channel var w bytes.Buffer - Lookup("goroutine").WriteTo(&w, 1) + goroutineProf := Lookup("goroutine") + + // Check debug profile + goroutineProf.WriteTo(&w, 1) prof := w.String() if !containsInOrder(prof, "\n50 @ ", "\n40 @", "\n10 @", "\n1 @") { t.Errorf("expected sorted goroutine counts:\n%s", prof) } + // Check proto profile + w.Reset() + goroutineProf.WriteTo(&w, 0) + p, err := profile.Parse(&w) + if err != nil { + t.Errorf("error parsing protobuf profile: %v", err) + } + if err := p.CheckValid(); err != nil { + t.Errorf("protobuf profile is invalid: %v", err) + } + if !containsCounts(p, []int64{50, 40, 10, 1}) { + t.Errorf("expected count profile to contain goroutines with counts %v, got %v", + []int64{50, 40, 10, 1}, p) + } + close(c) time.Sleep(10 * time.Millisecond) // let goroutines exit @@ -643,3 +736,23 @@ func containsInOrder(s string, all ...string) bool { } return true } + +func containsCounts(prof *profile.Profile, counts []int64) bool { + m := make(map[int64]int) + for _, c := range counts { + m[c]++ + } + for _, s := range prof.Sample { + // The count is the single value in the sample + if len(s.Value) != 1 { + return false + } + m[s.Value[0]]-- + } + for _, n := range m { + if n > 0 { + return false + } + } + return true +} |