pprof/profile/profile_test.go

// Copyright 2014 Google Inc. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package profile

import (
	"bytes"
	"fmt"
	"io/ioutil"
	"path/filepath"
	"reflect"
	"regexp"
	"testing"

	"github.com/google/pprof/internal/proftest"
)

func TestParse(t *testing.T) {
	const path = "testdata/"

	for _, source := range []string{
		"go.crc32.cpu",
		"go.godoc.thread",
		"gobench.cpu",
		"gobench.heap",
		"cppbench.cpu",
		"cppbench.heap",
		"cppbench.contention",
		"cppbench.growth",
		"cppbench.thread",
		"cppbench.thread.all",
		"cppbench.thread.none",
		"java.cpu",
		"java.heap",
		"java.contention",
	} {
		inbytes, err := ioutil.ReadFile(filepath.Join(path, source))
		if err != nil {
			t.Fatal(err)
		}
		p, err := Parse(bytes.NewBuffer(inbytes))
		if err != nil {
			t.Fatalf("%s: %s", source, err)
		}

		js := p.String()
		goldFilename := path + source + ".string"
		gold, err := ioutil.ReadFile(goldFilename)
		if err != nil {
			t.Fatalf("%s: %v", source, err)
		}

		if js != string(gold) {
			t.Errorf("diff %s %s", source, goldFilename)
			d, err := proftest.Diff(gold, []byte(js))
			if err != nil {
				t.Fatalf("%s: %v", source, err)
			}
			t.Error(source + "\n" + string(d) + "\n" + "new profile at:\n" + leaveTempfile([]byte(js)))
		}

		// Reencode and decode.
		bw := bytes.NewBuffer(nil)
		if err := p.Write(bw); err != nil {
			t.Fatalf("%s: %v", source, err)
		}
		if p, err = Parse(bw); err != nil {
			t.Fatalf("%s: %v", source, err)
		}
		js2 := p.String()
		if js2 != string(gold) {
			d, err := proftest.Diff(gold, []byte(js2))
			if err != nil {
				t.Fatalf("%s: %v", source, err)
			}
			t.Error(source + "\n" + string(d) + "\n" + "gold:\n" + goldFilename +
				"\nnew profile at:\n" + leaveTempfile([]byte(js)))
		}
	}
}

// leaveTempfile leaves |b| in a temporary file on disk and returns the
// temp filename.  This is useful to recover a profile when the test
// fails.
func leaveTempfile(b []byte) string {
	f1, err := ioutil.TempFile("", "profile_test")
	if err != nil {
		panic(err)
	}
	if _, err := f1.Write(b); err != nil {
		panic(err)
	}
	return f1.Name()
}

const mainBinary = "/bin/main"

var cpuM = []*Mapping{
	{
		ID:              1,
		Start:           0x10000,
		Limit:           0x40000,
		File:            mainBinary,
		HasFunctions:    true,
		HasFilenames:    true,
		HasLineNumbers:  true,
		HasInlineFrames: true,
	},
	{
		ID:              2,
		Start:           0x1000,
		Limit:           0x4000,
		File:            "/lib/lib.so",
		HasFunctions:    true,
		HasFilenames:    true,
		HasLineNumbers:  true,
		HasInlineFrames: true,
	},
	{
		ID:              3,
		Start:           0x4000,
		Limit:           0x5000,
		File:            "/lib/lib2_c.so.6",
		HasFunctions:    true,
		HasFilenames:    true,
		HasLineNumbers:  true,
		HasInlineFrames: true,
	},
	{
		ID:              4,
		Start:           0x5000,
		Limit:           0x9000,
		File:            "/lib/lib.so_6 (deleted)",
		HasFunctions:    true,
		HasFilenames:    true,
		HasLineNumbers:  true,
		HasInlineFrames: true,
	},
}

var cpuF = []*Function{
	{ID: 1, Name: "main", SystemName: "main", Filename: "main.c"},
	{ID: 2, Name: "foo", SystemName: "foo", Filename: "foo.c"},
	{ID: 3, Name: "foo_caller", SystemName: "foo_caller", Filename: "foo.c"},
}

