Tracing enhancements for CLI perf metrics capture (#7279)

* Allow ProgramTest Tracing flag to expand {command}

* Fix comment typos

* Memory stats collection

pkg/testing/integration/program.go

@@ -216,8 +216,17 @@ type ProgramTestOptions struct {
 	// environment during tests.
 	StackName string
 
-	// Tracing specifies the Zipkin endpoint if any to use for tracing Pulumi invocations.
+	// If non-empty, specifies the value of the `--tracing` flag to pass
+	// to Pulumi CLI, which may be a Zipkin endpoint or a
+	// `file:./local.trace` style url for AppDash tracing.
+	//
+	// Template `{command}` syntax will be expanded to the current
+	// command name such as `pulumi-stack-rm`. This is useful for
+	// file-based tracing since `ProgramTest` performs multiple
+	// CLI invocations that can inadvertently overwrite the trace
+	// file.
 	Tracing string
+
 	// NoParallel will opt the test out of being ran in parallel.
 	NoParallel bool
 
@@ -719,7 +728,7 @@ func (pt *ProgramTester) getDotNetBin() (string, error) {
 	return getCmdBin(&pt.dotNetBin, "dotnet", pt.opts.DotNetBin)
 }
 
-func (pt *ProgramTester) pulumiCmd(args []string) ([]string, error) {
+func (pt *ProgramTester) pulumiCmd(name string, args []string) ([]string, error) {
 	bin, err := pt.getBin()
 	if err != nil {
 		return nil, err
@@ -730,7 +739,7 @@ func (pt *ProgramTester) pulumiCmd(args []string) ([]string, error) {
 	}
 	cmd = append(cmd, args...)
 	if tracing := pt.opts.Tracing; tracing != "" {
-		cmd = append(cmd, "--tracing", tracing)
+		cmd = append(cmd, "--tracing", strings.ReplaceAll(tracing, "{command}", name))
 	}
 	return cmd, nil
 }
@@ -770,7 +779,7 @@ func (pt *ProgramTester) runCommand(name string, args []string, wd string) error
 }
 
 func (pt *ProgramTester) runPulumiCommand(name string, args []string, wd string, expectFailure bool) error {
-	cmd, err := pt.pulumiCmd(args)
+	cmd, err := pt.pulumiCmd(name, args)
 	if err != nil {
 		return err
 	}

sdk/go/common/util/cmdutil/trace.go

@@ -1,4 +1,4 @@
-// Copyright 2016-2018, Pulumi Corporation.
+// Copyright 2016-2021, Pulumi Corporation.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -22,6 +22,9 @@ import (
 	"net"
 	"net/url"
 	"os"
+	"runtime"
+	"strings"
+	"time"
 
 	opentracing "github.com/opentracing/opentracing-go"
 	"github.com/pulumi/pulumi/sdk/v3/go/common/util/contract"
@@ -143,7 +146,12 @@ func InitTracing(name, rootSpanName, tracingEndpoint string) {
 
 	// If a root span was requested, start it now.
 	if rootSpanName != "" {
-		TracingRootSpan = tracer.StartSpan(rootSpanName)
+		var options []opentracing.StartSpanOption
+		for _, tag := range rootSpanTags() {
+			options = append(options, tag)
+		}
+		TracingRootSpan = tracer.StartSpan(rootSpanName, options...)
+		go collectMemStats(rootSpanName)
 	}
 }
 
@@ -184,3 +192,129 @@ func startProxyAppDashServer(collector appdash.Collector) (string, error) {
 
 	return fmt.Sprintf("tcp://127.0.0.1:%d", collectorPort), nil
 }
+
+// Computes initial tags to write to the `TracingRootSpan`, which can
+// be useful for aggregating trace data in benchmarks.
+func rootSpanTags() []opentracing.Tag {
+
+	tags := []opentracing.Tag{
+		{
+			Key:   "os.Args",
+			Value: os.Args,
+		},
+		{
+			Key:   "runtime.GOOS",
+			Value: runtime.GOOS,
+		},
+		{
+			Key:   "runtime.GOARCH",
+			Value: runtime.GOARCH,
+		},
+		{
+			Key:   "runtime.NumCPU",
+			Value: runtime.NumCPU(),
+		},
+	}
+
+	// Promote all env vars `pulumi_tracing_tag_foo=bar` into tags `foo: bar`.
+	envPrefix := "pulumi_tracing_tag_"
+	for _, e := range os.Environ() {
+		pair := strings.SplitN(e, "=", 2)
+		envVarName := strings.ToLower(pair[0])
+		envVarValue := pair[1]
+
+		if strings.HasPrefix(envVarName, envPrefix) {
+			tags = append(tags, opentracing.Tag{
+				Key:   strings.TrimPrefix(envVarName, envPrefix),
+				Value: envVarValue,
+			})
+		}
+	}
+
+	return tags
+}
+
+// Samples memory stats in the background at 1s intervals, and creates
+// spans for the data. This is currently opt-in via
+// `PULUMI_TRACING_MEMSTATS_POLL_INTERVAL=1s` or similar. Consider
+// collecting this by default later whenever tracing is enabled as we
+// calibrate that the overhead is low enough.
+func collectMemStats(spanPrefix string) {
+	memStats := runtime.MemStats{}
+	maxStats := runtime.MemStats{}
+
+	poll := func() {
+		if TracingRootSpan == nil {
+			return
+		}
+
+		runtime.ReadMemStats(&memStats)
+
+		// report cumulative metrics as is
+		TracingRootSpan.SetTag("runtime.NumCgoCall", runtime.NumCgoCall())
+		TracingRootSpan.SetTag("MemStats.TotalAlloc", memStats.TotalAlloc)
+		TracingRootSpan.SetTag("MemStats.Mallocs", memStats.Mallocs)
+		TracingRootSpan.SetTag("MemStats.Frees", memStats.Frees)
+		TracingRootSpan.SetTag("MemStats.PauseTotalNs", memStats.PauseTotalNs)
+		TracingRootSpan.SetTag("MemStats.NumGC", memStats.NumGC)
+
+		// for other metrics report the max
+
+		if memStats.Sys > maxStats.Sys {
+			maxStats.Sys = memStats.Sys
+			TracingRootSpan.SetTag("MemStats.Sys.Max", maxStats.Sys)
+		}
+
+		if memStats.HeapAlloc > maxStats.HeapAlloc {
+			maxStats.HeapAlloc = memStats.HeapAlloc
+			TracingRootSpan.SetTag("MemStats.HeapAlloc.Max", maxStats.HeapAlloc)
+		}
+
+		if memStats.HeapSys > maxStats.HeapSys {
+			maxStats.HeapSys = memStats.HeapSys
+			TracingRootSpan.SetTag("MemStats.HeapSys.Max", maxStats.HeapSys)
+		}
+
+		if memStats.HeapIdle > maxStats.HeapIdle {
+			maxStats.HeapIdle = memStats.HeapIdle
+			TracingRootSpan.SetTag("MemStats.HeapIdle.Max", maxStats.HeapIdle)
+		}
+
+		if memStats.HeapInuse > maxStats.HeapInuse {
+			maxStats.HeapInuse = memStats.HeapInuse
+			TracingRootSpan.SetTag("MemStats.HeapInuse.Max", maxStats.HeapInuse)
+		}
+
+		if memStats.HeapReleased > maxStats.HeapReleased {
+			maxStats.HeapReleased = memStats.HeapReleased
+			TracingRootSpan.SetTag("MemStats.HeapReleased.Max", maxStats.HeapReleased)
+		}
+
+		if memStats.HeapObjects > maxStats.HeapObjects {
+			maxStats.HeapObjects = memStats.HeapObjects
+			TracingRootSpan.SetTag("MemStats.HeapObjects.Max", maxStats.HeapObjects)
+		}
+
+		if memStats.StackInuse > maxStats.StackInuse {
+			maxStats.StackInuse = memStats.StackInuse
+			TracingRootSpan.SetTag("MemStats.StackInuse.Max", maxStats.StackInuse)
+		}
+
+		if memStats.StackSys > maxStats.StackSys {
+			maxStats.StackSys = memStats.StackSys
+			TracingRootSpan.SetTag("MemStats.StackSys.Max", maxStats.StackSys)
+		}
+	}
+
+	interval := os.Getenv("PULUMI_TRACING_MEMSTATS_POLL_INTERVAL")
+
+	if interval != "" {
+		intervalDuration, err := time.ParseDuration(interval)
+		if err == nil {
+			for {
+				poll()
+				time.Sleep(intervalDuration)
+			}
+		}
+	}
+}

sdk/nodejs/runtime/rpc.ts

@@ -628,7 +628,7 @@ export function register<T extends { readonly version?: string }>(source: Map<st
         for (const existing of items) {
             if (sameVersion(existing.version, item.version)) {
                 // It is possible for the same version of the same provider SDK to be loaded multiple times in Node.js.
-                // In this case, we might legitimately get mutliple registrations of the same resource.  It should not
+                // In this case, we might legitimately get multiple registrations of the same resource.  It should not
                 // matter which we use, so we can just skip re-registering.  De-serialized resources will always be
                 // instances of classes from the first registered package.
                 if (excessiveDebugOutput) {