log error message when negative samples appear in non-diff_base profiles

internal/driver/driver.go

@@ -114,7 +114,7 @@ func generateReport(p *profile.Profile, cmd []string, vars variables, o *plugin.
 
 	// Generate the report.
 	dst := new(bytes.Buffer)
-	if err := report.Generate(dst, rpt, o.Obj); err != nil {
+	if err := report.Generate(dst, rpt, o.Obj, o.UI); err != nil {
 		return err
 	}
 	src := dst

internal/driver/webui.go

@@ -398,7 +398,7 @@ func (ui *webInterface) peek(w http.ResponseWriter, req *http.Request) {
 	}
 
 	out := &bytes.Buffer{}
-	if err := report.Generate(out, rpt, ui.options.Obj); err != nil {
+	if err := report.Generate(out, rpt, ui.options.Obj, ui.options.UI); err != nil {
 		http.Error(w, err.Error(), http.StatusBadRequest)
 		ui.options.UI.PrintErr(err)
 		return

internal/report/report.go

@@ -82,7 +82,11 @@ type Options struct {
 }
 
 // Generate generates a report as directed by the Report.
-func Generate(w io.Writer, rpt *Report, obj plugin.ObjTool) error {
+func Generate(w io.Writer, rpt *Report, obj plugin.ObjTool, ui plugin.UI) error {
+	if rpt.unexpNegSamples {
+		ui.PrintErr("Negative sample values appeared in the profile.\nIf using the -base flag to compare profiles, consider using the -diff_base flag instead.")
+	}
+
 	o := rpt.options
 
 	switch o.OutputFormat {
@@ -1202,8 +1206,8 @@ func New(prof *profile.Profile, o *Options) *Report {
 		}
 		return measurement.ScaledLabel(v, o.SampleUnit, o.OutputUnit)
 	}
-	return &Report{prof, computeTotal(prof, o.SampleValue, o.SampleMeanDivisor),
-		o, format}
+	total, unexpNegSamples := computeTotal(prof, o.SampleValue, o.SampleMeanDivisor)
+	return &Report{prof, total, o, format, unexpNegSamples}
 }
 
 // NewDefault builds a new report indexing the last sample value
@@ -1225,15 +1229,19 @@ func NewDefault(prof *profile.Profile, options Options) *Report {
 // computeTotal computes the sum of the absolute value of all sample values.
 // If any samples have label indicating they belong to the diff base, then the
 // total will only include samples with that label.
-func computeTotal(prof *profile.Profile, value, meanDiv func(v []int64) int64) int64 {
+// Returns the profile total, and a boolean which is true if the profile was not
+// a diff base profile, but did have negative samples.
+func computeTotal(prof *profile.Profile, value, meanDiv func(v []int64) int64) (int64, bool) {
 	var div, total, diffDiv, diffTotal int64
+	var negSamples bool
 	for _, sample := range prof.Sample {
 		var d, v int64
 		v = value(sample.Value)
 		if meanDiv != nil {
 			d = meanDiv(sample.Value)
 		}
 		if v < 0 {
+			negSamples = true
 			v = -v
 		}
 		total += v
@@ -1246,20 +1254,23 @@ func computeTotal(prof *profile.Profile, value, meanDiv func(v []int64) int64) i
 	if diffTotal > 0 {
 		total = diffTotal
 		div = diffDiv
+		// negative samples are expected in diff base profiles.
+		negSamples = false
 	}
 	if div != 0 {
-		return total / div
+		return total / div, negSamples
 	}
-	return total
+	return total, negSamples
 }
 
 // Report contains the data and associated routines to extract a
 // report from a profile.
 type Report struct {
-	prof        *profile.Profile
-	total       int64
-	options     *Options
-	formatValue func(int64) string
+	prof            *profile.Profile
+	total           int64
+	options         *Options
+	formatValue     func(int64) string
+	unexpNegSamples bool
 }
 
 // Total returns the total number of samples in a report.

internal/report/report_test.go

@@ -28,8 +28,9 @@ import (
 )
 
 type testcase struct {
-	rpt  *Report
-	want string
+	rpt              *Report
+	want             string
+	wantNegSampleErr bool
 }
 
 func TestSource(t *testing.T) {
@@ -42,39 +43,63 @@ func TestSource(t *testing.T) {
 	for _, tc := range []testcase{
 		{
 			rpt: New(
-				testProfile.Copy(),
+				testProfile1.Copy(),
 				&Options{
 					OutputFormat: List,
 					Symbol:       regexp.MustCompile(`.`),
 					TrimPath:     "/some/path",
 
 					SampleValue: sampleValue1,
-					SampleUnit:  testProfile.SampleType[1].Unit,
+					SampleUnit:  testProfile1.SampleType[1].Unit,
 				},
 			),
 			want: path + "source.rpt",
 		},
 		{
 			rpt: New(
-				testProfile.Copy(),
+				testProfile1.Copy(),
 				&Options{
 					OutputFormat: Dot,
 					CallTree:     true,
 					Symbol:       regexp.MustCompile(`.`),
 					TrimPath:     "/some/path",
 
 					SampleValue: sampleValue1,
-					SampleUnit:  testProfile.SampleType[1].Unit,
+					SampleUnit:  testProfile1.SampleType[1].Unit,
 				},
 			),
 			want: path + "source.dot",
 		},
+		{
+			rpt: New(
+				testProfile2.Copy(),
+				&Options{
+					OutputFormat: Dot,
+					CallTree:     true,
+					Symbol:       regexp.MustCompile(`.`),
+					TrimPath:     "/some/path",
+
+					SampleValue: sampleValue1,
+					SampleUnit:  testProfile2.SampleType[1].Unit,
+				},
+			),
+			wantNegSampleErr: true,
+			want:             path + "source_neg_samples.dot",
+		},
 	} {
 		var b bytes.Buffer
-		if err := Generate(&b, tc.rpt, &binutils.Binutils{}); err != nil {
+		ui := &proftest.TestUI{T: t}
+		if tc.wantNegSampleErr {
+			ui.AllowRx = "Negative sample values appeared in the profile.\nIf using the -base flag to compare profiles, consider using the -diff_base flag instead."
+		}
+		if err := Generate(&b, tc.rpt, &binutils.Binutils{}, ui); err != nil {
 			t.Fatalf("%s: %v", tc.want, err)
 		}
 
+		if tc.wantNegSampleErr && ui.NumAllowRxMatches != 1 {
+			t.Errorf("want %q logged to UI once, got this message logged %d time(s)", ui.AllowRx, ui.NumAllowRxMatches)
+		}
+
 		gold, err := ioutil.ReadFile(tc.want)
 		if err != nil {
 			t.Fatalf("%s: %v", tc.want, err)
@@ -178,7 +203,7 @@ var testL = []*profile.Location{
 	},
 }
 
-var testProfile = &profile.Profile{
+var testProfile1 = &profile.Profile{
 	PeriodType:    &profile.ValueType{Type: "cpu", Unit: "millisecond"},
 	Period:        10,
 	DurationNanos: 10e9,
@@ -213,6 +238,41 @@ var testProfile = &profile.Profile{
 	Mapping:  testM,
 }
 
+var testProfile2 = &profile.Profile{
+	PeriodType:    &profile.ValueType{Type: "cpu", Unit: "millisecond"},
+	Period:        10,
+	DurationNanos: 10e9,
+	SampleType: []*profile.ValueType{
+		{Type: "samples", Unit: "count"},
+		{Type: "cpu", Unit: "cycles"},
+	},
+	Sample: []*profile.Sample{
+		{
+			Location: []*profile.Location{testL[0]},
+			Value:    []int64{1, 1},
+		},
+		{
+			Location: []*profile.Location{testL[2], testL[1], testL[0]},
+			Value:    []int64{1, 10},
+		},
+		{
+			Location: []*profile.Location{testL[4], testL[2], testL[0]},
+			Value:    []int64{1, -100},
+		},
+		{
+			Location: []*profile.Location{testL[3], testL[0]},
+			Value:    []int64{1, 1000},
+		},
+		{
+			Location: []*profile.Location{testL[4], testL[3], testL[0]},
+			Value:    []int64{1, 10000},
+		},
+	},
+	Location: testL,
+	Function: testF,
+	Mapping:  testM,
+}
+
 func TestDisambiguation(t *testing.T) {
 	parent1 := &graph.Node{Info: graph.NodeInfo{Name: "parent1"}}
 	parent2 := &graph.Node{Info: graph.NodeInfo{Name: "parent2"}}
@@ -296,7 +356,7 @@ func TestLegendActiveFilters(t *testing.T) {
 }
 
 func TestComputeTotal(t *testing.T) {
-	p1 := testProfile.Copy()
+	p1 := testProfile1.Copy()
 	p1.Sample = []*profile.Sample{
 		{
 			Location: []*profile.Location{testL[0]},
@@ -312,7 +372,7 @@ func TestComputeTotal(t *testing.T) {
 		},
 	}
 
-	p2 := testProfile.Copy()
+	p2 := testProfile1.Copy()
 	p2.Sample = []*profile.Sample{
 		{
 			Location: []*profile.Location{testL[0]},
@@ -328,7 +388,7 @@ func TestComputeTotal(t *testing.T) {
 		},
 	}
 
-	p3 := testProfile.Copy()
+	p3 := testProfile1.Copy()
 	p3.Sample = []*profile.Sample{
 		{
 			Location: []*profile.Location{testL[0]},
@@ -365,10 +425,11 @@ func TestComputeTotal(t *testing.T) {
 	}
 
 	testcases := []struct {
-		desc           string
-		prof           *profile.Profile
-		value, meanDiv func(v []int64) int64
-		wantTotal      int64
+		desc                string
+		prof                *profile.Profile
+		value, meanDiv      func(v []int64) int64
+		wantTotal           int64
+		wantUnexpNegSamples bool
 	}{
 		{
 			desc: "no diff base, all positive values, index 1",
@@ -392,7 +453,8 @@ func TestComputeTotal(t *testing.T) {
 			value: func(v []int64) int64 {
 				return v[1]
 			},
-			wantTotal: 111,
+			wantTotal:           111,
+			wantUnexpNegSamples: true,
 		},
 		{
 			desc: "diff base, some negative values",
@@ -406,9 +468,13 @@ func TestComputeTotal(t *testing.T) {
 
 	for _, tc := range testcases {
 		t.Run(tc.desc, func(t *testing.T) {
-			if gotTotal := computeTotal(tc.prof, tc.value, tc.meanDiv); gotTotal != tc.wantTotal {
+			gotTotal, gotUnexpNegSamples := computeTotal(tc.prof, tc.value, tc.meanDiv)
+			if gotTotal != tc.wantTotal {
 				t.Errorf("got total %d, want %v", gotTotal, tc.wantTotal)
 			}
+			if gotUnexpNegSamples != tc.wantUnexpNegSamples {
+				t.Errorf("got  unexpected negative samples %v, want %v", gotUnexpNegSamples, tc.wantUnexpNegSamples)
+			}
 		})
 	}
 }

internal/report/source_test.go

@@ -11,6 +11,7 @@ import (
 	"testing"
 
 	"github.com/google/pprof/internal/binutils"
+	"github.com/google/pprof/internal/proftest"
 	"github.com/google/pprof/profile"
 )
 
@@ -27,7 +28,7 @@ func TestWebList(t *testing.T) {
 		SampleUnit:   cpu.SampleType[1].Unit,
 	})
 	var buf bytes.Buffer
-	if err := Generate(&buf, rpt, &binutils.Binutils{}); err != nil {
+	if err := Generate(&buf, rpt, &binutils.Binutils{}, &proftest.TestUI{T: t}); err != nil {
 		t.Fatalf("could not generate weblist: %v", err)
 	}
 	output := buf.String()

internal/report/testdata/source_neg_samples.dot

@@ -0,0 +1,17 @@
+digraph "unnamed" {
+node [style=filled fillcolor="#f8f8f8"]
+subgraph cluster_L { "Duration: 10s, Total samples = 11111 " [shape=box fontsize=16 label="Duration: 10s, Total samples = 11111 \lShowing nodes accounting for 10911, 98.20% of 11111 total\l"] }
+N1 [label="tee\nsource2:8\n10000 (90.00%)" id="node1" fontsize=24 shape=box tooltip="tee testdata/source2:8 (10000)" color="#b20500" fillcolor="#edd6d5"]
+N2 [label="main\nsource1:2\n1 (0.009%)\nof 10911 (98.20%)" id="node2" fontsize=9 shape=box tooltip="main testdata/source1:2 (10911)" color="#b20000" fillcolor="#edd5d5"]
+N3 [label="tee\nsource2:2\n1000 (9.00%)\nof 11000 (99.00%)" id="node3" fontsize=14 shape=box tooltip="tee testdata/source2:2 (11000)" color="#b20000" fillcolor="#edd5d5"]
+N4 [label="tee\nsource2:8\n-100 (0.9%)" id="node4" fontsize=10 shape=box tooltip="tee testdata/source2:8 (-100)" color="#b0b2aa" fillcolor="#ecedec"]
+N5 [label="bar\nsource1:10\n10 (0.09%)" id="node5" fontsize=9 shape=box tooltip="bar testdata/source1:10 (10)" color="#b2b2b1" fillcolor="#ededed"]
+N6 [label="bar\nsource1:10\n0 of -100 (0.9%)" id="node6" fontsize=8 shape=box tooltip="bar testdata/source1:10 (-100)" color="#b0b2aa" fillcolor="#ecedec"]
+N7 [label="foo\nsource1:4\n0 of 10 (0.09%)" id="node7" fontsize=8 shape=box tooltip="foo testdata/source1:4 (10)" color="#b2b2b1" fillcolor="#ededed"]
+N2 -> N3 [label=" 11000" weight=100 penwidth=5 color="#b20000" tooltip="main testdata/source1:2 -> tee testdata/source2:2 (11000)" labeltooltip="main testdata/source1:2 -> tee testdata/source2:2 (11000)"]
+N3 -> N1 [label=" 10000" weight=91 penwidth=5 color="#b20500" tooltip="tee testdata/source2:2 -> tee testdata/source2:8 (10000)" labeltooltip="tee testdata/source2:2 -> tee testdata/source2:8 (10000)"]
+N6 -> N4 [label=" -100" color="#b0b2aa" tooltip="bar testdata/source1:10 -> tee testdata/source2:8 (-100)" labeltooltip="bar testdata/source1:10 -> tee testdata/source2:8 (-100)"]
+N2 -> N6 [label=" -100" color="#b0b2aa" tooltip="main testdata/source1:2 -> bar testdata/source1:10 (-100)" labeltooltip="main testdata/source1:2 -> bar testdata/source1:10 (-100)"]
+N7 -> N5 [label=" 10" color="#b2b2b1" tooltip="foo testdata/source1:4 -> bar testdata/source1:10 (10)" labeltooltip="foo testdata/source1:4 -> bar testdata/source1:10 (10)"]
+N2 -> N7 [label=" 10" color="#b2b2b1" tooltip="main testdata/source1:2 -> foo testdata/source1:4 (10)" labeltooltip="main testdata/source1:2 -> foo testdata/source1:4 (10)"]
+}