sweet: reduce length of TestSweetEndToEnd

This test is failing on the LUCI builders because it's running out the
default timeout, and timeouts for subrepos haven't been ported there
yet.

Surprisingly, this is the only repository that runs out the default
clock. This prompted me to look into where time is spent in this test,
and I noticed that the etcd benchmark didn't use the -short flag at all
(!).

In addition to making use of -short in the etcd benchmark, this change
also fiddles around with other benchmarks' use of the -short flag to
make the test slightly shorter. The net decrease in time spent on my
local machine is 25% (5m -> 3m45s).

The test is also tweaked to allow more of the small benchmarks to run in
parallel during the test.

Finally, this change adds timing logs to the test, so when it next times
out we have a better idea as to why.

Change-Id: I7e394e675fd767d13778d934584c12ce23675c01
Reviewed-on: https://go-review.googlesource.com/c/benchmarks/+/506556
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>
Run-TryBot: Michael Knyszek <mknyszek@google.com>

sweet/benchmarks/etcd/main.go

@@ -176,6 +176,8 @@ type benchmark struct {
 	name       string
 	reportName string
 	args       []string
+	longArgs   []string // if !config.short
+	shortArgs  []string // if config.short
 }
 
 var benchmarks = []benchmark{
@@ -190,9 +192,14 @@ var benchmarks = []benchmark{
 			"put",
 			"--key-size=8",
 			"--sequential-keys",
-			"--total=100000",
 			"--val-size=256",
 		},
+		longArgs: []string{
+			"--total=100000",
+		},
+		shortArgs: []string{
+			"--total=1000",
+		},
 	},
 	{
 		name:       "stm",
@@ -204,9 +211,14 @@ var benchmarks = []benchmark{
 			"stm",
 			"--keys=1000",
 			"--keys-per-txn=2",
-			"--total=100000",
 			"--val-size=8",
 		},
+		longArgs: []string{
+			"--total=100000",
+		},
+		shortArgs: []string{
+			"--total=1000",
+		},
 	},
 }
 
@@ -216,6 +228,11 @@ func runBenchmark(b *driver.B, cfg *config, instances []*etcdInstance) (err erro
 		hosts = append(hosts, inst.host(clientPort))
 	}
 	args := append([]string{"--endpoints", strings.Join(hosts, ",")}, cfg.bench.args...)
+	if cfg.short {
+		args = append(args, cfg.bench.shortArgs...)
+	} else {
+		args = append(args, cfg.bench.longArgs...)
+	}
 	cmd := exec.Command(cfg.benchmarkBin, args...)
 
 	var stdout, stderr bytes.Buffer

sweet/benchmarks/gopher-lua/main.go