var cpuL = []*Location{
	{
		ID:      1000,
		Mapping: cpuM[1],
		Address: 0x1000,
		Line: []Line{
			{Function: cpuF[0], Line: 1},
		},
	},
	{
		ID:      2000,
		Mapping: cpuM[0],
		Address: 0x2000,
		Line: []Line{
			{Function: cpuF[1], Line: 2},
			{Function: cpuF[2], Line: 1},
		},
	},
	{
		ID:      3000,
		Mapping: cpuM[0],
		Address: 0x3000,
		Line: []Line{
			{Function: cpuF[1], Line: 2},
			{Function: cpuF[2], Line: 1},
		},
	},
	{
		ID:      3001,
		Mapping: cpuM[0],
		Address: 0x3001,
		Line: []Line{
			{Function: cpuF[2], Line: 2},
		},
	},
	{
		ID:      3002,
		Mapping: cpuM[0],
		Address: 0x3002,
		Line: []Line{
			{Function: cpuF[2], Line: 3},
		},
	},
}

var testProfile = &Profile{
	PeriodType:    &ValueType{Type: "cpu", Unit: "milliseconds"},
	Period:        1,
	DurationNanos: 10e9,
	SampleType: []*ValueType{
		{Type: "samples", Unit: "count"},
		{Type: "cpu", Unit: "milliseconds"},
	},
	Sample: []*Sample{
		{
			Location: []*Location{cpuL[0]},
			Value:    []int64{1000, 1000},
			Label: map[string][]string{
				"key1": []string{"tag1"},
				"key2": []string{"tag1"},
			},
		},
		{
			Location: []*Location{cpuL[1], cpuL[0]},
			Value:    []int64{100, 100},
			Label: map[string][]string{
				"key1": []string{"tag2"},
				"key3": []string{"tag2"},
			},
		},
		{
			Location: []*Location{cpuL[2], cpuL[0]},
			Value:    []int64{10, 10},
			Label: map[string][]string{
				"key1": []string{"tag3"},
				"key2": []string{"tag2"},
			},
		},
		{
			Location: []*Location{cpuL[3], cpuL[0]},
			Value:    []int64{10000, 10000},
			Label: map[string][]string{
				"key1": []string{"tag4"},
				"key2": []string{"tag1"},
			},
		},
		{
			Location: []*Location{cpuL[4], cpuL[0]},
			Value:    []int64{1, 1},
			Label: map[string][]string{
				"key1": []string{"tag4"},
				"key2": []string{"tag1"},
			},
		},
	},
	Location: cpuL,
	Function: cpuF,
	Mapping:  cpuM,
}

var aggTests = map[string]aggTest{
	"precise":         aggTest{true, true, true, true, 5},
	"fileline":        aggTest{false, true, true, true, 4},
	"inline_function": aggTest{false, true, false, true, 3},
	"function":        aggTest{false, true, false, false, 2},
}

type aggTest struct {
	precise, function, fileline, inlineFrame bool
	rows                                     int
}

const totalSamples = int64(11111)

func TestAggregation(t *testing.T) {
	prof := testProfile.Copy()
	for _, resolution := range []string{"precise", "fileline", "inline_function", "function"} {
		a := aggTests[resolution]
		if !a.precise {
			if err := prof.Aggregate(a.inlineFrame, a.function, a.fileline, a.fileline, false); err != nil {
				t.Error("aggregating to " + resolution + ":" + err.Error())
			}
		}
		if err := checkAggregation(prof, &a); err != nil {
			t.Error("failed aggregation to " + resolution + ": " + err.Error())
		}
	}
}

// checkAggregation verifies that the profile remained consistent
// with its aggregation.
func checkAggregation(prof *Profile, a *aggTest) error {
	// Check that the total number of samples for the rows was preserved.
	total := int64(0)

	samples := make(map[string]bool)
	for _, sample := range prof.Sample {
		tb := locationHash(sample)
		samples[tb] = true
		total += sample.Value[0]
	}

	if total != totalSamples {
		return fmt.Errorf("sample total %d, want %d", total, totalSamples)
	}

	// Check the number of unique sample locations
	if a.rows != len(samples) {
		return fmt.Errorf("number of samples %d, want %d", len(samples), a.rows)
	}

	// Check that all mappings have the right detail flags.
	for _, m := range prof.Mapping {
		if m.HasFunctions != a.function {
			return fmt.Errorf("unexpected mapping.HasFunctions %v, want %v", m.HasFunctions, a.function)
		}
		if m.HasFilenames != a.fileline {
			return fmt.Errorf("unexpected mapping.HasFilenames %v, want %v", m.HasFilenames, a.fileline)
		}
		if m.HasLineNumbers != a.fileline {
			return fmt.Errorf("unexpected mapping.HasLineNumbers %v, want %v", m.HasLineNumbers, a.fileline)
		}
		if m.HasInlineFrames != a.inlineFrame {
			return fmt.Errorf("unexpected mapping.HasInlineFrames %v, want %v", m.HasInlineFrames, a.inlineFrame)
		}
	}

	// Check that aggregation has removed finer resolution data.
	for _, l := range prof.Location {
		if !a.inlineFrame && len(l.Line) > 1 {
			return fmt.Errorf("found %d lines on location %d, want 1", len(l.Line), l.ID)
		}

		for _, ln := range l.Line {
			if !a.fileline && (ln.Function.Filename != "" || ln.Line != 0) {
				return fmt.Errorf("found line %s:%d on location %d, want :0",
					ln.Function.Filename, ln.Line, l.ID)
			}
			if !a.function && (ln.Function.Name != "") {
				return fmt.Errorf(`found file %s location %d, want ""`,
					ln.Function.Name, l.ID)
			}
		}
	}

	return nil
}

