internal/middleware: instrument cache latency
To prove the hypothesis that our cache timeout is too short, instrument
a cache latency metric.
Change-Id: Ie120f890b9dd488cdbb02556de84c9489ff8d846
Reviewed-on: https://go-review.googlesource.com/c/pkgsite/+/247317
Run-TryBot: Julie Qiu <julie@golang.org>
TryBot-Result: kokoro <noreply+kokoro@google.com>
Reviewed-by: Julie Qiu <julie@golang.org>
diff --git a/cmd/frontend/main.go b/cmd/frontend/main.go
index e8d32b8..d498d2e 100644
--- a/cmd/frontend/main.go
+++ b/cmd/frontend/main.go
@@ -138,6 +138,7 @@
frontend.VersionTypeCount,
middleware.CacheResultCount,
middleware.CacheErrorCount,
+ middleware.CacheLatency,
middleware.QuotaResultCount,
)
if err := dcensus.Init(cfg, views...); err != nil {
diff --git a/internal/middleware/caching.go b/internal/middleware/caching.go
index b8ec1da..7aaa1fb 100644
--- a/internal/middleware/caching.go
+++ b/internal/middleware/caching.go
@@ -15,6 +15,7 @@
"time"
"github.com/go-redis/redis/v7"
+ "go.opencensus.io/plugin/ochttp"
"go.opencensus.io/stats"
"go.opencensus.io/stats/view"
"go.opencensus.io/tag"
@@ -31,13 +32,17 @@
"The result of a cache request.",
stats.UnitDimensionless,
)
+ cacheLatency = stats.Float64(
+ "go-discovery/cache/result_latency",
+ "Cache serving latency latency",
+ stats.UnitMilliseconds,
+ )
cacheErrors = stats.Int64(
"go-discovery/cache/errors",
"Errors retrieving from cache.",
stats.UnitDimensionless,
)
- // CacheResultCount is a counter of cache results, by cache name and hit success.
CacheResultCount = &view.View{
Name: "go-discovery/cache/result_count",
Measure: cacheResults,
@@ -45,7 +50,13 @@
Description: "cache results, by cache name and whether it was a hit",
TagKeys: []tag.Key{keyCacheName, keyCacheHit},
}
- // CacheErrorCount is a counter of cache errors, by cache name.
+ CacheLatency = &view.View{
+ Name: "go-discovery/cache/result_latency",
+ Measure: cacheLatency,
+ Description: "cache result latency, by cache name and whether it was a hit",
+ Aggregation: ochttp.DefaultLatencyDistribution,
+ TagKeys: []tag.Key{keyCacheName, keyCacheHit},
+ }
CacheErrorCount = &view.View{
Name: "go-discovery/cache/errors",
Measure: cacheErrors,
@@ -59,11 +70,12 @@
testMode = false
)
-func recordCacheResult(ctx context.Context, name string, hit bool) {
+func recordCacheResult(ctx context.Context, name string, hit bool, latency time.Duration) {
+ ms := float64(latency) / float64(time.Millisecond)
stats.RecordWithTags(ctx, []tag.Mutator{
tag.Upsert(keyCacheName, name),
tag.Upsert(keyCacheHit, strconv.FormatBool(hit)),
- }, cacheResults.M(1))
+ }, cacheResults.M(1), cacheLatency.M(ms))
}
func recordCacheError(ctx context.Context, name, operation string) {
@@ -111,6 +123,7 @@
}
func (c *cache) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+ start := time.Now()
// Check auth header to see if request should bypass cache.
authVal := r.Header.Get(config.AuthHeader)
for _, wantVal := range c.authValues {
@@ -122,13 +135,13 @@
ctx := r.Context()
key := r.URL.String()
if reader, ok := c.get(ctx, key); ok {
- recordCacheResult(ctx, c.name, true)
+ recordCacheResult(ctx, c.name, true, time.Since(start))
if _, err := io.Copy(w, reader); err != nil {
log.Errorf(ctx, "error copying zip bytes: %v", err)
}
return
}
- recordCacheResult(ctx, c.name, false)
+ recordCacheResult(ctx, c.name, false, time.Since(start))
rec := newRecorder(w)
c.delegate.ServeHTTP(rec, r)
if rec.bufErr == nil && (rec.statusCode == 0 || rec.statusCode == http.StatusOK) {
