all: instrument build, vet, and run time

This change adds a latency distribution for the build&vet stage, the vet
stage, and the run stage of a snippet handled by the compile handler.

For golang/go#44822

Change-Id: Icedce87492afadd6041efb05e6f0ed3cd12a01ba
Reviewed-on: https://go-review.googlesource.com/c/playground/+/302770
Trust: Alexander Rakoczy <alex@golang.org>
Run-TryBot: Alexander Rakoczy <alex@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Carlos Amedee <carlos@golang.org>

Author: toothrot

go.mod

@@ -15,6 +15,7 @@ require (
 	golang.org/x/mod v0.2.0
 	golang.org/x/tools v0.0.0-20200420001825-978e26b7c37c
 	google.golang.org/api v0.20.0
+	google.golang.org/appengine v1.6.5 // indirect
 	google.golang.org/genproto v0.0.0-20200312145019-da6875a35672
 	gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 // indirect
 	gopkg.in/yaml.v2 v2.2.7 // indirect

internal/metrics/service.go

@@ -7,6 +7,7 @@
 package metrics
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"net/http"
@@ -17,6 +18,7 @@ import (
 	"contrib.go.opencensus.io/exporter/prometheus"
 	"contrib.go.opencensus.io/exporter/stackdriver"
 	"go.opencensus.io/stats/view"
+	"google.golang.org/appengine"
 	mrpb "google.golang.org/genproto/googleapis/api/monitoredres"
 )
 
@@ -138,6 +140,30 @@ func GCEResource(jobName string) (*MonitoredResource, error) {
 	}), nil
 }
 
+// GAEResource returns a *MonitoredResource with fields populated and
+// for StackDriver.
+//
+// The resource will be in StackDrvier's gae_instance type.
+func GAEResource(ctx context.Context) (*MonitoredResource, error) {
+	if !appengine.IsAppEngine() {
+		return nil, fmt.Errorf("not running on appengine")
+	}
+	projID, err := metadata.ProjectID()
+	if err != nil {
+		return nil, err
+	}
+	return (*MonitoredResource)(&mrpb.MonitoredResource{
+		Type: "gae_instance",
+		Labels: map[string]string{
+			"project_id":  projID,
+			"module_id":   appengine.ModuleName(ctx),
+			"version_id":  appengine.VersionID(ctx),
+			"instance_id": appengine.InstanceID(),
+			"location":    appengine.Datacenter(ctx),
+		},
+	}), nil
+}
+
 // instanceGroupName fetches the instanceGroupName from the instance
 // metadata.
 //

metrics.go

