Run and test benchmarks against C# as well

[RReverser]

Description of Changes

Turns out, there are some APIs that are not covered by any of our tests, except benchmarks.

Benchmarks are executed as both actual benchmarks and as integration tests for Rust, but not for C#. This PR fixes that to ensure that both Rust and C# are tested and measured on the CI from now on.

It also makes some adjustments to integration tests themselves, in particular fixes an issue where in integration tests reducers would be called but the response would never be read, so if a reducer panics, the tests would still succeed. Additionally, on failures the SpacetimeDB logs will be read and added to the error message so that you get a useful stacktrace from the module itself.

I also had to adjust some benchmark numbers (in particular, for ia_loop) since they were already very slow on CI for Rust, but become even more so for C#. The new loads are much lower, but should still be very usable for benchmark comparisons.

The only remaining issue is that the benchmark names have changed, and the benchmark comparison tool tries to compare mismatched pairs - I'm not sure what the solution to this is. cc @kazimuth

API and ABI breaking changes

If this is an API or ABI breaking change, please apply the
corresponding GitHub label.

Expected complexity level and risk

How complicated do you think these changes are? Grade on a scale from 1 to 5,
where 1 is a trivial change, and 5 is a deep-reaching and complex change.

This complexity rating applies not only to the complexity apparent in the diff,
but also to its interactions with existing and future code.

If you answered more than a 2, explain what is complex about the PR,
and what other components it interacts with in potentially concerning ways.

Testing

Describe any testing you've done, and any testing you'd like your reviewers to do,
so that you're confident that all the changes work as expected!

• Write a test you've completed here.
• Write a test you want a reviewer to do here, so they can check it off when they're satisfied.

[RReverser]

@kazimuth FWIW this is marked as draft because it's not quite ready to look at. I only created a PR because without it our CI doesn't run on branches :)

[kazimuth]

Well, looks good to me so far :)

[RReverser]

benchmarks please

[RReverser]

The failure here is the one that will be fixed by #1987.

[github-actions]

Criterion benchmark results

Criterion benchmark report

YOU SHOULD PROBABLY IGNORE THESE RESULTS.

Criterion is a wall time based benchmarking system that is extremely noisy when run on CI. We collect these results for longitudinal analysis, but they are not reliable for comparing individual PRs.

Go look at the callgrind report instead.

empty

db	on disk	new latency	old latency	new throughput	old throughput
sqlite	💿	-	421.3±1.80ns	-	-
sqlite	🧠	-	413.6±1.18ns	-	-
stdb_raw	💿	773.1±0.78ns	779.3±3.76ns	-	-
stdb_raw	🧠	775.9±0.85ns	777.7±1.16ns	-	-

insert_1

db	on disk	schema	indices	preload	new latency	old latency	new throughput	old throughput

insert_bulk

db	on disk	schema	indices	preload	count	new latency	old latency	new throughput	old throughput
sqlite	💿	u32_u64_str	btree_each_column	2048	256	-	584.6±0.45µs	-	1710 tx/sec
sqlite	💿	u32_u64_str	unique_0	2048	256	-	150.0±0.52µs	-	6.5 Ktx/sec
sqlite	💿	u32_u64_u64	btree_each_column	2048	256	-	480.0±42.66µs	-	2.0 Ktx/sec
sqlite	💿	u32_u64_u64	unique_0	2048	256	-	136.6±1.01µs	-	7.1 Ktx/sec
sqlite	🧠	u32_u64_str	btree_each_column	2048	256	-	447.6±3.58µs	-	2.2 Ktx/sec
sqlite	🧠	u32_u64_str	unique_0	2048	256	-	126.9±0.36µs	-	7.7 Ktx/sec
sqlite	🧠	u32_u64_u64	btree_each_column	2048	256	-	368.0±0.24µs	-	2.7 Ktx/sec
sqlite	🧠	u32_u64_u64	unique_0	2048	256	-	104.6±0.54µs	-	9.3 Ktx/sec
stdb_raw	💿	u32_u64_str	btree_each_column	2048	256	591.9±26.82µs	601.7±20.50µs	1689 tx/sec	1661 tx/sec
stdb_raw	💿	u32_u64_str	unique_0	2048	256	485.7±25.34µs	473.7±19.44µs	2.0 Ktx/sec	2.1 Ktx/sec
stdb_raw	💿	u32_u64_u64	btree_each_column	2048	256	354.8±26.21µs	376.0±9.37µs	2.8 Ktx/sec	2.6 Ktx/sec
stdb_raw	💿	u32_u64_u64	unique_0	2048	256	337.8±21.79µs	343.8±8.88µs	2.9 Ktx/sec	2.8 Ktx/sec
stdb_raw	🧠	u32_u64_str	btree_each_column	2048	256	299.7±0.25µs	297.9±0.21µs	3.3 Ktx/sec	3.3 Ktx/sec
stdb_raw	🧠	u32_u64_str	unique_0	2048	256	231.9±0.33µs	228.8±0.41µs	4.2 Ktx/sec	4.3 Ktx/sec
stdb_raw	🧠	u32_u64_u64	btree_each_column	2048	256	239.2±0.10µs	239.1±0.20µs	4.1 Ktx/sec	4.1 Ktx/sec
stdb_raw	🧠	u32_u64_u64	unique_0	2048	256	212.5±0.39µs	207.0±0.25µs	4.6 Ktx/sec	4.7 Ktx/sec