func TestParseMappingEntry(t *testing.T) {
	for _, test := range []*struct {
		entry string
		want  *Mapping
	}{
		{
			entry: "00400000-02e00000 r-xp 00000000 00:00 0",
			want: &Mapping{
				Start: 0x400000,
				Limit: 0x2e00000,
			},
		},
		{
			entry: "02e00000-02e8a000 r-xp 02a00000 00:00 15953927    /foo/bin",
			want: &Mapping{
				Start:  0x2e00000,
				Limit:  0x2e8a000,
				Offset: 0x2a00000,
				File:   "/foo/bin",
			},
		},
		{
			entry: "02e00000-02e8a000 r-xp 000000 00:00 15953927    [vdso]",
			want: &Mapping{
				Start: 0x2e00000,
				Limit: 0x2e8a000,
				File:  "[vdso]",
			},
		},
		{
			entry: "  02e00000-02e8a000: /foo/bin (@2a00000)",
			want: &Mapping{
				Start:  0x2e00000,
				Limit:  0x2e8a000,
				Offset: 0x2a00000,
				File:   "/foo/bin",
			},
		},
		{
			entry: "  02e00000-02e8a000: /foo/bin",
			want: &Mapping{
				Start: 0x2e00000,
				Limit: 0x2e8a000,
				File:  "/foo/bin",
			},
		},
		{
			entry: "  02e00000-02e8a000: [vdso]",
			want: &Mapping{
				Start: 0x2e00000,
				Limit: 0x2e8a000,
				File:  "[vdso]",
			},
		},
	} {
		got, err := parseMappingEntry(test.entry)
		if err != nil {
			t.Error(err)
		}
		if !reflect.DeepEqual(test.want, got) {
			t.Errorf("%s want=%v got=%v", test.entry, test.want, got)
		}
	}
}

// Test merge leaves the main binary in place.
func TestMergeMain(t *testing.T) {
	prof := testProfile.Copy()
	p1, err := Merge([]*Profile{prof})
	if err != nil {
		t.Fatalf("merge error: %v", err)
	}
	if cpuM[0].File != p1.Mapping[0].File {
		t.Errorf("want Mapping[0]=%s got %s", cpuM[0].File, p1.Mapping[0].File)
	}
}

func TestMerge(t *testing.T) {
	// Aggregate a profile with itself and once again with a factor of
	// -2. Should end up with an empty profile (all samples for a
	// location should add up to 0).

	prof := testProfile.Copy()
	p1, err := Merge([]*Profile{prof, prof})
	if err != nil {
		t.Errorf("merge error: %v", err)
	}
	prof.Scale(-2)
	prof, err = Merge([]*Profile{p1, prof})
	if err != nil {
		t.Errorf("merge error: %v", err)
	}

	// Use aggregation to merge locations at function granularity.
	if err := prof.Aggregate(false, true, false, false, false); err != nil {
		t.Errorf("aggregating after merge: %v", err)
	}

	samples := make(map[string]int64)
	for _, s := range prof.Sample {
		tb := locationHash(s)
		samples[tb] = samples[tb] + s.Value[0]
	}
	for s, v := range samples {
		if v != 0 {
			t.Errorf("nonzero value for sample %s: %d", s, v)
		}
	}
}

func TestMergeAll(t *testing.T) {
	// Aggregate 10 copies of the profile.
	profs := make([]*Profile, 10)
	for i := 0; i < 10; i++ {
		profs[i] = testProfile.Copy()
	}
	prof, err := Merge(profs)
	if err != nil {
		t.Errorf("merge error: %v", err)
	}
	samples := make(map[string]int64)
	for _, s := range prof.Sample {
		tb := locationHash(s)
		samples[tb] = samples[tb] + s.Value[0]
	}
	for _, s := range testProfile.Sample {
		tb := locationHash(s)
		if samples[tb] != s.Value[0]*10 {
			t.Errorf("merge got wrong value at %s : %d instead of %d", tb, samples[tb], s.Value[0]*10)
		}
	}
}