@@ -0,0 +1,72 @@
+// Copyright 2021 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package main
+
+import (
+	"go.opencensus.io/stats"
+	"go.opencensus.io/stats/view"
+	"go.opencensus.io/tag"
+)
+
+var (
+	BuildLatencyDistribution = view.Distribution(1, 5, 10, 15, 20, 25, 50, 75, 100, 125, 150, 200, 250, 300, 400, 500, 750, 1000, 1500, 2000, 2500, 3000, 3500, 4000, 4500, 5000, 5500, 6000, 7000, 8000, 9000, 10000, 20000, 30000)
+	kGoBuildSuccess          = tag.MustNewKey("go-playground/frontend/go_build_success")
+	kGoRunSuccess            = tag.MustNewKey("go-playground/frontend/go_run_success")
+	kGoVetSuccess            = tag.MustNewKey("go-playground/frontend/go_vet_success")
+	mGoBuildLatency          = stats.Float64("go-playground/frontend/go_build_latency", "", stats.UnitMilliseconds)
+	mGoRunLatency            = stats.Float64("go-playground/frontend/go_run_latency", "", stats.UnitMilliseconds)
+	mGoVetLatency            = stats.Float64("go-playground/frontend/go_vet_latency", "", stats.UnitMilliseconds)
+
+	goBuildCount = &view.View{
+		Name:        "go-playground/frontend/go_build_count",
+		Description: "Number of snippets built",
+		Measure:     mGoBuildLatency,
+		TagKeys:     []tag.Key{kGoBuildSuccess},
+		Aggregation: view.Count(),
+	}
+	goBuildLatency = &view.View{
+		Name:        "go-playground/frontend/go_build_latency",
+		Description: "Latency distribution of building snippets",
+		Measure:     mGoBuildLatency,
+		Aggregation: BuildLatencyDistribution,
+	}
+	goRunCount = &view.View{
+		Name:        "go-playground/frontend/go_run_count",
+		Description: "Number of snippets run",
+		Measure:     mGoRunLatency,
+		TagKeys:     []tag.Key{kGoRunSuccess},
+		Aggregation: view.Count(),
+	}
+	goRunLatency = &view.View{
+		Name:        "go-playground/frontend/go_run_latency",
+		Description: "Latency distribution of running snippets",
+		Measure:     mGoRunLatency,
+		Aggregation: BuildLatencyDistribution,
+	}
+	goVetCount = &view.View{
+		Name:        "go-playground/frontend/go_vet_count",
+		Description: "Number of vet runs",
+		Measure:     mGoVetLatency,
+		TagKeys:     []tag.Key{kGoVetSuccess},
+		Aggregation: view.Count(),
+	}
+	goVetLatency = &view.View{
+		Name:        "go-playground/sandbox/go_vet_latency",
+		Description: "Latency distribution of vet runs",
+		Measure:     mGoVetLatency,
+		Aggregation: BuildLatencyDistribution,
+	}
+)
+
+// views should contain all measurements. All *view.View added to this
+// slice will be registered and exported to the metric service.
+var views = []*view.View{
+	goBuildCount,
+	goBuildLatency,
+	goRunCount,
+	goRunLatency,
+	goVetCount,
+	goVetLatency,
+}

sandbox.go

