tf: record count of all echo calls made (istio#37483)

This is helpful for debugging, we can see if we are making more requests
than expected, if a PR reduces calls, etc.

pkg/test/echo/client.go

@@ -23,6 +23,7 @@ import (
 	"strings"
 	"time"
 
+	"go.uber.org/atomic"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials"
 	"google.golang.org/grpc/credentials/insecure"
@@ -109,10 +110,15 @@ func (c *Client) Echo(ctx context.Context, request *proto.EchoRequest) (Response
 // ForwardEcho sends the given forward request and parses the response for easier processing. Only fails if the request fails.
 func (c *Client) ForwardEcho(ctx context.Context, request *proto.ForwardEchoRequest) (Responses, error) {
 	// Forward a request from 'this' service to the destination service.
+	GlobalEchoRequests.Add(uint64(request.Count))
 	resp, err := c.client.ForwardEcho(ctx, request)
 	if err != nil {
 		return nil, err
 	}
 
 	return ParseResponses(request, resp), nil
 }
+
+// GlobalEchoRequests records how many echo calls we have made total, from all sources.
+// Note: go tests are distinct binaries per test suite, so this is the suite level number of calls
+var GlobalEchoRequests = atomic.NewUint64(0)

pkg/test/framework/components/istio/operator.go

@@ -82,9 +82,8 @@ type operatorComponent struct {
 	// The key is the cluster name
 	installManifest map[string][]string
 	// ingress components, indexed first by cluster name and then by gateway name.
-	ingress    map[string]map[string]ingress.Instance
-	workDir    string
-	deployTime time.Duration
+	ingress map[string]map[string]ingress.Instance
+	workDir string
 }
 
 var (
@@ -171,34 +170,14 @@ func (i *operatorComponent) CustomIngressFor(c cluster.Cluster, serviceName, ist
 	return i.ingress[c.Name()][istioLabel]
 }
 
-func appendToFile(contents string, file string) error {
-	f, err := os.OpenFile(file, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0o600)
-	if err != nil {
-		return err
-	}
-
-	defer func() {
-		_ = f.Close()
-	}()
-
-	if _, err = f.WriteString(contents); err != nil {
-		return err
-	}
-	return nil
-}
-
 func (i *operatorComponent) Close() error {
 	t0 := time.Now()
 	scopes.Framework.Infof("=== BEGIN: Cleanup Istio [Suite=%s] ===", i.ctx.Settings().TestID)
 
 	// Write time spent for cleanup and deploy to ARTIFACTS/trace.yaml and logs to allow analyzing test times
 	defer func() {
 		delta := time.Since(t0)
-		y := fmt.Sprintf(`'suite/%s':
-  istio-deploy: %f
-  istio-cleanup: %f
-`, i.ctx.Settings().TestID, i.deployTime.Seconds(), delta.Seconds())
-		_ = appendToFile(y, filepath.Join(i.ctx.Settings().BaseDir, "trace.yaml"))
+		i.ctx.RecordTraceEvent("istio-cleanup", delta.Seconds())
 		scopes.Framework.Infof("=== SUCCEEDED: Cleanup Istio in %v [Suite=%s] ===", delta, i.ctx.Settings().TestID)
 	}()
 
@@ -323,7 +302,7 @@ func deploy(ctx resource.Context, env *kube.Environment, cfg Config) (Instance,
 
 	t0 := time.Now()
 	defer func() {
-		i.deployTime = time.Since(t0)
+		ctx.RecordTraceEvent("istio-deploy", time.Since(t0).Seconds())
 	}()
 	i.id = ctx.TrackResource(i)
 

pkg/test/framework/config.go

@@ -19,6 +19,7 @@ import (
 	"strings"
 
 	"github.com/hashicorp/go-multierror"
+	"go.uber.org/atomic"
 
 	"istio.io/istio/pkg/test"
 	"istio.io/istio/pkg/test/framework/components/cluster"
@@ -45,10 +46,15 @@ func newConfigManager(ctx resource.Context, clusters cluster.Clusters) resource.
 	}
 }
 
+// GlobalYAMLWrites records how many YAMLs we have applied from all sources.
+// Note: go tests are distinct binaries per test suite, so this is the suite level number of calls
+var GlobalYAMLWrites = atomic.NewUint64(0)
+
 func (c *configManager) applyYAML(cleanup bool, ns string, yamlText ...string) error {
 	if len(c.prefix) == 0 {
 		return c.WithFilePrefix("apply").(*configManager).applyYAML(cleanup, ns, yamlText...)
 	}
+	GlobalYAMLWrites.Add(uint64(len(yamlText)))
 
 	// Convert the content to files.
 	yamlFiles, err := c.ctx.WriteYAML(c.prefix, yamlText...)

pkg/test/framework/resource/context.go

@@ -98,4 +98,7 @@ type Context interface {
 
 	// ConfigIstio returns a ConfigManager that writes config to all Istio config clusters.
 	ConfigIstio() ConfigManager
+
+	// RecordTraceEvent records an event. This is later saved to trace.yaml for analysis
+	RecordTraceEvent(key string, value interface{})
 }

pkg/test/framework/suite.go

@@ -30,6 +30,7 @@ import (
 	"gopkg.in/yaml.v2"
 
 	kubelib "istio.io/istio/pkg/kube"
+	"istio.io/istio/pkg/test/echo"
 	"istio.io/istio/pkg/test/framework/components/cluster"
 	"istio.io/istio/pkg/test/framework/components/environment/kube"
 	"istio.io/istio/pkg/test/framework/config"
@@ -334,7 +335,6 @@ func (s *suiteImpl) run() (errLevel int) {
 	}
 
 	ctx := rt.suiteContext()
-
 	// Skip the test if its explicitly skipped
 	if s.isSkipped() {
 		return s.doSkip(ctx)
@@ -380,6 +380,11 @@ func (s *suiteImpl) run() (errLevel int) {
 	defer func() {
 		end := time.Now()
 		scopes.Framework.Infof("=== Suite %q run time: %v ===", ctx.Settings().TestID, end.Sub(start))
+
+		ctx.RecordTraceEvent("suite-runtime", end.Sub(start).Seconds())
+		ctx.RecordTraceEvent("echo-calls", echo.GlobalEchoRequests.Load())
+		ctx.RecordTraceEvent("yaml-apply", GlobalYAMLWrites.Load())
+		_ = appendToFile(ctx.marshalTraceEvent(), filepath.Join(ctx.Settings().BaseDir, "trace.yaml"))
 	}()
 
 	attempt := 0
@@ -548,3 +553,19 @@ func mustCompileAll(patterns ...string) []*regexp.Regexp {
 
 	return out
 }
+
+func appendToFile(contents []byte, file string) error {
+	f, err := os.OpenFile(file, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0o600)
+	if err != nil {
+		return err
+	}
+
+	defer func() {
+		_ = f.Close()
+	}()
+
+	if _, err = f.Write(contents); err != nil {
+		return err
+	}
+	return nil
+}

pkg/test/framework/suitecontext.go

@@ -22,6 +22,8 @@ import (
 	"strings"
 	"sync"
 
+	"sigs.k8s.io/yaml"
+
 	"istio.io/istio/pkg/test/framework/components/cluster"
 	"istio.io/istio/pkg/test/framework/features"
 	"istio.io/istio/pkg/test/framework/label"
@@ -57,6 +59,8 @@ type suiteContext struct {
 
 	outcomeMu    sync.RWMutex
 	testOutcomes []TestOutcome
+
+	traces sync.Map
 }
 
 func newSuiteContext(s *resource.Settings, envFn resource.EnvironmentFactory, labels label.Set) (*suiteContext, error) {
@@ -239,3 +243,20 @@ func (s *suiteContext) registerOutcome(test *testImpl) {
 	defer s.contextMu.Unlock()
 	s.testOutcomes = append(s.testOutcomes, newOutcome)
 }
+
+func (s *suiteContext) RecordTraceEvent(key string, value interface{}) {
+	s.traces.Store(key, value)
+}
+
+func (s *suiteContext) marshalTraceEvent() []byte {
+	kvs := map[string]interface{}{}
+	s.traces.Range(func(key, value interface{}) bool {
+		kvs[key.(string)] = value
+		return true
+	})
+	outer := map[string]interface{}{
+		fmt.Sprintf("suite/%s", s.settings.TestID): kvs,
+	}
+	d, _ := yaml.Marshal(outer)
+	return d
+}

pkg/test/framework/testcontext.go

@@ -413,3 +413,8 @@ type closer struct {
 func (c *closer) Close() error {
 	return c.fn()
 }
+
+func (c *testContext) RecordTraceEvent(key string, value interface{}) {
+	// Currently, only supported at suite level.
+	panic("TODO: implement tracing in test context")
+}