Repository: knative/pkg
Pull request #1497 (2020-07-15 07:53:21)

Remove delay-based flakiness from workqueue_test.go
I noticed that `metrics/workqueue_test.go` seemed to be fairly flaky:

https://testgrid.knative.dev/pkg#continuous&sort-by-failures=&include-filter-by-regex=metrics.TestWorkqueueMetrics

It turns out that as we've added some latency to extracting metrics via metricstest, the fairly low latency of `AddRateLimited` with the default rate limiter has started to exceed the latency of extracting 5 metrics from the backend and comparing them. (I'm a little surprised; I was unable to duplicate this locally. I *was* able to trigger failures in the `CheckCountData` on line 130 after the sleep by reducing the sleep to <4ms, but the failure rate wasn't consistent.)

I choose a much bigger delay interval (50ms), and was then able to cut the sleep to 100ms and this passed 100/100 times locally. (Of course, the old test passed every time locally, too, but I feel more confident about this timing.)

knative-prow-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/knative/pkg/pull/1497#" title="Author self-approved">evankanderson</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=knative%2Fpkg).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[metrics/OWNERS](https://github.com/knative/pkg/blob/master/metrics/OWNERS)~~ [evankanderson]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
knative-prow-robot: @evankanderson: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-pkg-unit-tests | 7718460401261385eca70316094a49a3a7cc16c9 | [link](https://prow.knative.dev/view/gcs/knative-prow/pr-logs/pull/knative_pkg/1497/pull-knative-pkg-unit-tests/1283308820935741440) | `/test pull-knative-pkg-unit-tests`

[Full PR test history](https://gubernator.knative.dev/pr/knative_pkg/1497). [Your PR dashboard](https://gubernator.knative.dev/pr/evankanderson).

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
evankanderson: Hmm, the same failure. I'm not quite sure what's driving the latency of the main code path vs elsewhere, but trying increasing the delay to 200ms.

Patch:
diff --git a/controller/controller.go b/controller/controller.go
index 6024ec253..03f67b6ec 100644
--- a/controller/controller.go
+++ b/controller/controller.go
@@ -452,7 +452,7 @@ func (c *Impl) processNextWorkItem() bool {
 		if err != nil {
 			status = falseString
 		}
-		c.statsReporter.ReportReconcile(time.Since(startTime), keyStr, status)
+		c.statsReporter.ReportReconcile(time.Since(startTime), status)
 	}()
 
 	// Embed the key into the logger and attach that to the context we pass
diff --git a/controller/stats_reporter.go b/controller/stats_reporter.go
index c3445ed3d..6efaeca0f 100644
--- a/controller/stats_reporter.go
+++ b/controller/stats_reporter.go
@@ -46,7 +46,6 @@ var (
 	// - length between 1 and 255 inclusive
 	// - characters are printable US-ASCII
 	reconcilerTagKey = tag.MustNewKey("reconciler")
-	keyTagKey        = tag.MustNewKey("key")
 	successTagKey    = tag.MustNewKey("success")
 )
 
@@ -167,12 +166,12 @@ func init() {
 		Description: "Number of reconcile operations",
 		Measure:     reconcileCountStat,
 		Aggregation: view.Count(),
-		TagKeys:     []tag.Key{reconcilerTagKey, keyTagKey, successTagKey},
+		TagKeys:     []tag.Key{reconcilerTagKey, successTagKey},
 	}, {
 		Description: "Latency of reconcile operations",
 		Measure:     reconcileLatencyStat,
 		Aggregation: reconcileDistribution,
-		TagKeys:     []tag.Key{reconcilerTagKey, keyTagKey, successTagKey},
+		TagKeys:     []tag.Key{reconcilerTagKey, successTagKey},
 	}}
 	views = append(views, wp.DefaultViews()...)
 	views = append(views, rp.DefaultViews()...)
@@ -192,7 +191,7 @@ type StatsReporter interface {
 	ReportQueueDepth(v int64) error
 
 	// ReportReconcile reports the count and latency metrics for a reconcile operation
-	ReportReconcile(duration time.Duration, key, success string) error
+	ReportReconcile(duration time.Duration, success string) error
 }
 
 // Reporter holds cached metric objects to report metrics
@@ -234,11 +233,10 @@ func (r *reporter) ReportQueueDepth(v int64) error {
 }
 
 // ReportReconcile reports the count and latency metrics for a reconcile operation
-func (r *reporter) ReportReconcile(duration time.Duration, key, success string) error {
+func (r *reporter) ReportReconcile(duration time.Duration, success string) error {
 	ctx, err := tag.New(
 		context.Background(),
 		tag.Insert(reconcilerTagKey, r.reconciler),
-		tag.Insert(keyTagKey, key),
 		tag.Insert(successTagKey, success))
 	if err != nil {
 		return err
diff --git a/metrics/stackdriver_exporter.go b/metrics/stackdriver_exporter.go
index 1e1a85ae2..96d72dd24 100644
--- a/metrics/stackdriver_exporter.go
+++ b/metrics/stackdriver_exporter.go
@@ -206,76 +206,71 @@ func sdCustomMetricsRecorder(mc metricsConfig, allowCustomMetrics bool) func(con
 		metricskey.LabelClusterName: gm.cluster,
 	}
 	return func(ctx context.Context, mss []stats.Measurement, ros ...stats.Options) error {
-		i := 0
-		var templ *resourceTemplate
-		templateFound := false
+		// Some metrics may be promoted to known Stackdriver schemas, so we may
+		// end up multiple Resources recorded for a single `RecordBatch` call.
+		metricsByResource := map[*resourceTemplate][]stats.Measurement{}
 
-		// This loop serves two purpose, filtering out custom metrics when allowCustomMetrics set to false,
-		// and find the template for the system metrics.
 		for _, m := range mss {
 			metricType := path.Join(mc.stackdriverMetricTypePrefix, m.Measure().Name())
 			t, ok := metricToResourceLabels[metricType]
 			if ok || allowCustomMetrics {
-				mss[i] = m
-				i++
-				if templateFound && templ != t {
-					return fmt.Errorf("mixed resource type measurements in one report: %v", mss)
+				if metricsByResource[t] == nil {
+					metricsByResource[t] = make([]stats.Measurement, 0, len(mss))
 				}
-				templ = t
-				templateFound = true
+				metricsByResource[t] = append(metricsByResource[t], m)
 			}
 		}
-		// Trim the array
-		mss = mss[:i]
-		if i == 0 {
-			return nil
-		}
 
+		baseLabels := map[string]string{}
 		baseResource := metricskey.GetResource(ctx)
-		// Extract resource, if possible
-		if templ != nil {
-			tagMap := tag.FromContext(ctx)
-			r := resource.Resource{
-				Type:   templ.Type,
-				Labels: map[string]string{},
-			}
-			tagMutations := make([]tag.Mutator, 0, len(templ.LabelKeys))
-			if baseResource == nil {
-				baseResource = &resource.Resource{}
-			}
-			for k := range templ.LabelKeys {
-				if v, ok := baseResource.Labels[k]; ok {
-					r.Labels[k] = v
-					continue
+		if baseResource != nil {
+			baseLabels = baseResource.Labels
+		}
+		tagMap := tag.FromContext(ctx)
+		for templ, ms := range metricsByResource {
+			sdResource := baseResource
+			sdCtx := ctx
+			if templ != nil {
+				sdResource = &resource.Resource{
+					Type:   templ.Type,
+					Labels: map[string]string{},
 				}
-				tagKey := tag.MustNewKey(k)
-				if v, ok := tagMap.Value(tagKey); ok {
-					r.Labels[k] = v
-					tagMutations = append(tagMutations, tag.Delete(tagKey))
-					continue
+				tagMutations := make([]tag.Mutator, 0, len(templ.LabelKeys))
+				for k := range templ.LabelKeys {
+					if v, ok := baseLabels[k]; ok {
+						sdResource.Labels[k] = v
+						continue
+					}
+					tagKey := tag.MustNewKey(k)
+					if v, ok := tagMap.Value(tagKey); ok {
+						sdResource.Labels[k] = v
+						tagMutations = append(tagMutations, tag.Delete(tagKey))
+						continue
+					}
+					if v, ok := metadataMap[k]; ok {
+						sdResource.Labels[k] = v
+						continue
+					}
+					sdResource.Labels[k] = metricskey.ValueUnknown
 				}
-				if v, ok := metadataMap[k]; ok {
-					r.Labels[k] = v
-					continue
+				var err error
+				sdCtx, err = tag.New(metricskey.WithResource(ctx, *sdResource), tagMutations...)
+				if err != nil {
+					return err
 				}
-				r.Labels[k] = metricskey.ValueUnknown
 			}
-			var err error
-			ctx, err = tag.New(metricskey.WithResource(ctx, r), tagMutations...)
-			if err != nil {
-				return err
+			if sdResource != nil {
+				opt, err := optionForResource(sdResource)
+				if err != nil {
+					return err
+				}
+				ros = append(ros, opt)
 			}
-			baseResource = &r
-		}
-		if baseResource != nil {
-			opt, err := optionForResource(baseResource)
-			if err != nil {
+			if err := stats.RecordWithOptions(sdCtx, append(ros, stats.WithMeasurements(ms...))...); err != nil {
 				return err
 			}
-			ros = append(ros, opt)
 		}
-
-		return stats.RecordWithOptions(ctx, append(ros, stats.WithMeasurements(mss...))...)
+		return nil
 	}
 }
 


Test patch:
diff --git a/controller/stats_reporter_test.go b/controller/stats_reporter_test.go
index d82e7fe35..ff56d99a3 100644
--- a/controller/stats_reporter_test.go
+++ b/controller/stats_reporter_test.go
@@ -68,7 +68,6 @@ func TestReportReconcile(t *testing.T) {
 	r, _ := NewStatsReporter("testreconciler")
 	wantTags := map[string]string{
 		"reconciler": "testreconciler",
-		"key":        "test/key",
 		"success":    "true",
 	}
 
@@ -81,11 +80,11 @@ func TestReportReconcile(t *testing.T) {
 		initialReconcileLatency = d[0].Data.(*view.DistributionData).Sum()
 	}
 
-	expectSuccess(t, func() error { return r.ReportReconcile(10*time.Millisecond, "test/key", "true") })
+	expectSuccess(t, func() error { return r.ReportReconcile(10*time.Millisecond, "true") })
 	metricstest.CheckCountData(t, "reconcile_count", wantTags, initialReconcileCount+1)
 	metricstest.CheckDistributionData(t, "reconcile_latency", wantTags, 1, initialReconcileLatency+10, initialReconcileLatency+10)
 
-	expectSuccess(t, func() error { return r.ReportReconcile(15*time.Millisecond, "test/key", "true") })
+	expectSuccess(t, func() error { return r.ReportReconcile(15*time.Millisecond, "true") })
 	metricstest.CheckCountData(t, "reconcile_count", wantTags, initialReconcileCount+2)
 	metricstest.CheckDistributionData(t, "reconcile_latency", wantTags, 2, initialReconcileLatency+10, initialReconcileLatency+15)
 }
diff --git a/controller/testing/fake_stats_reporter.go b/controller/testing/fake_stats_reporter.go
index 506754dc1..528a854b3 100644
--- a/controller/testing/fake_stats_reporter.go
+++ b/controller/testing/fake_stats_reporter.go
@@ -30,8 +30,8 @@ type FakeStatsReporter struct {
 
 // FakeReconcileStatData is used to record the calls to ReportReconcile
 type FakeReconcileStatData struct {
-	Duration     time.Duration
-	Key, Success string
+	Duration time.Duration
+	Success  string
 }
 
 // ReportQueueDepth records the call and returns success.
@@ -43,10 +43,10 @@ func (r *FakeStatsReporter) ReportQueueDepth(v int64) error {
 }
 
 // ReportReconcile records the call and returns success.
-func (r *FakeStatsReporter) ReportReconcile(duration time.Duration, key, success string) error {
+func (r *FakeStatsReporter) ReportReconcile(duration time.Duration, success string) error {
 	r.Lock.Lock()
 	defer r.Lock.Unlock()
-	r.reconcileData = append(r.reconcileData, FakeReconcileStatData{duration, key, success})
+	r.reconcileData = append(r.reconcileData, FakeReconcileStatData{duration, success})
 	return nil
 }
 
diff --git a/controller/testing/fake_stats_reporter_test.go b/controller/testing/fake_stats_reporter_test.go
index dc2f894df..8fde1c7e4 100644
--- a/controller/testing/fake_stats_reporter_test.go
+++ b/controller/testing/fake_stats_reporter_test.go
@@ -38,8 +38,8 @@ func TestReportQueueDepth(t *testing.T) {
 
 func TestReportReconcile(t *testing.T) {
 	r := &FakeStatsReporter{}
-	r.ReportReconcile(time.Duration(123), "testkey", "False")
-	if got, want := r.GetReconcileData(), []FakeReconcileStatData{{time.Duration(123), "testkey", "False"}}; !reflect.DeepEqual(want, got) {
+	r.ReportReconcile(time.Duration(123), "False")
+	if got, want := r.GetReconcileData(), []FakeReconcileStatData{{time.Duration(123), "False"}}; !reflect.DeepEqual(want, got) {
 		t.Errorf("reconcile data len: want: %v, got: %v", want, got)
 	}
 }
diff --git a/metrics/resource_view_test.go b/metrics/resource_view_test.go
index e8c5262a1..76b9e23c7 100644
--- a/metrics/resource_view_test.go
+++ b/metrics/resource_view_test.go
@@ -25,6 +25,7 @@ import (
 	"net/http"
 	"os"
 	"sort"
+	"strings"
 	"sync"
 	"testing"
 	"time"
@@ -450,8 +451,11 @@ func TestStackDriverExports(t *testing.T) {
 		"revision_name":      "revision2",
 		"service_name":       "service2",
 	}
-	label3 := map[string]string{
-		"key": "value",
+	batchLabels := map[string]string{
+		"namespace_name":     "ns2",
+		"configuration_name": "config2",
+		"revision_name":      "revision2",
+		"service_name":       "service2",
 	}
 	harness := []struct {
 		name               string
@@ -472,8 +476,8 @@ func TestStackDriverExports(t *testing.T) {
 				2,
 			},
 			{
-				"custom.googleapis.com/knative.dev/autoscaler/testing/value",
-				label3,
+				"custom.googleapis.com/knative.dev/autoscaler/not_ready_pods",
+				batchLabels,
 				3,
 			},
 		},
@@ -516,14 +520,13 @@ func TestStackDriverExports(t *testing.T) {
 				Measure:     desiredPodCountM,
 				Aggregation: view.LastValue(),
 			}
-			customMeasurement := stats.Int64(
-				"testing/value",
-				"Stored value",
+			notReadyPodCountM := stats.Int64(
+				"not_ready_pods",
+				"Number of pods that are not ready",
 				stats.UnitDimensionless)
 			customView := &view.View{
-				Name:        "testing/value",
-				Description: "Test value",
-				Measure:     customMeasurement,
+				Description: "non-knative-revision metric per KnativeRevisionMetrics",
+				Measure:     notReadyPodCountM,
 				Aggregation: view.LastValue(),
 			}
 
@@ -551,23 +554,13 @@ func TestStackDriverExports(t *testing.T) {
 			Record(ctx, actualPodCountM.M(int64(1)))
 
 			r := resource.Resource{
-				Type: "knative_revision",
-				Labels: map[string]string{
-					metricskey.LabelNamespaceName:     "ns2",
-					metricskey.LabelServiceName:       "service2",
-					metricskey.LabelConfigurationName: "config2",
-					metricskey.LabelRevisionName:      "revision2",
-				},
+				Type:   "testing",
+				Labels: batchLabels,
 			}
-			Record(metricskey.WithResource(context.Background(), r), desiredPodCountM.M(int64(2)))
-
-			r = resource.Resource{
-				Type: "custom_resource",
-				Labels: map[string]string{
-					"key": "value",
-				},
-			}
-			Record(metricskey.WithResource(context.Background(), r), customMeasurement.M(int64(3)))
+			RecordBatch(
+				metricskey.WithResource(context.Background(), r),
+				desiredPodCountM.M(int64(2)),
+				notReadyPodCountM.M(int64(3)))
 
 			records := []metricExtract{}
 			for record := range sdFake.published {
@@ -577,6 +570,11 @@ func TestStackDriverExports(t *testing.T) {
 						Labels: ts.Resource.Labels,
 						Value:  ts.Points[0].Value.GetInt64Value(),
 					})
+					if strings.HasPrefix(ts.Metric.Type, "knative.dev/") {
+						if diff := cmp.Diff(ts.Resource.Type, metricskey.ResourceTypeKnativeRevision); diff != "" {
+							t.Errorf("Incorrect resource type for %q: (-want +got): %s", ts.Metric.Type, diff)
+						}
+					}
 				}
 				if len(records) >= 2 {
 					// There's no way to synchronize on the internal timer used
diff --git a/metrics/workqueue_test.go b/metrics/workqueue_test.go
index c08523965..e45359e14 100644
--- a/metrics/workqueue_test.go
+++ b/metrics/workqueue_test.go
@@ -35,6 +35,20 @@ func newFloat64(name string) *stats.Float64Measure {
 	return stats.Float64(name, "bar", "wtfs/s")
 }
 
+type FixedRateLimiter struct {
+	delay time.Duration
+}
+
+func (f *FixedRateLimiter) When(item interface{}) time.Duration {
+	return f.delay
+}
+
+func (f *FixedRateLimiter) Forget(item interface{}) {}
+
+func (f *FixedRateLimiter) NumRequeues(item interface{}) int {
+	return 0
+}
+
 func TestWorkqueueMetrics(t *testing.T) {
 	wp := &WorkqueueProvider{
 		Adds:                           newInt64("adds"),
@@ -60,10 +74,8 @@ func TestWorkqueueMetrics(t *testing.T) {
 	defer view.Unregister(views...)
 
 	queueName := t.Name()
-	wq := workqueue.NewNamedRateLimitingQueue(
-		workqueue.DefaultControllerRateLimiter(),
-		queueName,
-	)
+	limiter := &FixedRateLimiter{delay: 200 * time.Millisecond}
+	wq := workqueue.NewNamedRateLimitingQueue(limiter, queueName)
 
 	metricstest.CheckStatsNotReported(t, "adds", "depth", "latency", "retries", "work_duration",
 		"unfinished_work_seconds", "longest_running_processor_seconds")
@@ -114,7 +126,7 @@ func TestWorkqueueMetrics(t *testing.T) {
 	metricstest.CheckCountData(t, "adds", map[string]string{"name": queueName}, 2)
 
 	// It doesn't show up as an "add" until the rate limit has elapsed.
-	time.Sleep(1 * time.Second)
+	time.Sleep(2 * limiter.delay)
 	metricstest.CheckCountData(t, "adds", map[string]string{"name": queueName}, 3)
 
 	wq.ShutDown()