Sentry: Measure the time it takes to initialize the Sentry.

PiperOrigin-RevId: 383472507

1 files changed, 145 insertions, 0 deletions

diff --git a/pkg/metric/metric_test.go b/pkg/metric/metric_test.go
index 1b4a9e73a..0654bdf07 100644
--- a/pkg/metric/metric_test.go
+++ b/pkg/metric/metric_test.go
@@ -16,6 +16,7 @@ package metric
 
 import (
 	"testing"
+	"time"
 
 	"google.golang.org/protobuf/proto"
 	"gvisor.dev/gvisor/pkg/eventchannel"
@@ -352,3 +353,147 @@ func TestEmitMetricUpdateWithFields(t *testing.T) {
 		t.Errorf("Field value weird2 not found: %+v", emitter)
 	}
 }
+
+func TestMetricUpdateStageTiming(t *testing.T) {
+	defer reset()
+
+	expectedTimings := map[InitStage]struct{ min, max time.Duration }{}
+	measureStage := func(stage InitStage, body func()) {
+		stageStarted := time.Now()
+		endStage := StartStage(stage)
+		bodyStarted := time.Now()
+		body()
+		bodyEnded := time.Now()
+		endStage()
+		stageEnded := time.Now()
+
+		expectedTimings[stage] = struct{ min, max time.Duration }{
+			min: bodyEnded.Sub(bodyStarted),
+			max: stageEnded.Sub(stageStarted),
+		}
+	}
+	checkStage := func(got *pb.StageTiming, want InitStage) {
+		if InitStage(got.GetStage()) != want {
+			t.Errorf("%v: got stage %q expected %q", got, got.GetStage(), want)
+		}
+		timingBounds, found := expectedTimings[want]
+		if !found {
+			t.Fatalf("invalid init stage name %q", want)
+		}
+		started := got.Started.AsTime()
+		ended := got.Ended.AsTime()
+		duration := ended.Sub(started)
+		if duration < timingBounds.min {
+			t.Errorf("stage %v: lasted %v, expected at least %v", want, duration, timingBounds.min)
+		} else if duration > timingBounds.max {
+			t.Errorf("stage %v: lasted %v, expected no more than %v", want, duration, timingBounds.max)
+		}
+	}
+
+	// Test that it's legit to go through stages before metric registration.
+	measureStage("before_first_update_1", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+	measureStage("before_first_update_2", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+
+	fooMetric, err := NewUint64Metric("/foo", false, pb.MetricMetadata_UNITS_NONE, fooDescription)
+	if err != nil {
+		t.Fatalf("Cannot register /foo: %v", err)
+	}
+	emitter.Reset()
+	Initialize()
+	EmitMetricUpdate()
+
+	// We should have gotten the metric registration and the first MetricUpdate.
+	if len(emitter) != 2 {
+		t.Fatalf("emitter has %d messages (%v), expected %d", len(emitter), emitter, 2)
+	}
+
+	if registration, ok := emitter[0].(*pb.MetricRegistration); !ok {
+		t.Errorf("first message is not MetricRegistration: %T / %v", emitter[0], emitter[0])
+	} else if len(registration.Stages) != len(allStages) {
+		t.Errorf("MetricRegistration has %d stages (%v), expected %d (%v)", len(registration.Stages), registration.Stages, len(allStages), allStages)
+	} else {
+		for i := 0; i < len(allStages); i++ {
+			if InitStage(registration.Stages[i]) != allStages[i] {
+				t.Errorf("MetricRegistration.Stages[%d]: got %q want %q", i, registration.Stages[i], allStages[i])
+			}
+		}
+	}
+
+	if firstUpdate, ok := emitter[1].(*pb.MetricUpdate); !ok {
+		t.Errorf("second message is not MetricUpdate: %T / %v", emitter[1], emitter[1])
+	} else if len(firstUpdate.StageTiming) != 2 {
+		t.Errorf("MetricUpdate has %d stage timings (%v), expected %d", len(firstUpdate.StageTiming), firstUpdate.StageTiming, 2)
+	} else {
+		checkStage(firstUpdate.StageTiming[0], "before_first_update_1")
+		checkStage(firstUpdate.StageTiming[1], "before_first_update_2")
+	}
+
+	// Ensure re-emitting doesn't cause another event to be sent.
+	emitter.Reset()
+	EmitMetricUpdate()
+	if len(emitter) != 0 {
+		t.Fatalf("EmitMetricUpdate emitted %d events want %d", len(emitter), 0)
+	}
+
+	// Generate monitoring data, we should get an event with no stages.
+	fooMetric.Increment()
+	emitter.Reset()
+	EmitMetricUpdate()
+	if len(emitter) != 1 {
+		t.Fatalf("EmitMetricUpdate emitted %d events want %d", len(emitter), 1)
+	} else if update, ok := emitter[0].(*pb.MetricUpdate); !ok {
+		t.Errorf("message is not MetricUpdate: %T / %v", emitter[1], emitter[1])
+	} else if len(update.StageTiming) != 0 {
+		t.Errorf("unexpected stage timing information: %v", update.StageTiming)
+	}
+
+	// Now generate new stages.
+	measureStage("foo_stage_1", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+	measureStage("foo_stage_2", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+	emitter.Reset()
+	EmitMetricUpdate()
+	if len(emitter) != 1 {
+		t.Fatalf("EmitMetricUpdate emitted %d events want %d", len(emitter), 1)
+	} else if update, ok := emitter[0].(*pb.MetricUpdate); !ok {
+		t.Errorf("message is not MetricUpdate: %T / %v", emitter[1], emitter[1])
+	} else if len(update.Metrics) != 0 {
+		t.Errorf("MetricUpdate has %d metric value changes (%v), expected %d", len(update.Metrics), update.Metrics, 0)
+	} else if len(update.StageTiming) != 2 {
+		t.Errorf("MetricUpdate has %d stages (%v), expected %d", len(update.StageTiming), update.StageTiming, 2)
+	} else {
+		checkStage(update.StageTiming[0], "foo_stage_1")
+		checkStage(update.StageTiming[1], "foo_stage_2")
+	}
+
+	// Now try generating data for both metrics and stages.
+	fooMetric.Increment()
+	measureStage("last_stage_1", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+	measureStage("last_stage_2", func() {
+		time.Sleep(100 * time.Millisecond)
+	})
+	fooMetric.Increment()
+	emitter.Reset()
+	EmitMetricUpdate()
+	if len(emitter) != 1 {
+		t.Fatalf("EmitMetricUpdate emitted %d events want %d", len(emitter), 1)
+	} else if update, ok := emitter[0].(*pb.MetricUpdate); !ok {
+		t.Errorf("message is not MetricUpdate: %T / %v", emitter[1], emitter[1])
+	} else if len(update.Metrics) != 1 {
+		t.Errorf("MetricUpdate has %d metric value changes (%v), expected %d", len(update.Metrics), update.Metrics, 1)
+	} else if len(update.StageTiming) != 2 {
+		t.Errorf("MetricUpdate has %d stages (%v), expected %d", len(update.StageTiming), update.StageTiming, 2)
+	} else {
+		checkStage(update.StageTiming[0], "last_stage_1")
+		checkStage(update.StageTiming[1], "last_stage_2")
+	}
+}