@@ -64,12 +64,12 @@ func doBenchmark(s *lua.LState, input lua.LString) error {
 	if err := s.CallByParam(freq, input, lua.LNumber(1)); err != nil {
 		return err
 	}
-	if err := s.CallByParam(freq, input, lua.LNumber(2)); err != nil {
-		return err
-	}
 	if short {
 		return nil
 	}
+	if err := s.CallByParam(freq, input, lua.LNumber(2)); err != nil {
+		return err
+	}
 	if err := s.CallByParam(count, input, lua.LString("GGT")); err != nil {
 		return err
 	}

sweet/benchmarks/tile38/main.go

@@ -331,7 +331,7 @@ func run(cfg *config) (err error) {
 	}
 	iters := 40 * 50000
 	if cfg.short {
-		iters = 1000
+		iters = 100
 	}
 	return driver.RunBenchmark(benchName, func(d *driver.B) error {
 		if driver.DiagnosticEnabled(diagnostics.Trace) {

sweet/cmd/sweet/integration_test.go

@@ -14,6 +14,7 @@ import (
 	"strings"
 	"sync"
 	"testing"
+	"time"
 
 	"golang.org/x/benchmarks/sweet/common"
 	"golang.org/x/sync/semaphore"
@@ -26,6 +27,16 @@ func TestSweetEndToEnd(t *testing.T) {
 	if testing.Short() {
 		t.Skip("the full Sweet end-to-end experience takes several minutes")
 	}
+
+	// Timing state for timeout debug logging.
+	testStartTime := time.Now()
+	lastTime := testStartTime
+	phaseDone := func(name string) {
+		now := time.Now()
+		t.Logf("phase %s @%s (duration: %s)", name, lastTime.Sub(testStartTime), now.Sub(lastTime))
+		lastTime = now
+	}
+
 	goRoot := os.Getenv("GOROOT")
 	if goRoot == "" {
 		data, err := exec.Command("go", "env", "GOROOT").Output()
@@ -87,6 +98,8 @@ func TestSweetEndToEnd(t *testing.T) {
 		}
 	}()
 
+	phaseDone("setup")
+
 	// Download assets.
 	getCmd := exec.Command(sweetBin, "get",
 		"-auth", "none",
@@ -98,6 +111,8 @@ func TestSweetEndToEnd(t *testing.T) {
 		t.Fatal(err)
 	}
 
+	phaseDone("sweet-get")
+
 	// TODO(mknyszek): Test regenerating assets. As it stands, the following
 	// parts of the test will fail if the source assets change, since they're
 	// prebuilt and baked into the assets archive. The only recourse is to
@@ -110,6 +125,12 @@ func TestSweetEndToEnd(t *testing.T) {
 
 	var outputMu sync.Mutex
 	runShard := func(shard, resultsDir, workDir string) {
+		startTime := time.Now()
+		defer func() {
+			endTime := time.Now()
+			t.Logf("\tphase sweet-run-%s @%s (duration: %s)", shard, startTime.Sub(testStartTime), endTime.Sub(startTime))
+		}()
+
 		args := []string{
 			"run",
 			"-run", shard,
@@ -163,16 +184,26 @@ func TestSweetEndToEnd(t *testing.T) {
 			t.Error(runErr)
 		}
 	}
+	type shard struct {
+		run    string
+		weight int64
+	}
 	// Limit parallelism to conserve memory.
-	sema := semaphore.NewWeighted(2)
+	sema := semaphore.NewWeighted(8)
 	var wg sync.WaitGroup
-	for i, shard := range []string{
-		"tile38", "go-build", "biogo-igor", "biogo-krishna", "etcd",
+	for i, shard := range []shard{
+		{"tile38", 4},
+		{"go-build", 4},
+		{"biogo-igor", 1},
+		{"biogo-krishna", 1},
+		{"etcd", 1},
+		{"bleve-index", 1},
+		{"gopher-lua", 1},
+		{"markdown", 1},
 		// TODO(go.dev/issue/51445): Enable once gVisor builds with Go 1.19.
-		// "gvisor",
-		"bleve-index,gopher-lua,markdown",
+		// {"gvisor", 1},
 	} {
-		sema.Acquire(context.Background(), 1)
+		sema.Acquire(context.Background(), shard.weight)
 		wg.Add(1)
 		go func(i int, shard string) {
 			defer sema.Release(1)
@@ -180,9 +211,11 @@ func TestSweetEndToEnd(t *testing.T) {
 			resultsDir := filepath.Join(tmpDir, fmt.Sprintf("results-%d", i))
 			workDir := filepath.Join(tmpDir, fmt.Sprintf("tmp-%d", i))
 			runShard(shard, resultsDir, workDir)
-		}(i, shard)
+		}(i, shard.run)
 	}
 	wg.Wait()
+
+	phaseDone("sweet-run")
 }
 
 func makeConfigFile(t *testing.T, goRoot string) string {

sweet/harnesses/local.go

@@ -79,14 +79,19 @@ func BleveIndex() common.Harness {
 	return &localBenchHarness{
 		binName: "bleve-index-bench",
 		genArgs: func(cfg *common.Config, rcfg *common.RunConfig) []string {
-			args := []string{
-				"-batch-size", "100",
-				filepath.Join(rcfg.AssetsDir, "enwiki-20080103-pages-articles.xml.bz2"),
-			}
+			var args []string
 			if rcfg.Short {
-				args = append([]string{"-documents", "100"}, args...)
+				args = []string{
+					"-documents", "10",
+					"-batch-size", "10",
+				}
+			} else {
+				args = []string{
+					"-documents", "1000",
+					"-batch-size", "100",
+				}
 			}
-			return args
+			return append(args, filepath.Join(rcfg.AssetsDir, "enwiki-20080103-pages-articles.xml.bz2"))
 		},
 	}
 }