Add river bench benchmarking tool producing succinct output + summary

[brandur]

Here, add a new benchmarking tool to the main River CLI. We had an
existing one, but it hasn't been used or updated in ages, and was
written quite quickly, without too much concern for UX.

This river bench is user-runnable, and designed to produce output
that's succinct and easily comprehensible. Every two seconds it produces
a new line of output with the number of jobs worked during that period,
number of jobs inserted during that period, and the rough jobs per
second being complete. When the program is interrupted via SIGINT, it
produces one final log line indicating similar information, but
calculated across the entire run period.

$ go run main.go bench --database-url $DATABASE_URL
bench: jobs worked [          0 ], inserted [      50000 ], job/sec [        0.0 ] [0s]
bench: jobs worked [      22445 ], inserted [      22000 ], job/sec [    11222.5 ] [2s]
bench: jobs worked [      26504 ], inserted [      28000 ], job/sec [    13252.0 ] [2s]
bench: jobs worked [      25919 ], inserted [      24000 ], job/sec [    12959.5 ] [2s]
bench: jobs worked [      27432 ], inserted [      28000 ], job/sec [    13716.0 ] [2s]
bench: jobs worked [      26068 ], inserted [      26000 ], job/sec [    13034.0 ] [2s]
bench: jobs worked [      27068 ], inserted [      28000 ], job/sec [    13534.0 ] [2s]
bench: jobs worked [      27876 ], inserted [      28000 ], job/sec [    13938.0 ] [2s]
bench: jobs worked [      25058 ], inserted [      24000 ], job/sec [    12529.0 ] [2s]
^Cbench: total jobs worked [     214356 ], total jobs inserted [     264000 ], overall job/sec [    13026.7 ], running 16.455185125s

It can also run with a total duration, which will be useful if we're
trying to compare runs across branches without having to try and time it
artificially:

$ go run main.go bench --database-url $DATABASE_URL --duration 30s
bench: jobs worked [          0 ], inserted [      50000 ], job/sec [        0.0 ] [0s]
bench: jobs worked [      23875 ], inserted [      24000 ], job/sec [    11937.5 ] [2s]
bench: jobs worked [      27964 ], inserted [      28000 ], job/sec [    13982.0 ] [2s]
bench: jobs worked [      25694 ], inserted [      26000 ], job/sec [    12847.0 ] [2s]
bench: jobs worked [      26649 ], inserted [      26000 ], job/sec [    13324.5 ] [2s]
bench: jobs worked [      26872 ], inserted [      28000 ], job/sec [    13436.0 ] [2s]
bench: jobs worked [      26519 ], inserted [      26000 ], job/sec [    13259.5 ] [2s]
bench: jobs worked [      25077 ], inserted [      24000 ], job/sec [    12538.5 ] [2s]
bench: jobs worked [      24126 ], inserted [      26000 ], job/sec [    12063.0 ] [2s]
bench: jobs worked [      23936 ], inserted [      22000 ], job/sec [    11968.0 ] [2s]
bench: jobs worked [      26044 ], inserted [      28000 ], job/sec [    13022.0 ] [2s]
bench: jobs worked [      26289 ], inserted [      26000 ], job/sec [    13144.5 ] [2s]
bench: jobs worked [      23058 ], inserted [      22000 ], job/sec [    11529.0 ] [2s]
bench: jobs worked [      23474 ], inserted [      24000 ], job/sec [    11737.0 ] [2s]
bench: jobs worked [      25380 ], inserted [      26000 ], job/sec [    12690.0 ] [2s]
bench: total jobs worked [     375743 ], total jobs inserted [     426000 ], overall job/sec [    12524.8 ], running 30.000017167s

Unlike the old benchmarking tool, we switch this one over to do job
accounting using a client subscribe channel instead of measuring it in
the worker. Measuring in the worker doesn't account for the time needed
to block in the job executor waiting for a goroutine to become available
in the completer to complete a job, making it less accurate and possibly
prone to memory overruns as a large backlog of jobs have been accounted
as completed but are actually waiting for a completer slot.