@@ -36,6 +36,8 @@ import (
 
 	"cloud.google.com/go/compute/metadata"
 	"github.com/bradfitz/gomemcache/memcache"
+	"go.opencensus.io/stats"
+	"go.opencensus.io/tag"
 	"golang.org/x/playground/internal"
 	"golang.org/x/playground/internal/gcpdial"
 	"golang.org/x/playground/sandbox/sandboxtypes"
@@ -415,13 +417,25 @@ func (b *buildResult) cleanup() error {
 // sandboxBuild builds a Go program and returns a build result that includes the build context.
 //
 // An error is returned if a non-user-correctable error has occurred.
-func sandboxBuild(ctx context.Context, tmpDir string, in []byte, vet bool) (*buildResult, error) {
+func sandboxBuild(ctx context.Context, tmpDir string, in []byte, vet bool) (br *buildResult, err error) {
+	start := time.Now()
+	defer func() {
+		status := "success"
+		if err != nil {
+			status = "error"
+		}
+		// Ignore error. The only error can be invalid tag key or value
+		// length, which we know are safe.
+		stats.RecordWithTags(ctx, []tag.Mutator{tag.Upsert(kGoBuildSuccess, status)},
+			mGoBuildLatency.M(float64(time.Since(start))/float64(time.Millisecond)))
+	}()
+
 	files, err := splitFiles(in)
 	if err != nil {
 		return &buildResult{errorMessage: err.Error()}, nil
 	}
 
-	br := new(buildResult)
+	br = new(buildResult)
 	defer br.cleanup()
 	var buildPkgArg = "."
 	if files.Num() == 1 && len(files.Data(progName)) > 0 {
@@ -515,7 +529,7 @@ func sandboxBuild(ctx context.Context, tmpDir string, in []byte, vet bool) (*bui
 	}
 	if vet {
 		// TODO: do this concurrently with the execution to reduce latency.
-		br.vetOut, err = vetCheckInDir(tmpDir, br.goPath)
+		br.vetOut, err = vetCheckInDir(ctx, tmpDir, br.goPath)
 		if err != nil {
 			return nil, fmt.Errorf("running vet: %v", err)
 		}
@@ -524,8 +538,18 @@ func sandboxBuild(ctx context.Context, tmpDir string, in []byte, vet bool) (*bui
 }
 
 // sandboxRun runs a Go binary in a sandbox environment.
-func sandboxRun(ctx context.Context, exePath string, testParam string) (sandboxtypes.Response, error) {
-	var execRes sandboxtypes.Response
+func sandboxRun(ctx context.Context, exePath string, testParam string) (execRes sandboxtypes.Response, err error) {
+	start := time.Now()
+	defer func() {
+		status := "success"
+		if err != nil {
+			status = "error"
+		}
+		// Ignore error. The only error can be invalid tag key or value
+		// length, which we know are safe.
+		stats.RecordWithTags(ctx, []tag.Mutator{tag.Upsert(kGoBuildSuccess, status)},
+			mGoRunLatency.M(float64(time.Since(start))/float64(time.Millisecond)))
+	}()
 	exeBytes, err := ioutil.ReadFile(exePath)
 	if err != nil {
 		return execRes, err

server.go

@@ -5,12 +5,15 @@
 package main
 
 import (
+	"context"
 	"fmt"
 	"net/http"
 	"os"
 	"strings"
 	"time"
 
+	"cloud.google.com/go/compute/metadata"
+	"golang.org/x/playground/internal/metrics"
 	"golang.org/x/tools/godoc/static"
 )
 
@@ -43,6 +46,17 @@ func newServer(options ...func(s *server) error) (*server, error) {
 			s.modtime = fi.ModTime()
 		}
 	}
+	gr, err := metrics.GAEResource(context.Background())
+	if err != nil {
+		s.log.Printf("metrics.GaeService() = _, %q", err)
+	}
+	ms, err := metrics.NewService(gr, views)
+	if err != nil {
+		s.log.Printf("Failed to initialize metrics: metrics.NewService() = _, %q. (not on GCP?)", err)
+	}
+	if ms != nil && !metadata.OnGCE() {
+		s.mux.Handle("/statusz", ms)
+	}
 	s.init()
 	return s, nil
 }

vet.go

@@ -12,6 +12,10 @@ import (
 	"os/exec"
 	"path/filepath"
 	"strings"
+	"time"
+
+	"go.opencensus.io/stats"
+	"go.opencensus.io/tag"
 )
 
 // vetCheck runs the "vet" tool on the source code in req.Body.
@@ -33,7 +37,7 @@ func vetCheck(ctx context.Context, req *request) (*response, error) {
 	if err := ioutil.WriteFile(in, []byte(req.Body), 0400); err != nil {
 		return nil, fmt.Errorf("error creating temp file %q: %v", in, err)
 	}
-	vetOutput, err := vetCheckInDir(tmpDir, os.Getenv("GOPATH"))
+	vetOutput, err := vetCheckInDir(ctx, tmpDir, os.Getenv("GOPATH"))
 	if err != nil {
 		// This is about errors running vet, not vet returning output.
 		return nil, err
@@ -46,7 +50,19 @@ func vetCheck(ctx context.Context, req *request) (*response, error) {
 // go vet was able to run, not whether vet reported problem. The
 // returned value is ("", nil) if vet successfully found nothing,
 // and (non-empty, nil) if vet ran and found issues.
-func vetCheckInDir(dir, goPath string) (output string, execErr error) {
+func vetCheckInDir(ctx context.Context, dir, goPath string) (output string, execErr error) {
+	start := time.Now()
+	defer func() {
+		status := "success"
+		if execErr != nil {
+			status = "error"
+		}
+		// Ignore error. The only error can be invalid tag key or value
+		// length, which we know are safe.
+		stats.RecordWithTags(ctx, []tag.Mutator{tag.Upsert(kGoVetSuccess, status)},
+			mGoVetLatency.M(float64(time.Since(start))/float64(time.Millisecond)))
+	}()
+
 	cmd := exec.Command("go", "vet")
 	cmd.Dir = dir
 	// Linux go binary is not built with CGO_ENABLED=0.