iterate

db	on disk	schema	indices	new latency	old latency	new throughput	old throughput
sqlite	💿	u32_u64_str	unique_0	-	23.4±0.11µs	-	41.8 Ktx/sec
sqlite	💿	u32_u64_u64	unique_0	-	22.1±0.06µs	-	44.2 Ktx/sec
sqlite	🧠	u32_u64_str	unique_0	-	20.9±0.08µs	-	46.6 Ktx/sec
sqlite	🧠	u32_u64_u64	unique_0	-	19.5±0.08µs	-	50.2 Ktx/sec
stdb_raw	💿	u32_u64_str	unique_0	4.9±0.00µs	4.0±0.00µs	199.6 Ktx/sec	245.9 Ktx/sec
stdb_raw	💿	u32_u64_u64	unique_0	4.8±0.00µs	3.9±0.00µs	203.7 Ktx/sec	251.8 Ktx/sec
stdb_raw	🧠	u32_u64_str	unique_0	4.9±0.00µs	4.0±0.00µs	199.2 Ktx/sec	246.0 Ktx/sec
stdb_raw	🧠	u32_u64_u64	unique_0	4.8±0.00µs	3.9±0.00µs	203.8 Ktx/sec	251.8 Ktx/sec

find_unique

db	on disk	key type	preload	new latency	old latency	new throughput	old throughput

filter

db	on disk	key type	index strategy	load	count	new latency	old latency	new throughput	old throughput
sqlite	💿	string	index	2048	256	-	70.4±0.35µs	-	13.9 Ktx/sec
sqlite	💿	u64	index	2048	256	-	66.9±0.12µs	-	14.6 Ktx/sec
sqlite	🧠	string	index	2048	256	-	66.0±0.16µs	-	14.8 Ktx/sec
sqlite	🧠	u64	index	2048	256	-	60.0±0.28µs	-	16.3 Ktx/sec
stdb_raw	💿	string	index	2048	256	4.9±0.00µs	5.0±0.00µs	197.4 Ktx/sec	195.7 Ktx/sec
stdb_raw	💿	u64	index	2048	256	4.9±0.00µs	4.9±0.00µs	201.1 Ktx/sec	198.8 Ktx/sec
stdb_raw	🧠	string	index	2048	256	4.9±0.00µs	5.0±0.00µs	197.5 Ktx/sec	195.5 Ktx/sec
stdb_raw	🧠	u64	index	2048	256	4.8±0.00µs	4.9±0.00µs	201.4 Ktx/sec	198.7 Ktx/sec

serialize