func TestFilter(t *testing.T) {
	// Perform several forms of filtering on the test profile.

	type filterTestcase struct {
		focus, ignore, hide, show *regexp.Regexp
		fm, im, hm, hnm           bool
	}

	for tx, tc := range []filterTestcase{
		{nil, nil, nil, nil, true, false, false, false},
		{regexp.MustCompile("notfound"), nil, nil, nil, false, false, false, false},
		{nil, regexp.MustCompile("foo.c"), nil, nil, true, true, false, false},
		{nil, nil, regexp.MustCompile("lib.so"), nil, true, false, true, false},
	} {
		prof := *testProfile.Copy()
		gf, gi, gh, gnh := prof.FilterSamplesByName(tc.focus, tc.ignore, tc.hide, tc.show)
		if gf != tc.fm {
			t.Errorf("Filter #%d, got fm=%v, want %v", tx, gf, tc.fm)
		}
		if gi != tc.im {
			t.Errorf("Filter #%d, got im=%v, want %v", tx, gi, tc.im)
		}
		if gh != tc.hm {
			t.Errorf("Filter #%d, got hm=%v, want %v", tx, gh, tc.hm)
		}
		if gnh != tc.hnm {
			t.Errorf("Filter #%d, got hnm=%v, want %v", tx, gnh, tc.hnm)
		}
	}
}

// locationHash constructs a string to use as a hashkey for a sample, based on its locations
func locationHash(s *Sample) string {
	var tb string
	for _, l := range s.Location {
		for _, ln := range l.Line {
			tb = tb + fmt.Sprintf("%s:%d@%d ", ln.Function.Name, ln.Line, l.Address)
		}
	}
	return tb
}

func TestSetMain(t *testing.T) {
	testProfile.massageMappings()
	if testProfile.Mapping[0].File != mainBinary {
		t.Errorf("got %s for main", testProfile.Mapping[0].File)
	}
}

// Benchmarks

// benchmarkMerge measures the overhead of merging profiles read from files.
// They must be the same type of profiles.
func benchmarkMerge(b *testing.B, files []string) {
	const path = "testdata/"

	p := make([]*Profile, len(files))

	for i, source := range files {
		inBytes, err := ioutil.ReadFile(filepath.Join(path, source))
		if err != nil {
			b.Fatal(err)
		}
		if p[i], err = Parse(bytes.NewBuffer(inBytes)); err != nil {
			b.Fatalf("%s: %s", source, err)
		}
	}

	var prof *Profile
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		prof, _ = Merge(p)
	}
	b.StopTimer()

	before := 0
	for _, p := range p {
		p.preEncode()
		buff := marshal(p)
		before += len(buff)
	}
	prof.preEncode()
	buff := marshal(prof)
	after := len(buff)
	b.Logf("Profile size before merge = %v, After merge = %v", before, after)
}

