bench/rttanalysis: stop printing text trace, write jaeger

This commit changes the behavior on failure of the rttanalysis tests.
Before it would print a textual trace. That was pretty much useless and
it was very loud. Now it'll write the jaeger trace json to a file in the
logging directory. Hopefully that'll be more useful to inspect the difference
between the expectation and the observed result.

Release note: None

pkg/bench/rttanalysis/rtt_analysis_bench.go

@@ -12,13 +12,16 @@ package rttanalysis
 
 import (
 	"context"
+	"io/ioutil"
+	"path/filepath"
 	"strings"
 	"sync"
 	"testing"
 
 	"github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord"
 	"github.com/cockroachdb/cockroach/pkg/testutils/skip"
 	"github.com/cockroachdb/cockroach/pkg/testutils/sqlutils"
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/quotapool"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing"
 	"github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
@@ -50,6 +53,7 @@ func runRoundTripBenchmark(b testingB, tests []RoundTripBenchTestCase, cc Cluste
 // concurrency.
 func runRoundTripBenchmarkTest(
 	t *testing.T,
+	scope *log.TestLogScope,
 	results *resultSet,
 	tests []RoundTripBenchTestCase,
 	cc ClusterConstructor,
@@ -63,7 +67,7 @@ func runRoundTripBenchmarkTest(
 		go func(tc RoundTripBenchTestCase) {
 			defer wg.Done()
 			t.Run(tc.Name, func(t *testing.T) {
-				runRoundTripBenchmarkTestCase(t, results, tc, cc, numRuns, limit)
+				runRoundTripBenchmarkTestCase(t, scope, results, tc, cc, numRuns, limit)
 			})
 		}(tc)
 	}
@@ -72,6 +76,7 @@ func runRoundTripBenchmarkTest(
 
 func runRoundTripBenchmarkTestCase(
 	t *testing.T,
+	scope *log.TestLogScope,
 	results *resultSet,
 	tc RoundTripBenchTestCase,
 	cc ClusterConstructor,
@@ -86,15 +91,18 @@ func runRoundTripBenchmarkTestCase(
 		go func() {
 			defer wg.Done()
 			defer alloc.Release()
-			executeRoundTripTest(tShim{T: t, results: results}, tc, cc)
+			executeRoundTripTest(tShim{
+				T: t, results: results, scope: scope,
+			}, tc, cc)
 		}()
 	}
 	wg.Wait()
 }
 
 // executeRoundTripTest executes a RoundTripBenchCase on with the provided SQL runner
 func executeRoundTripTest(b testingB, tc RoundTripBenchTestCase, cc ClusterConstructor) {
-	defer b.logScope()()
+	getDir, cleanup := b.logScope()
+	defer cleanup()
 
 	cluster := cc(b)
 	defer cluster.close()
@@ -139,11 +147,15 @@ func executeRoundTripTest(b testingB, tc RoundTripBenchTestCase, cc ClusterConst
 	}
 
 	res := float64(roundTrips) / float64(b.N())
+
 	if haveExp && !exp.matches(int(res)) && !*rewriteFlag {
-		b.Errorf(`got %v, expected %v. trace:
-%v
-(above trace from test %s. got %v, expected %v)
-`, res, exp, r, b.Name(), res, exp)
+		b.Errorf(`%s: got %v, expected %v`, b.Name(), res, exp)
+		dir := getDir()
+		jaegerJSON, err := r.ToJaegerJSON(tc.Stmt, "", "n0")
+		require.NoError(b, err)
+		path := filepath.Join(dir, strings.Replace(b.Name(), "/", "_", -1)) + ".jaeger.json"
+		require.NoError(b, ioutil.WriteFile(path, []byte(jaegerJSON), 0666))
+		b.Errorf("wrote jaeger trace to %s", path)
 	}
 	b.ReportMetric(res, roundTripsMetric)
 }

pkg/bench/rttanalysis/testing_shims.go

@@ -28,7 +28,7 @@ type testingB interface {
 
 	// logScope is used to wrap log.Scope and make it available only in
 	// appropriate contexts.
-	logScope() func()
+	logScope() (getDirectory func() string, close func())
 }
 
 type bShim struct {
@@ -37,9 +37,9 @@ type bShim struct {
 
 var _ testingB = bShim{}
 
-func (b bShim) logScope() func() {
+func (b bShim) logScope() (getDirectory func() string, close func()) {
 	sc := log.Scope(b)
-	return func() { sc.Close(b) }
+	return sc.GetDirectory, func() { sc.Close(b) }
 }
 func (b bShim) N() int { return b.B.N }
 func (b bShim) Run(name string, f func(b testingB)) {
@@ -54,13 +54,17 @@ func (b bShim) Run(name string, f func(b testingB)) {
 // execution.
 type tShim struct {
 	*testing.T
+	scope   *log.TestLogScope
 	results *resultSet
 }
 
 var _ testingB = tShim{}
 
-func (ts tShim) logScope() func() {
-	return func() {}
+func (ts tShim) logScope() (getDirectory func() string, close func()) {
+	return ts.scope.GetDirectory, func() {}
+}
+func (ts tShim) GetDirectory() string {
+	return ts.scope.GetDirectory()
 }
 func (ts tShim) N() int      { return 1 }
 func (ts tShim) ResetTimer() {}
@@ -81,6 +85,6 @@ func (ts tShim) Name() string {
 }
 func (ts tShim) Run(s string, f func(testingB)) {
 	ts.T.Run(s, func(t *testing.T) {
-		f(tShim{results: ts.results, T: t})
+		f(tShim{results: ts.results, T: t, scope: ts.scope})
 	})
 }

pkg/bench/rttanalysis/validate_benchmark_data.go

@@ -66,7 +66,8 @@ func runBenchmarkExpectationTests(t *testing.T, r *Registry) {
 	}
 
 	// Only create the scope after we've checked if we need to exec the subprocess.
-	defer log.Scope(t).Close(t)
+	scope := log.Scope(t)
+	defer scope.Close(t)
 
 	defer func() {
 		if t.Failed() {
@@ -88,7 +89,7 @@ func runBenchmarkExpectationTests(t *testing.T, r *Registry) {
 				if isRewrite {
 					runs = *rewriteIterations
 				}
-				runRoundTripBenchmarkTest(t, &results, cases, r.cc, runs, limiter)
+				runRoundTripBenchmarkTest(t, scope, &results, cases, r.cc, runs, limiter)
 			})
 		}(b, cases)
 	}