Improvements from Buildkit instrumentation (#214)

* Add an 'SetTestCodeFromCaller' API to set the test code

* Get exact test start time

* Bump agent pre version

* Add an 'SetTestCodeFromCaller' API to set the test code

* Get exact test start time

* Bump agent pre version

* Agent benchmark test

* Logger patch benchmark

* SetTestCodeFromCallerSkip and SetTestCodeFromFunc

* Test instrumentation init benchmark

* Benchmark dependencies and git tests

* Benchmark monkey patching testing logger

* Test and Benchmark Logger Patcher

* Reflection test

* ParallelByReflection test

* remove data race

* Remove reflection.Value arguments usage outside the dynamic func call

* format fixes

* test fix

* Fix util tests

Author: tonyredondo

agent/agent.go

@@ -62,7 +62,7 @@ type (
 )
 
 var (
-	version = "0.1.16-pre1"
+	version = "0.1.16-pre2"
 
 	testingModeFrequency    = time.Second
 	nonTestingModeFrequency = time.Minute

agent/agent_test.go

@@ -5,6 +5,7 @@ import (
 	"os/exec"
 	"reflect"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 
@@ -141,3 +142,27 @@ func TestTildeExpandRaceMetadata(t *testing.T) {
 	<-time.After(5 * time.Second)
 	agent.Stop()
 }
+
+var a *Agent
+
+func BenchmarkNewAgent(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		var err error
+		a, err = NewAgent(WithTestingModeEnabled(),
+			WithHandlePanicAsFail(),
+			WithRetriesOnFail(3),
+			WithSetGlobalTracer())
+		if err != nil {
+			b.Fatal(err)
+		}
+		span := a.Tracer().StartSpan("Test")
+		span.SetTag("span.kind", "test")
+		span.SetTag("test.name", "BenchNewAgent")
+		span.SetTag("test.suite", "root")
+		span.SetTag("test.status", tags.TestStatus_PASS)
+		span.SetBaggageItem("trace.kind", "test")
+		span.Finish()
+		once = sync.Once{}
+		a.Stop()
+	}
+}

agent/dependencies_test.go

@@ -0,0 +1,11 @@
+package agent
+
+import "testing"
+
+var mp map[string]string
+
+func BenchmarkGetDependencyMap(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		mp = getDependencyMap()
+	}
+}

agent/git_test.go

@@ -108,3 +108,18 @@ func TestMergeRegex(t *testing.T) {
 		}
 	}
 }
+
+var data *GitData
+var diff *GitDiff
+
+func BenchmarkGetGitData(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		data = getGitData()
+	}
+}
+
+func BenchmarkGetGitDiff(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		diff = getGitDiff()
+	}
+}

go.mod

@@ -15,13 +15,10 @@ require (
 	github.com/stretchr/testify v1.5.1
 	github.com/undefinedlabs/go-mpatch v0.0.0-20200326085307-1a86426f42a6
 	github.com/vmihailenco/msgpack v4.0.4+incompatible
-	golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3 // indirect
 	golang.org/x/net v0.0.0-20200301022130-244492dfa37a
 	golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527 // indirect
-	golang.org/x/tools v0.0.0-20190524140312-2c0ae7006135 // indirect
 	google.golang.org/appengine v1.6.5 // indirect
 	google.golang.org/grpc v1.27.1
 	gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 // indirect
 	gopkg.in/tomb.v2 v2.0.0-20161208151619-d5d1b5820637
-	honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc // indirect
 )

init.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"os"
 	"os/signal"
+	"reflect"
 	"runtime"
 	"sync"
 	"syscall"
@@ -75,6 +76,32 @@ func GetContextFromTest(t *testing.T) context.Context {
 	return context.TODO()
 }
 
+// Sets the test code from the caller of this func
+func SetTestCodeFromCaller(t *testing.T) {
+	SetTestCodeFromCallerSkip(t, 1)
+}
+
+// Sets the test code from the caller of this func
+func SetTestCodeFromCallerSkip(t *testing.T, skip int) {
+	test := GetTest(t)
+	if test == nil {
+		return
+	}
+	pc, _, _, _ := runtime.Caller(skip + 1)
+	test.SetTestCode(pc)
+}
+
+// Sets the test code from a func
+func SetTestCodeFromFunc(t *testing.T, fn interface{}) {
+	test := GetTest(t)
+	if test == nil {
+		return
+	}
+	value := reflect.ValueOf(fn)
+	pc := value.Pointer()
+	test.SetTestCode(pc)
+}
+
 // Gets the *Benchmark from a *testing.B
 func GetBenchmark(b *testing.B) *scopetesting.Benchmark {
 	return scopetesting.GetBenchmark(b)

instrumentation/logging/logger_test.go

@@ -132,3 +132,20 @@ func checkMessage(msg string, records []opentracing.LogRecord) bool {
 	}
 	return false
 }