I'm not going to call this feature complete, but I think it's a step in
the right direction, and the hope is that it'll give us a reasonable way
to gutcheck new changes and see whether they cause an obvious regression
or improvement in total performance.

[brandur]

@bgentry Added a "burndown" mode that does all the insertion up front:

$ go run main.go bench --database-url $DATABASE_URL -n 1_000_000
bench: jobs worked [          0 ], inserted [    1000000 ], job/sec [        0.0 ] [0s]
bench: jobs worked [       2255 ], inserted [          0 ], job/sec [     1127.5 ] [2s]
bench: jobs worked [       3658 ], inserted [          0 ], job/sec [     1829.0 ] [2s]
bench: jobs worked [       4450 ], inserted [          0 ], job/sec [     2225.0 ] [2s]
bench: jobs worked [       4689 ], inserted [          0 ], job/sec [     2344.5 ] [2s]
bench: jobs worked [       4745 ], inserted [          0 ], job/sec [     2372.5 ] [2s]
bench: jobs worked [       4675 ], inserted [          0 ], job/sec [     2337.5 ] [2s]
bench: jobs worked [       4704 ], inserted [          0 ], job/sec [     2352.0 ] [2s]
bench: jobs worked [       4614 ], inserted [          0 ], job/sec [     2307.0 ] [2s]
bench: jobs worked [       4611 ], inserted [          0 ], job/sec [     2305.5 ] [2s]
^Cbench: total jobs worked [      41704 ], total jobs inserted [    1000000 ], overall job/sec [     2142.0 ], running 19.469791417s

IMO the normal mode is more useful because it better simulates a real queue that's getting new insertions and working existing jobs, but the alternative is available in case it's needed.

[bgentry]

LGTM aside from comments, good stuff 👏

[bgentry]

aaaaWe'd probably want to make this MaxWorkers param an argument to the bench command. Setting it to 10k is probably not realistic, and it would probably be useful to play around with different input values to find the sweet spot on throughput.

The fetch cooldown is another attr that's probably worth setting up as an input variable to this. A queue that's optimized for throughput is going to have a much shorter & more aggressive fetch cooldown than most users would typically want (because it would have the tradeoff of constantly hitting the DB to fetch more jobs).

I would suggest setting these each to a specific default that doesn't necessarily map to River's own defaults, because those defaults are likely going to be what's better for a large number of smaller users than the small percentage of users chasing max throughput. But if your purpose is actually to gauge throughput, you'll want some different values.

[brandur]

Ah, good call on this one. I chose the max workers after num CPUs performed very poorly, and never reevaluated.

I played around with the numbers quite a bit, and although I wouldn't suggest these are perfect, ended up with some that perform quite well (much better than what I'd had here before). I'm sure more refinement is possible, but will leave that as a future improvement.

	client, err := river.NewClient(b.driver, &river.Config{
		// When benchmarking to maximize job throughput these numbers have an
		// outside effect on results. The ones chosen here could possibly be
		// optimized further, but based on my tests of throwing a lot of random
		// values against the wall, they perform quite well. Much better than
		// the client's default values at any rate.
		FetchCooldown:     2 * time.Millisecond,
		FetchPollInterval: 5 * time.Millisecond,

		Logger: slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelWarn})),
		Queues: map[string]river.QueueConfig{
			// This could probably use more refinement, but in my quick and
			// dirty tests I found that roughly 1k workers was most optimal. 500
			// and 2,000 performed a little more poorly, and jumping up to the
			// 10k performed considerably less well (scheduler contention?).
			// There may be a more optimal number than 1,000, but it seems close
			// enough to target for now.
			river.QueueDefault: {MaxWorkers: 1_000},
		},
		Workers: workers,
	})

[bgentry]

seems like this is outdated diff?

[brandur]

Ugh, I thought so too, but that's what go mod tidy produces. The ULID dep should be dropped next time we cut a release and can target the River CLI Go submodule against it.

[brandur]

Thanks!