schema	format	count	new latency	old latency	new throughput	old throughput
u32_u64_str	bflatn_to_bsatn_fast_path	100	3.6±0.00µs	3.9±0.01µs	26.6 Mtx/sec	24.7 Mtx/sec
u32_u64_str	bflatn_to_bsatn_slow_path	100	2.9±0.02µs	3.5±0.01µs	32.8 Mtx/sec	27.0 Mtx/sec
u32_u64_str	bsatn	100	16.0±0.04ns	15.6±0.17ns	5.8 Gtx/sec	6.0 Gtx/sec
u32_u64_str	bsatn	100	2.3±0.01µs	2.4±0.00µs	41.3 Mtx/sec	40.4 Mtx/sec
u32_u64_str	json	100	5.0±0.05µs	5.0±0.03µs	19.0 Mtx/sec	19.2 Mtx/sec
u32_u64_str	json	100	8.0±0.10µs	9.6±0.02µs	11.9 Mtx/sec	10.0 Mtx/sec
u32_u64_str	product_value	100	1019.7±9.21ns	1019.1±1.23ns	93.5 Mtx/sec	93.6 Mtx/sec
u32_u64_u64	bflatn_to_bsatn_fast_path	100	972.9±5.57ns	1010.7±8.08ns	98.0 Mtx/sec	94.4 Mtx/sec
u32_u64_u64	bflatn_to_bsatn_slow_path	100	2.4±0.00µs	2.8±0.00µs	39.5 Mtx/sec	34.5 Mtx/sec
u32_u64_u64	bsatn	100	15.6±0.01ns	14.8±0.01ns	6.0 Gtx/sec	6.3 Gtx/sec
u32_u64_u64	bsatn	100	1629.1±30.64ns	1826.3±19.44ns	58.5 Mtx/sec	52.2 Mtx/sec
u32_u64_u64	json	100	3.2±0.06µs	3.4±0.04µs	30.1 Mtx/sec	27.8 Mtx/sec
u32_u64_u64	json	100	5.8±0.12µs	5.9±0.08µs	16.4 Mtx/sec	16.3 Mtx/sec
u32_u64_u64	product_value	100	1015.8±0.57ns	1015.7±0.71ns	93.9 Mtx/sec	93.9 Mtx/sec
u64_u64_u32	bflatn_to_bsatn_fast_path	100	742.3±4.33ns	753.0±0.32ns	128.5 Mtx/sec	126.6 Mtx/sec
u64_u64_u32	bflatn_to_bsatn_slow_path	100	2.4±0.04µs	2.8±0.00µs	39.4 Mtx/sec	34.3 Mtx/sec
u64_u64_u32	bsatn	100	1098.7±0.64ns	923.9±3.27ns	86.8 Mtx/sec	103.2 Mtx/sec
u64_u64_u32	bsatn	100	1606.5±74.45ns	1715.6±19.68ns	59.4 Mtx/sec	55.6 Mtx/sec
u64_u64_u32	json	100	3.5±0.06µs	3.3±0.17µs	27.6 Mtx/sec	29.0 Mtx/sec
u64_u64_u32	json	100	5.9±0.07µs	5.8±0.01µs	16.3 Mtx/sec	16.4 Mtx/sec
u64_u64_u32	product_value	100	1015.1±1.19ns	1014.6±0.68ns	94.0 Mtx/sec	94.0 Mtx/sec

stdb_module_large_arguments

arg size	new latency	old latency	new throughput	old throughput
64KiB	-	102.2±10.40µs	-	-

stdb_module_print_bulk

line count	new latency	old latency	new throughput	old throughput
1	-	52.4±6.81µs	-	-
100	-	598.3±12.12µs	-	-
1000	-	4.7±0.80ms	-	-

remaining

name	new latency	old latency	new throughput	old throughput
special/db_game/circles/load=10	-	51.3±2.38ms	-	-
special/db_game/circles/load=100	-	36.1±1.22ms	-	-
special/db_game/csharp/circles/load=10	2.7±0.01s	-	-	-
special/db_game/csharp/circles/load=100	2.7±0.00s	-	-	-
special/db_game/csharp/ia_loop/load=10	356.5±1.52ms	-	-	-
special/db_game/csharp/ia_loop/load=100	931.5±6.14ms	-	-	-
special/db_game/ia_loop/load=500	-	148.1±0.81ms	-	-
special/db_game/ia_loop/load=5000	-	5.3±0.05s	-	-
special/db_game/rust/circles/load=10	43.4±1.85ms	-	-	-
special/db_game/rust/circles/load=100	50.1±4.56ms	-	-	-
special/db_game/rust/ia_loop/load=10	9.4±0.39ms	-	-	-
special/db_game/rust/ia_loop/load=100	11.9±0.62ms	-	-	-
special/stdb_module/csharp/large_arguments/64KiB	2.1±0.43ms	-	-	-
special/stdb_module/csharp/print_bulk/lines=1	170.3±8.60µs	-	-	-
special/stdb_module/csharp/print_bulk/lines=100	1883.1±242.80µs	-	-	-
special/stdb_module/csharp/print_bulk/lines=1000	12.0±1.84ms	-	-	-
special/stdb_module/rust/large_arguments/64KiB	99.8±7.46µs	-	-	-
special/stdb_module/rust/print_bulk/lines=1	54.3±4.68µs	-	-	-
special/stdb_module/rust/print_bulk/lines=100	605.3±11.50µs	-	-	-
special/stdb_module/rust/print_bulk/lines=1000	3.6±0.33ms	-	-	-
sqlite/💿/update_bulk/u32_u64_str/unique_0/load=2048/count=256	-	54.3±0.20µs	-	18.0 Ktx/sec
sqlite/💿/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	-	46.3±0.09µs	-	21.1 Ktx/sec
sqlite/🧠/update_bulk/u32_u64_str/unique_0/load=2048/count=256	-	39.6±0.13µs	-	24.7 Ktx/sec
sqlite/🧠/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	-	34.7±0.11µs	-	28.1 Ktx/sec
stdb_module/csharp/💿/update_bulk/u32_u64_str/unique_0/load=2048/count=256	11.9±0.07ms	-	84 tx/sec	-
stdb_module/csharp/💿/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	9.9±0.66ms	-	100 tx/sec	-
stdb_module/rust/💿/update_bulk/u32_u64_str/unique_0/load=2048/count=256	1250.3±13.71µs	-	799 tx/sec	-
stdb_module/rust/💿/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	994.9±18.13µs	-	1005 tx/sec	-
stdb_module/💿/update_bulk/u32_u64_str/unique_0/load=2048/count=256	-	1242.6±13.61µs	-	804 tx/sec
stdb_module/💿/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	-	998.1±5.79µs	-	1001 tx/sec
stdb_raw/💿/update_bulk/u32_u64_str/unique_0/load=2048/count=256	633.0±18.61µs	615.3±41.19µs	1579 tx/sec	1625 tx/sec
stdb_raw/💿/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	428.2±6.87µs	480.8±7.76µs	2.3 Ktx/sec	2.0 Ktx/sec
stdb_raw/🧠/update_bulk/u32_u64_str/unique_0/load=2048/count=256	374.4±0.17µs	363.1±0.20µs	2.6 Ktx/sec	2.7 Ktx/sec
stdb_raw/🧠/update_bulk/u32_u64_u64/unique_0/load=2048/count=256	335.7±0.27µs	323.5±0.46µs	2.9 Ktx/sec	3.0 Ktx/sec