+
+func BenchmarkPatchStandardLogger(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		PatchStandardLogger()
+		UnpatchStandardLogger()
+	}
+}
+
+var lg *stdlog.Logger
+
+func BenchmarkPatchLogger(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		lg = stdlog.New(os.Stdout, "", stdlog.Llongfile|stdlog.Lmicroseconds)
+		PatchLogger(lg)
+		UnpatchLogger(lg)
+	}
+}

instrumentation/testing/benchmark.go

@@ -111,8 +111,10 @@ func startBenchmark(b *testing.B, pc uintptr, benchFunc func(b *testing.B)) {
 		fullTestName = strings.Join(nameSegments, "/")
 	}
 	packageName := reflection.GetBenchmarkSuiteName(b)
+	pName, _, tCode := getPackageAndNameAndBoundaries(pc)
+
 	if packageName == "" {
-		packageName = getPackageName(pc, fullTestName)
+		packageName = pName
 	}
 
 	oTags := opentracing.Tags{
@@ -124,9 +126,8 @@ func startBenchmark(b *testing.B, pc uintptr, benchFunc func(b *testing.B)) {
 		"test.type":      "benchmark",
 	}
 
-	testCode := getTestCodeBoundaries(pc, fullTestName)
-	if testCode != "" {
-		oTags["test.code"] = testCode
+	if tCode != "" {
+		oTags["test.code"] = tCode
 	}
 
 	var startOptions []opentracing.StartSpanOption

instrumentation/testing/logger.go

@@ -52,84 +52,82 @@ func UnpatchTestingLogger() {
 }
 
 func patchError() {
-	patch("Error", func(test *Test, argsValues []reflect.Value) {
+	patch("Error", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		args := getArgs(argsValues[0])
 		test.Error(args...)
 	})
 }
 
 func patchErrorf() {
-	patch("Errorf", func(test *Test, argsValues []reflect.Value) {
+	patch("Errorf", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		format := argsValues[0].String()
-		args := getArgs(argsValues[1])
-		test.Errorf(format, args...)
+		format := args[0].(string)
+		test.Errorf(format, args[1:]...)
 	})
 }
 
 func patchFatal() {
-	patch("Fatal", func(test *Test, argsValues []reflect.Value) {
+	patch("Fatal", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		args := getArgs(argsValues[0])
 		test.Fatal(args...)
 	})
 }
 
 func patchFatalf() {
-	patch("Fatalf", func(test *Test, argsValues []reflect.Value) {
+	patch("Fatalf", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		format := argsValues[0].String()
-		args := getArgs(argsValues[1])
-		test.Fatalf(format, args...)
+		format := args[0].(string)
+		test.Fatalf(format, args[1:]...)
 	})
 }
 
 func patchLog() {
-	patch("Log", func(test *Test, argsValues []reflect.Value) {
+	patch("Log", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		args := getArgs(argsValues[0])
 		test.Log(args...)
 	})
 }
 
 func patchLogf() {
-	patch("Logf", func(test *Test, argsValues []reflect.Value) {
+	patch("Logf", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		format := argsValues[0].String()
-		args := getArgs(argsValues[1])
-		test.Logf(format, args...)
+		format := args[0].(string)
+		test.Logf(format, args[1:]...)
 	})
 }
 
 func patchSkip() {
-	patch("Skip", func(test *Test, argsValues []reflect.Value) {
+	patch("Skip", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		args := getArgs(argsValues[0])
 		test.Skip(args...)
 	})
 }
 
 func patchSkipf() {
-	patch("Skipf", func(test *Test, argsValues []reflect.Value) {
+	patch("Skipf", func(test *Test, args []interface{}) {
 		test.t.Helper()
-		format := argsValues[0].String()
-		args := getArgs(argsValues[1])
-		test.Skipf(format, args...)
+		format := args[0].(string)
+		test.Skipf(format, args[1:]...)
 	})
 }
 
-func getArgs(in reflect.Value) []interface{} {
+func createArgs(in []reflect.Value) []interface{} {
 	var args []interface{}
-	if in.Kind() == reflect.Slice {
-		for i := 0; i < in.Len(); i++ {
-			args = append(args, in.Index(i).Interface())
+	for _, item := range in {
+		if item.Kind() == reflect.Slice {
+			var itemArg []interface{}
+			for i := 0; i < item.Len(); i++ {
+				itemArg = append(itemArg, item.Index(i).Interface())
+			}
+			args = append(args, itemArg)
+		} else {
+			args = append(args, item.Interface())
 		}
 	}
 	return args
 }
 
-func patch(methodName string, methodBody func(test *Test, argsValues []reflect.Value)) {
+func patch(methodName string, methodBody func(test *Test, argsValues []interface{})) {
 	patchesMutex.Lock()
 	defer patchesMutex.Unlock()
 	patchPointersMutex.Lock()
@@ -144,6 +142,7 @@ func patch(methodName string, methodBody func(test *Test, argsValues []reflect.V
 	var methodPatch *mpatch.Patch
 	var err error
 	methodPatch, err = mpatch.PatchMethodWithMakeFunc(method, func(in []reflect.Value) []reflect.Value {
+		argIn := createArgs(in[1:])
 		t := (*testing.T)(unsafe.Pointer(in[0].Pointer()))
 		if t == nil {
 			instrumentation.Logger().Println("testing.T is nil")
@@ -161,7 +160,7 @@ func patch(methodName string, methodBody func(test *Test, argsValues []reflect.V
 			instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name())
 			return nil
 		}
-		methodBody(test, in[1:])
+		methodBody(test, argIn)
 		return nil
 	})
 	logOnError(err)

instrumentation/testing/testing.go

@@ -19,14 +19,16 @@ import (
 	"go.undefinedlabs.com/scopeagent/reflection"
 	"go.undefinedlabs.com/scopeagent/runner"
 	"go.undefinedlabs.com/scopeagent/tags"
+	"go.undefinedlabs.com/scopeagent/tracer"
 )
 
 type (
 	Test struct {
 		testing.TB
-		ctx  context.Context
-		span opentracing.Span
-		t    *testing.T
+		ctx    context.Context
+		span   opentracing.Span
+		t      *testing.T
+		codePC uintptr
 	}
 
 	Option func(*Test)
@@ -64,6 +66,7 @@ func StartTestFromCaller(t *testing.T, pc uintptr, opts ...Option) *Test {
 		// If there is already one we want to replace it, so we clear the context
 		test.ctx = context.Background()
 	}
+	test.codePC = pc
 
 	for _, opt := range opts {
 		opt(test)
@@ -72,17 +75,16 @@ func StartTestFromCaller(t *testing.T, pc uintptr, opts ...Option) *Test {
 	// Extracting the testing func name (by removing any possible sub-test suffix `{test_func}/{sub_test}`)
 	// to search the func source code bounds and to calculate the package name.
 	fullTestName := runner.GetOriginalTestName(t.Name())
-	packageName := getPackageName(pc, fullTestName)
+	pName, _, testCode := getPackageAndNameAndBoundaries(pc)
 
 	testTags := opentracing.Tags{
 		"span.kind":      "test",
 		"test.name":      fullTestName,
-		"test.suite":     packageName,
+		"test.suite":     pName,
 		"test.framework": "testing",
 		"test.language":  "go",
 	}
 
-	testCode := getTestCodeBoundaries(pc, fullTestName)
 	if testCode != "" {
 		testTags["test.code"] = testCode
 	}
@@ -102,6 +104,15 @@ func StartTestFromCaller(t *testing.T, pc uintptr, opts ...Option) *Test {
 	return test
 }
 
+// Set test code
+func (test *Test) SetTestCode(pc uintptr) {
+	pName, _, fBoundaries := getPackageAndNameAndBoundaries(pc)
+	test.span.SetTag("test.suite", pName)
+	if fBoundaries != "" {
+		test.span.SetTag("test.code", fBoundaries)
+	}
+}
+
 // Ends the current test
 func (test *Test) End() {
 	autoInstrumentedTestsMutex.RLock()
@@ -135,6 +146,15 @@ func (test *Test) Run(name string, f func(t *testing.T)) bool {
 func (test *Test) end() {
 	finishTime := time.Now()
 
+	// If we have our own implementation of the span, we can set the exact start time from the test
+	if ownSpan, ok := test.span.(tracer.Span); ok {
+		if startTime, err := reflection.GetTestStartTime(test.t); err == nil {
+			ownSpan.SetStart(startTime)
+		} else {
+			instrumentation.Logger().Printf("error: %v", err)
+		}
+	}
+
 	// Remove the Test struct from the hash map, so a call to Start while we end this instance will create a new struct
 	removeTest(test.t)
 	// Stop and get records generated by loggers