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>
diff --git a/sweet/benchmarks/etcd/main.go b/sweet/benchmarks/etcd/main.go
index e82e176..b132185 100644
--- a/sweet/benchmarks/etcd/main.go
+++ b/sweet/benchmarks/etcd/main.go
@@ -176,6 +176,8 @@
 	name       string
 	reportName string
 	args       []string
+	longArgs   []string // if !config.short
+	shortArgs  []string // if config.short
 }
 
 var benchmarks = []benchmark{
@@ -190,9 +192,14 @@
 			"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 @@
 			"stm",
 			"--keys=1000",
 			"--keys-per-txn=2",
-			"--total=100000",
 			"--val-size=8",
 		},
+		longArgs: []string{
+			"--total=100000",
+		},
+		shortArgs: []string{
+			"--total=1000",
+		},
 	},
 }
 
@@ -216,6 +228,11 @@
 		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
diff --git a/sweet/benchmarks/gopher-lua/main.go b/sweet/benchmarks/gopher-lua/main.go
index 88c50c7..5e3d735 100644
--- a/sweet/benchmarks/gopher-lua/main.go
+++ b/sweet/benchmarks/gopher-lua/main.go
@@ -64,12 +64,12 @@
 	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
 	}
diff --git a/sweet/benchmarks/tile38/main.go b/sweet/benchmarks/tile38/main.go
index e755fdb..f65870c 100644
--- a/sweet/benchmarks/tile38/main.go
+++ b/sweet/benchmarks/tile38/main.go
@@ -331,7 +331,7 @@
 	}
 	iters := 40 * 50000
 	if cfg.short {
-		iters = 1000
+		iters = 100
 	}
 	return driver.RunBenchmark(benchName, func(d *driver.B) error {
 		if driver.DiagnosticEnabled(diagnostics.Trace) {
diff --git a/sweet/cmd/sweet/integration_test.go b/sweet/cmd/sweet/integration_test.go
index d13ed70..a3fb992 100644
--- a/sweet/cmd/sweet/integration_test.go
+++ b/sweet/cmd/sweet/integration_test.go
@@ -14,6 +14,7 @@
 	"strings"
 	"sync"
 	"testing"
+	"time"
 
 	"golang.org/x/benchmarks/sweet/common"
 	"golang.org/x/sync/semaphore"
@@ -26,6 +27,16 @@
 	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 @@
 		}
 	}()
 
+	phaseDone("setup")
+
 	// Download assets.
 	getCmd := exec.Command(sweetBin, "get",
 		"-auth", "none",
@@ -98,6 +111,8 @@
 		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 @@
 
 	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 @@
 			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 @@
 			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 {
diff --git a/sweet/harnesses/local.go b/sweet/harnesses/local.go
index d3a0022..af1d71c 100644
--- a/sweet/harnesses/local.go
+++ b/sweet/harnesses/local.go
@@ -79,14 +79,19 @@
 	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"))
 		},
 	}
 }