[github-actions]

Callgrind benchmark results

Callgrind Benchmark Report

These benchmarks were run using callgrind,
an instruction-level profiler. They allow comparisons between sqlite (sqlite), SpacetimeDB running through a module (stdb_module), and the underlying SpacetimeDB data storage engine (stdb_raw). Callgrind emulates a CPU to collect the below estimates.

Measurement changes larger than five percent are in bold.

In-memory benchmarks

callgrind: empty transaction

db	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	6397	6397	0.00%	6519	6527	-0.12%
sqlite	5579	5589	-0.18%	5941	6117	-2.88%

callgrind: filter

db	schema	indices	count	preload	_column	data_type	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	no_index	64	128	1	u64	76591	76591	0.00%	77039	77031	0.01%
stdb_raw	u32_u64_str	no_index	64	128	2	string	119089	120178	-0.91%	119855	120932	-0.89%
stdb_raw	u32_u64_str	btree_each_column	64	128	2	string	25082	25081	0.00%	25604	25735	-0.51%
stdb_raw	u32_u64_str	btree_each_column	64	128	1	u64	24049	24049	0.00%	24445	24609	-0.67%
sqlite	u32_u64_str	no_index	64	128	2	string	144695	144695	0.00%	146185	146181	0.00%
sqlite	u32_u64_str	no_index	64	128	1	u64	124044	124044	0.00%	125192	125272	-0.06%
sqlite	u32_u64_str	btree_each_column	64	128	1	u64	131361	131361	0.00%	132729	132857	-0.10%
sqlite	u32_u64_str	btree_each_column	64	128	2	string	134494	134494	0.00%	136124	136176	-0.04%

callgrind: insert bulk

db	schema	indices	count	preload	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	64	128	878645	878993	-0.04%	898727	934437	-3.82%
stdb_raw	u32_u64_str	btree_each_column	64	128	1025919	1031446	-0.54%	1062275	1098746	-3.32%
sqlite	u32_u64_str	unique_0	64	128	398320	398320	0.00%	414892	414994	-0.02%
sqlite	u32_u64_str	btree_each_column	64	128	983637	983637	0.00%	1022751	1021691	0.10%

callgrind: iterate

db	schema	indices	count	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	1024	153724	153724	0.00%	153840	153866	-0.02%
stdb_raw	u32_u64_str	unique_0	64	16749	16749	0.00%	16849	16871	-0.13%
sqlite	u32_u64_str	unique_0	1024	1068275	1067255	0.10%	1071515	1070691	0.08%
sqlite	u32_u64_str	unique_0	64	76261	76201	0.08%	77287	77335	-0.06%

callgrind: serialize_product_value

count	format	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
64	json	47528	47528	0.00%	50218	50180	0.08%
64	bsatn	25509	25509	0.00%	27719	27719	0.00%
16	bsatn	8200	8200	0.00%	9526	9526	0.00%
16	json	12188	12188	0.00%	14126	14092	0.24%