// BenchmarkMergeCppCPUMedium measures the overhead of merging two medium CPU
// profiles of a C++ program (muppet).
func BenchmarkMergeCppCPUMedium(b *testing.B) {
	files := []string{
		"muppet.profilez.medium.1.pb.gz",
		"muppet.profilez.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeCppHeapMedium measures the overhead of merging two medium Heap
// profiles of a C++ program (muppet).
func BenchmarkMergeCppHeapMedium(b *testing.B) {
	files := []string{
		"muppet.heapz.medium.1.pb.gz",
		"muppet.heapz.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeCppContentionMedium measures the overhead of merging two medium
// contention profiles of a C++ program (muppet).
func BenchmarkMergeCppContentionMedium(b *testing.B) {
	files := []string{
		"muppet.contentionz.medium.1.pb.gz",
		"muppet.contentionz.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaCPUMedium measures the overhead of merging two medium CPU
// profiles of a Java program (caribou).
func BenchmarkMergeJavaCPUMedium(b *testing.B) {
	files := []string{
		"caribou.profilez.medium.1.pb.gz",
		"caribou.profilez.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaHeapMedium measures the overhead of merging two medium Heap
// profiles of a Java program (caribou).
func BenchmarkMergeJavaHeapMedium(b *testing.B) {
	files := []string{
		"caribou.heapz.medium.1.pb.gz",
		"caribou.heapz.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaContentionMedium measures the overhead of merging two medium
// contention profiles of a Java program (caribou).
func BenchmarkMergeJavaContentionMedium(b *testing.B) {
	files := []string{
		"caribou.contentionz.medium.1.pb.gz",
		"caribou.contentionz.medium.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeCppCPULarge measures the overhead of merging two large CPU
// profiles of a C++ program (muppet).
func BenchmarkMergeCppCPULarge(b *testing.B) {
	files := []string{
		"muppet.profilez.large.1.pb.gz",
		"muppet.profilez.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeCppHeapLarge measures the overhead of merging two large Heap
// profiles of a C++ program (muppet).
func BenchmarkMergeCppHeapLarge(b *testing.B) {
	files := []string{
		"muppet.heapz.large.1.pb.gz",
		"muppet.heapz.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeCppContentionLarge measures the overhead of merging two large
// contention profiles of a C++ program (muppet).
func BenchmarkMergeCppContentionLarge(b *testing.B) {
	files := []string{
		"muppet.contentionz.large.1.pb.gz",
		"muppet.contentionz.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaCPULarge measures the overhead of merging two large CPU
// profiles of a Java program (caribou).
func BenchmarkMergeJavaCPULarge(b *testing.B) {
	files := []string{
		"caribou.profilez.large.1.pb.gz",
		"caribou.profilez.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaHeapLarge measures the overhead of merging two large Heap
// profiles of a Java program (caribou).
func BenchmarkMergeJavaHeapLarge(b *testing.B) {
	files := []string{
		"caribou.heapz.large.1.pb.gz",
		"caribou.heapz.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaContentionLarge measures the overhead of merging two large
// contention profiles of a Java program (caribou).
func BenchmarkMergeJavaContentionLarge(b *testing.B) {
	files := []string{
		"caribou.contentionz.large.1.pb.gz",
		"caribou.contentionz.large.2.pb.gz",
	}

	benchmarkMerge(b, files)
}

// BenchmarkMergeJavaCPUWorst measures the overhead of merging rollups worth 7 days
// for the worst case scenario. These rollups are generated by merging samples
// (10 seconds/min) from /profilez handler of caribou prod jobs. They are deduplicated
// so that Samples, Locations, Mappings, and Functions are unique.
func BenchmarkMergeJavaCPUWorst(b *testing.B) {
	files := []string{
		"caribou.profilez.1min.1.pb.gz",
		"caribou.profilez.1min.2.pb.gz",
		"caribou.profilez.1min.3.pb.gz",
		"caribou.profilez.1min.4.pb.gz",
		"caribou.profilez.1min.5.pb.gz",
		"caribou.profilez.1min.6.pb.gz",
		"caribou.profilez.1min.7.pb.gz",
		"caribou.profilez.1min.8.pb.gz",
		"caribou.profilez.1min.9.pb.gz",
		"caribou.profilez.1min.10.pb.gz",
		"caribou.profilez.1min.11.pb.gz",
		"caribou.profilez.1min.12.pb.gz",
		"caribou.profilez.1min.13.pb.gz",
		"caribou.profilez.1min.14.pb.gz",
		"caribou.profilez.1min.15.pb.gz",
		"caribou.profilez.1min.16.pb.gz",
		"caribou.profilez.1min.17.pb.gz",
		"caribou.profilez.1min.18.pb.gz",
		"caribou.profilez.10mins.1.pb.gz",
		"caribou.profilez.10mins.2.pb.gz",
		"caribou.profilez.10mins.3.pb.gz",
		"caribou.profilez.10mins.4.pb.gz",
		"caribou.profilez.10mins.5.pb.gz",
		"caribou.profilez.10mins.6.pb.gz",
		"caribou.profilez.10mins.7.pb.gz",
		"caribou.profilez.10mins.8.pb.gz",
		"caribou.profilez.10mins.9.pb.gz",
		"caribou.profilez.10mins.10.pb.gz",
		"caribou.profilez.1hour.1.pb.gz",
		"caribou.profilez.1hour.2.pb.gz",
		"caribou.profilez.1hour.3.pb.gz",
		"caribou.profilez.1hour.4.pb.gz",
		"caribou.profilez.1hour.5.pb.gz",
		"caribou.profilez.1hour.6.pb.gz",
		"caribou.profilez.4hours.1.pb.gz",
		"caribou.profilez.4hours.2.pb.gz",
		"caribou.profilez.4hours.3.pb.gz",
		"caribou.profilez.4hours.4.pb.gz",
		"caribou.profilez.12hours.1.pb.gz",
		"caribou.profilez.12hours.2.pb.gz",
		"caribou.profilez.1day.1.pb.gz",
		"caribou.profilez.1day.2.pb.gz",
		"caribou.profilez.1day.3.pb.gz",
		"caribou.profilez.1day.4.pb.gz",
		"caribou.profilez.1day.5.pb.gz",
	}

	benchmarkMerge(b, files)
}