profiler: fix duration in (fast)delta profiles (#1612)

Fixes a bug in the duration computation for fast delta where delta pprofs had a DurationNanos ~equal to the life of the process.

Note: this was a regression from a previously tested version of fastdelta. Unfortunately, there wasn't sufficient test coverage for this case. This pull addresses that too.

profiler/internal/fastdelta/fd.go

@@ -273,14 +273,14 @@ func (dc *DeltaComputer) pass4WriteAndPruneRecords() error {
 			case *pproflite.KeepFrames:
 				dc.includedStrings.Add(int(t.Value))
 			case *pproflite.TimeNanos:
-				curProfTimeNanos := int64(t.Value)
+				curProfTimeNanos := t.Value
 				if !firstPprof {
 					prevProfTimeNanos := dc.curProfTimeNanos
 					if err := dc.encoder.Encode(t); err != nil {
 						return err
 					}
 					dc.durationNanos.Value = curProfTimeNanos - prevProfTimeNanos
-					return dc.encoder.Encode(&dc.durationNanos)
+					f = &dc.durationNanos
 				}
 				dc.curProfTimeNanos = curProfTimeNanos
 			case *pproflite.DurationNanos:

profiler/internal/fastdelta/fd_test.go

@@ -343,6 +343,43 @@ func makeGolden(t testing.TB, before, after []byte, fields ...pprofutils.ValueTy
 	return c
 }
 
+func TestDurationAndTime(t *testing.T) {
+	// given
+	dc := NewDeltaComputer(
+		vt("alloc_objects", "count"),
+		vt("alloc_space", "bytes"),
+	)
+	heapBytes, err := os.ReadFile("testdata/big-heap.pprof")
+	require.NoError(t, err)
+	inputPprof, err := profile.ParseData(heapBytes)
+	require.NoError(t, err)
+
+	// The first expected duration is the same as the first pprof fed to dc.
+	// We need to invoke dc.Delta at least 3 times to exercise the duration logic.
+	var fixtures = []int64{inputPprof.DurationNanos, 0, 0, 0}
+	for i := 1; i < len(fixtures); i++ {
+		fixtures[i] = int64(i) * 10
+	}
+
+	inputBuf := new(bytes.Buffer)
+	outputBuf := new(bytes.Buffer)
+	for i := 1; i < len(fixtures); i++ {
+		inputBuf.Reset()
+		outputBuf.Reset()
+		require.NoError(t, inputPprof.WriteUncompressed(inputBuf))
+		err = dc.Delta(inputBuf.Bytes(), outputBuf)
+		deltaPprof, err := profile.ParseData(outputBuf.Bytes())
+		require.NoError(t, err)
+
+		expectedDuration := fixtures[i-1]
+		require.Equal(t, expectedDuration, deltaPprof.DurationNanos)
+		require.Equal(t, inputPprof.TimeNanos, deltaPprof.TimeNanos)
+
+		// advance the time
+		inputPprof.TimeNanos += fixtures[i]
+	}
+}
+
 func TestCompaction(t *testing.T) {
 	// given
 

profiler/profile.go

@@ -434,6 +434,12 @@ func (cdp *comparingDeltaProfiler) Delta(data []byte) (res []byte, err error) {
 		return res, nil
 	}
 
+	if pprofGolden.DurationNanos != pprofSut.DurationNanos {
+		log.Error("profiles differ: golden_dur=%d sut_dur=%d", pprofGolden.DurationNanos, pprofSut.DurationNanos)
+		cdp.reportError("compare_failed")
+		return res, nil
+	}
+
 	pprofDiff, err := PprofDiff(pprofSut, pprofGolden)
 	if err != nil {
 		cdp.reportError(err.Error())