callgrind: update bulk

db	schema	indices	count	preload	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	1024	1024	20119200	20120482	-0.01%	20640060	20703592	-0.31%
stdb_raw	u32_u64_str	unique_0	64	128	1287320	1287068	0.02%	1326058	1329642	-0.27%
sqlite	u32_u64_str	unique_0	1024	1024	1802182	1802182	0.00%	1811458	1811474	-0.00%
sqlite	u32_u64_str	unique_0	64	128	128528	128528	0.00%	131398	131416	-0.01%

On-disk benchmarks

callgrind: empty transaction

db	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	6402	6402	0.00%	6536	6536	0.00%
sqlite	5621	5621	0.00%	6047	6175	-2.07%

callgrind: filter

db	schema	indices	count	preload	_column	data_type	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	no_index	64	128	1	u64	76596	76596	0.00%	77024	77012	0.02%
stdb_raw	u32_u64_str	no_index	64	128	2	string	120183	119094	0.91%	121009	119764	1.04%
stdb_raw	u32_u64_str	btree_each_column	64	128	2	string	25086	25086	0.00%	25572	25728	-0.61%
stdb_raw	u32_u64_str	btree_each_column	64	128	1	u64	24054	24054	0.00%	24422	24582	-0.65%
sqlite	u32_u64_str	no_index	64	128	1	u64	125965	125971	-0.00%	127521	127555	-0.03%
sqlite	u32_u64_str	no_index	64	128	2	string	146616	146616	0.00%	148418	148458	-0.03%
sqlite	u32_u64_str	btree_each_column	64	128	2	string	136616	136616	0.00%	138668	138824	-0.11%
sqlite	u32_u64_str	btree_each_column	64	128	1	u64	133457	133457	0.00%	135319	135343	-0.02%

callgrind: insert bulk

db	schema	indices	count	preload	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	64	128	827614	828159	-0.07%	877486	882163	-0.53%
stdb_raw	u32_u64_str	btree_each_column	64	128	977349	978051	-0.07%	1040467	1042435	-0.19%
sqlite	u32_u64_str	unique_0	64	128	415857	415857	0.00%	431631	431843	-0.05%
sqlite	u32_u64_str	btree_each_column	64	128	1021898	1021898	0.00%	1059450	1059298	0.01%

callgrind: iterate

db	schema	indices	count	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	1024	153729	153729	0.00%	153825	153851	-0.02%
stdb_raw	u32_u64_str	unique_0	64	16754	16754	0.00%	16850	16872	-0.13%
sqlite	u32_u64_str	unique_0	1024	1071343	1070323	0.10%	1075045	1074105	0.09%
sqlite	u32_u64_str	unique_0	64	78033	77973	0.08%	79275	79263	0.02%

callgrind: serialize_product_value

count	format	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
64	json	47528	47528	0.00%	50218	50180	0.08%
64	bsatn	25509	25509	0.00%	27719	27719	0.00%
16	bsatn	8200	8200	0.00%	9526	9526	0.00%
16	json	12188	12188	0.00%	14126	14092	0.24%

callgrind: update bulk

db	schema	indices	count	preload	total reads + writes	old total reads + writes	Δrw	estimated cycles	old estimated cycles	Δcycles
stdb_raw	u32_u64_str	unique_0	1024	1024	19037270	19035674	0.01%	19625194	19691388	-0.34%
stdb_raw	u32_u64_str	unique_0	64	128	1240913	1239755	0.09%	1308873	1312385	-0.27%
sqlite	u32_u64_str	unique_0	1024	1024	1809743	1809743	0.00%	1818367	1818423	-0.00%
sqlite	u32_u64_str	unique_0	64	128	132654	132654	0.00%	135556	135606	-0.04%

[kazimuth]

This looks good!

There are some regexes here that need to be updated with new strings for this, to get the auto-generated comments fixed. This is, unfortunately, kind of a pain to test, so I can do it if needed.

[gefjon]

Internal tests failures appear to be spurious/unrelated, but let's wait to merge until they're fixed just in case.

[RReverser]

There are some regexes here that need to be updated with new strings for this, to get the auto-generated comments fixed. This is, unfortunately, kind of a pain to test, so I can do it if needed.

Yeah if you could, please do.

Internal tests failures appear to be spurious/unrelated, but let's wait to merge until they're fixed just in case.

SGTM.

[bfops]

I hit the "Update branch" button because I believe it will make the internal tests pass.

[RReverser]

It did, thanks.