Frequent errors showing up in benchmarking, introduced in "feat: improve logging in the query_plan" or a bit earlier

[pflanze]

The SILO benchmarking/ dir uses api-query to carry out the requests. api-query counts the hard errors (failing connections) and if it reaches 6, then it stops with a "too many errors" message, making that particular benchmarking run fail. This never happened in the past, but rather regularly starting with SILO commit bd2b494. Since benchmarking jobs do 10 runs and are only aborted after the second failure of individual runs, most jobs still finish due to the second chance, but I've seen at least one job fail twice and hence aborted (one of the jobs in "erroneous-jobs" in the evobench job listing), I can look up which it was in case it matters.

It's not a big problem for the benchmarking, in fact we can just increase the number of allowed failures to make ~all jobs succeed. But I wonder if there's an underlying problem that this indicates.

The errors look like these in ~evobench/.evobench-run/working_directory_pool/18.output_of_benchmarking_command_at_2025-09-26T17:36:14.030083174+02:00:

2025-09-26T17:37:37.157186883+02:00     E       Error: too many errors (besides {200: 20304, 400: 177} ~successes): [posting the query "{\"action\":{\"minProportion\":0.001,\"randomize\":false,\"type\":\"Mutations\"},\"filterExpression\":{\"children\":[{\"column\":\"date\",\"from\":\"2023-07-24\",\"to\":\"2023-07-30\",\"type\":\"DateBetween\"},{\"children\":[{\"column\":\"host\",\"value\":\"Homo sapiens\",\"type\":\"StringEquals\"}],\"type\":\"Or\"},{\"sequenceName\":\"S\",\"position\":70,\"symbol\":\"V\",\"type\":\"AminoAcidEquals\"},{\"sequenceName\":\"S\",\"position\":69,\"symbol\":\"H\",\"type\":\"AminoAcidEquals\"}],\"type\":\"And\"}}"
2025-09-26T17:37:37.157248433+02:00     E       
2025-09-26T17:37:37.157259422+02:00     E       Caused by:
2025-09-26T17:37:37.157269562+02:00     E           0: error sending request for url (http://localhost:8081/query): connection error: Connection reset by peer (os error 104)
2025-09-26T17:37:37.157279602+02:00     E           1: connection error: Connection reset by peer (os error 104)
2025-09-26T17:37:37.157289672+02:00     E           2: Connection reset by peer (os error 104), posting the query "{\"action\":{\"groupByFields\":[\"originatingLab\"],\"randomize\":false,\"type\":\"Aggregated\"},\"filterExpression\":{\"type\":\"True\"}}"
2025-09-26T17:37:37.157319492+02:00     E       
2025-09-26T17:37:37.157330152+02:00     E       Caused by:
2025-09-26T17:37:37.157340012+02:00     E           0: error sending request for url (http://localhost:8081/query): connection closed before message completed
2025-09-26T17:37:37.157349872+02:00     E           1: connection closed before message completed, posting the query "{\"action\":{\"groupByFields\":[\"date\"],\"orderByFields\":[{\"field\":\"date\",\"order\":\"ascending\"}],\"randomize\":false,\"type\":\"Aggregated\"},\"filterExpression\":{\"children\":[{\"sequenceName\":\"S\",\"position\":100,\"symbol\":\"X\",\"type\":\"AminoAcidEquals\"}],\"type\":\"And\"}}"
2025-09-26T17:37:37.157359702+02:00     E       
2025-09-26T17:37:37.157369382+02:00     E       Caused by:
2025-09-26T17:37:37.157379332+02:00     E           0: error sending request for url (http://localhost:8081/query): connection closed before message completed
2025-09-26T17:37:37.157400072+02:00     E           1: connection closed before message completed, posting the query "{\"action\":{\"groupByFields\":[\"host\"],\"randomize\":false,\"type\":\"Aggregated\"},\"filterExpression\":{\"type\":\"True\"}}"
2025-09-26T17:37:37.157409972+02:00     E       
2025-09-26T17:37:37.157419742+02:00     E       Caused by:
2025-09-26T17:37:37.157429532+02:00     E           0: error sending request for url (http://localhost:8081/query): connection closed before message completed
2025-09-26T17:37:37.157439672+02:00     E           1: connection closed before message completed, posting the query "{\"action\":{\"groupByFields\":[\"date\"],\"randomize\":false,\"type\":\"Aggregated\"},\"filterExpression\":{\"children\":[{\"column\":\"date\",\"from\":\"2024-10-07\",\"to\":\"2025-04-05\",\"type\":\"DateBetween\"},{\"children\":[{\"column\":\"pangoLineage\",\"value\":\"KP.1.1\",\"includeSublineages\":true,\"type\":\"Lineage\"}],\"type\":\"Or\"},{\"children\":[{\"column\":\"host\",\"value\":\"Homo sapiens\",\"type\":\"StringEquals\"}],\"type\":\"Or\"}],\"type\":\"And\"}}"
2025-09-26T17:37:37.157449432+02:00     E       
2025-09-26T17:37:37.157459072+02:00     E       Caused by:
2025-09-26T17:37:37.157468832+02:00     E           0: error sending request for url (http://localhost:8081/query): connection error: Connection reset by peer (os error 104)
2025-09-26T17:37:37.157478642+02:00     E           1: connection error: Connection reset by peer (os error 104)
2025-09-26T17:37:37.157488542+02:00     E           2: Connection reset by peer (os error 104), posting the query "{\"action\":{\"groupByFields\":[\"division\",\"country\",\"region\"],\"randomize\":false,\"type\":\"Aggregated\"},\"filterExpression\":{\"children\":[{\"column\":\"date\",\"from\":\"2020-01-06\",\"to\":\"2025-04-06\",\"type\":\"DateBetween\"},{\"children\":[{\"column\":\"host\",\"value\":\"Homo sapiens\",\"type\":\"StringEquals\"}],\"type\":\"Or\"}],\"type\":\"And\"}}"
2025-09-26T17:37:37.157498292+02:00     E       
2025-09-26T17:37:37.157507861+02:00     E       Caused by:
2025-09-26T17:37:37.157517661+02:00     E           0: error sending request for url (http://localhost:8081/query): connection closed before message completed
2025-09-26T17:37:37.157527401+02:00     E           1: connection closed before message completed]

Searching for these errors across all benchmarking runs ever done yields the commit ids that had such errors:

evobench@gs-staging-1:~/.evobench-run/working_directory_pool$ grep -F 'Error: too many errors' *.output* -l|» ls -lrt| perl -wne 's{.*? (\d+\.)}{$1}; chomp; print "$_\t"; system "grep","commit.id", $_ '|perl -wne 'm{([^\t]+).*commit_id:.*?([a-f0-9]+)} or die; print "$1\t$2\n"'
18.output_of_benchmarking_command_at_2025-09-26T17:36:14.030083174+02:00	bd2b494687cdd17bdc043c15ebe83be094e871d6
32.output_of_benchmarking_command_at_2025-10-02T00:09:17.910603117+02:00	fddc48c5f4df46135e9451e1358542228680b9a4
30.output_of_benchmarking_command_at_2025-10-02T11:37:58.660032154+02:00	f547e9fdbf221c5b433493346dd50b105b579bf8
17.output_of_benchmarking_command_at_2025-10-02T13:29:05.961113749+02:00	e18702904a6fd3784d7b549a26d98207ea33441b
16.output_of_benchmarking_command_at_2025-10-03T00:12:38.257369762+02:00	f547e9fdbf221c5b433493346dd50b105b579bf8
7.output_of_benchmarking_command_at_2025-10-08T15:34:57.078044183+02:00	d650f2ecc8b35dd9d055126ae27944b4bf52d2f5
49.output_of_benchmarking_command_at_2025-10-09T04:32:26.947147676+02:00	d5bbaba6fbe93a6af7751e562ec62dcf8a35f319
39.output_of_benchmarking_command_at_2025-10-09T05:04:17.733228127+02:00	5beabade64f6568293f60d197497067e3e974c63
50.output_of_benchmarking_command_at_2025-10-11T03:56:29.837424237+02:00	0c805f70c73af1ba8b00b9dd2668e17139b34c73
0.output_of_benchmarking_command_at_2025-10-14T00:04:11.943828124+02:00	e380245471a2df2178186d7f099e89f314d6ea62
6.output_of_benchmarking_command_at_2025-10-20T15:47:04.806275382+02:00	4a7399b4147fbd45f51b95c14ab721dcd6ee337e

bd2b494 is the first commit that has them.

[pflanze]

PS. all errors have happened with the SC2open DATASET (no surprise, the errors are rare and only happen with many queries and perhaps large datasets).

[pflanze]

How to do the same SILO run "manually":

# evobench@gs-staging-1:~/.evobench-run/working_directory_pool$ less 13.output_of_benchmarking_command_at_2025-10-22T23:14:13.873138063+02:00

export    CONCURRENCY=120
export    DATASET=SC2open
export    RANDOMIZED=1
export    REPEAT=1
export    SILO_API_THREADS_FOR_HTTP_CONNECTIONS=16
export    SORTED=0
export DATASET=SC2open
export DATASET_DIR=/home/evobench/silo-benchmark-datasets/SC2open/v0.9.0/

export COMMIT_ID=685efc3a41446fdd069169c371baa63baefd5bed
export BENCH_OUTPUT_LOG=local-bench.log
#export EVOBENCH_LOG=

evobench@gs-staging-1:~/.evobench-run/working_directory_pool/13/benchmarking$ make api

[pflanze]

What we know so far:

• SILO crashes/disappears, the log is cut off (the copy to stdout has a whole last line, the copy to logs/ not)
• so far only with 16+ api connections, not with the run with 1 connection, but a run that repeats 8 times and randomizes is ongoing

A question was, is it running out of memory? I've checked whether earlyoom or the kernel oom triggers, the answer is no:

root@gs-staging-1 ~ # journalctl -k --since today|grep oom
root@gs-staging-1 ~ # journalctl --since today|grep earlyoom |less

Also, here's the correlation with the crash (all times in Basel time):

evobench@gs-staging-1:~/.evobench-run/working_directory_pool/13/benchmarking$ grep 'Current memory consumption:' local-bench.log.1
[2025-10-23 10:50:46.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 16540 KB
[2025-10-23 10:50:51.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 6293864 KB
[2025-10-23 10:50:56.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 8256564 KB
[2025-10-23 10:51:01.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 9872164 KB
[2025-10-23 10:51:06.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 11360596 KB
[2025-10-23 10:51:11.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 13050428 KB
[2025-10-23 10:51:16.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 14665548 KB
[2025-10-23 10:51:21.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 16358928 KB
[2025-10-23 10:51:26.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 17927880 KB
[2025-10-23 10:51:31.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 19567568 KB
[2025-10-23 10:51:36.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 21098280 KB
[2025-10-23 10:51:41.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 22617976 KB
[2025-10-23 10:51:46.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 24227912 KB
[2025-10-23 10:51:51.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 25742056 KB
[2025-10-23 10:51:56.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 27432016 KB
[2025-10-23 10:52:01.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 30431228 KB
[2025-10-23 10:52:06.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31358428 KB
[2025-10-23 10:52:11.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31616644 KB
[2025-10-23 10:52:16.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31652416 KB
[2025-10-23 10:52:21.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31677016 KB
[2025-10-23 10:52:26.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31722776 KB
[2025-10-23 10:52:31.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31715488 KB
[2025-10-23 10:52:36.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31731052 KB
[2025-10-23 10:52:41.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31706336 KB
[2025-10-23 10:52:46.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31764392 KB
[2025-10-23 10:52:51.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31730264 KB
[2025-10-23 10:52:56.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31777924 KB
[2025-10-23 10:53:01.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31786548 KB
[2025-10-23 10:53:06.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31766936 KB
[2025-10-23 10:53:11.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31746308 KB
[2025-10-23 10:53:16.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31763988 KB
[2025-10-23 10:53:21.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31772652 KB
[2025-10-23 10:53:26.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31761656 KB
[2025-10-23 10:53:31.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31785220 KB
[2025-10-23 10:53:36.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31860512 KB
[2025-10-23 10:53:41.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31804332 KB
[2025-10-23 10:53:46.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31763292 KB
[2025-10-23 10:53:51.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31852952 KB
[2025-10-23 10:53:56.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31877944 KB
[2025-10-23 10:54:01.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31855812 KB
[2025-10-23 10:54:06.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31817876 KB
[2025-10-23 10:54:11.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31897752 KB
[2025-10-23 10:54:16.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31877612 KB
[2025-10-23 10:54:21.083] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31872560 KB
[2025-10-23 10:54:26.084] [logger] [info] [memory_monitor.cpp:72] Current memory consumption: 31837628 KB

journalctl:

Oct 23 10:54:09 gs-staging-1 earlyoom[2330634]: mem avail: 159013 of 321931 MiB (49.39%), swap free: 81444 of 81919 MiB (99.42%)
Oct 23 10:54:19 gs-staging-1 earlyoom[2330634]: mem avail: 159101 of 321931 MiB (49.42%), swap free: 81444 of 81919 MiB (99.42%)
Oct 23 10:54:29 gs-staging-1 earlyoom[2330634]: mem avail: 159058 of 321931 MiB (49.41%), swap free: 81444 of 81919 MiB (99.42%)
Oct 23 10:54:39 gs-staging-1 earlyoom[2330634]: mem avail: 190107 of 321931 MiB (59.05%), swap free: 81444 of 81919 MiB (99.42%)
Oct 23 10:54:49 gs-staging-1 earlyoom[2330634]: mem avail: 190097 of 321931 MiB (59.05%), swap free: 81444 of 81919 MiB (99.42%)

So, there was no memory problem, half the memory on gs-staging-1 was still available, and SILO itself says that it used ~30 GB, i.e. fine.

[pflanze]

I have conclusive evidence that the commit that introduces the problem is 223e5c6 (#981).

• It does not appear to happen with concurrency 1 (= api-query only sending 1 query at a time) (at least there were no crashes in ~600'000 requests)

• It crashes around as often while recording benchmarking data as without; oddly, it now only crashes every about 200'000 requests, around 4x less often than before, I have no idea why except perhaps the server load is different during the week than on the weekend and triggers races differently?

• It still crashes even with the previous (TBB) instead of the new threading infrastructure (arrow's with my wrapper), although about 10x less frequently (perhaps a change in the duration of a race window?)

• SILO with the new threading infrastructure (arrow and my wrapper) never crashed before this commit

The stack traces in the core dumps are always the same (regardless whether TBB or arrow/wrapper are used for threading!) (optimized build without debugging symbols):

#7  0x00007fd73e6a040c in std::__throw_bad_function_call() () from /lib/x86_64-linux-gnu/libstdc++.so.6
#8  0x000055a638fce1ab in arrow::acero::TaskSchedulerImpl::OnTaskGroupFinished(unsigned long, int, bool*) ()
#9  0x000055a638fced1d in arrow::acero::TaskSchedulerImpl::StartTaskGroup(unsigned long, int, long) ()
#10 0x000055a638f94f6c in arrow::acero::QueryContext::StartTaskGroup(int, long) ()
#11 0x000055a639022b1f in arrow::acero::aggregate::GroupByNode::OutputResult(bool) ()
#12 0x000055a639022cb0 in arrow::acero::aggregate::GroupByNode::InputFinished(arrow::acero::ExecNode*, int) ()
#13 0x000055a638fae578 in std::_Function_handler<arrow::Status (), arrow::acero::(anonymous namespace)::SourceNode::StartProducing()::{lambda(arrow::Result<int>)#2}::operator()(arrow::Result<int>)::{lambda()#1}>::_M_invoke(std::_Any_data const&) ()
#14 0x000055a638f968bf in arrow::internal::FnOnce<void ()>::FnImpl<std::_Bind<arrow::detail::ContinueFuture (arrow::Future<arrow::internal::Empty>, std::function<arrow::Status ()>)> >::invoke() ()
#15 0x000055a639ee4dd7 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<arrow::internal::ThreadPool::LaunchWorkersUnlocked(int)::{lambda()#1}> > >::_M_run() ()

I've tried running the same with a debug build of SILO, but that didn't give me a core dump, but just printed the following on stdout or stderr and exited, so I don't have a backtrace with line information:

terminate called after throwing an instance of 'std::bad_function_call'
  what():  bad_function_call

[pflanze]

PS. I also tested @Taepper 's change to mimalloc (edd7153) with regards to the crashes: they still happened.

I pushed the branches that I tested:

1035-test-448bf27b6323baae59a2d836119a5de7c107e891
1035-test-5f4908891eed05842691c35462ab6433b2508385
1035-test-9a1e907a8de4e94467825f6d33642ba1f360fc56
1035-test-9f13d7966c6ecaae20c81798472c1942f5d346f7
1035-test-a5ffd5da7ded204745525e3472e7de81ded05316
1035-test-edd71537b8b35fac50d9f5a270e46a748ad9ab9c
1035-test-fb76231563efb88f429a513b6d31462bff39ee08

PS. note that those are not the original commits, but with some commits on top so that the benchmarking suite can work (since we did some changes). You can pass them all to gitk to see which commits they test.

[pflanze]

While testing #1060 with the new api-query CSV log, I caught SILO crashing; the log with the successful queries and then the crashed ones is here: api-query-log-2025-11-24T15:10:58+01:00.csv

It might be interesting to note that by the time of the crash, a number of queries were running or hanging a long time (up to 29 seconds). You can see this nicely by loading the CSV in LibreOffice or something, then sorting by the 'start' column. There's a query that was started pretty early (query number 550), then almost 10'000 more queries ran through until SILO crashed, with that query from 29 seconds ago never finishing. Maybe not related, but perhaps the queries that came in shortly before the crash are relevant?

[Taepper]

Oh, I do not think the ones before are relevant, but I think we ran into another arrow bug with our implementation of Mutations queries! I see correctly that the last query before the crash was of type Mutations?

[pflanze]

I would expect that all queries that end with an error (the last 6 in this case) are potentially relevant, as parallel queries are required for making SILO crash (presumably via race condition). I'd agree that the queries that end with Ok probably aren't relevant.

Two of those 6 queries were of action type Mutations, the other 4 of type Aggregated. I've added an expand subcommand to api-query-log to add a column with the query string according to the reference (line number):

api-query-log expand \
   ~/silo-benchmark-datasets/SC2open/v0.9.0/silo_queries.ndjson \
   api-query-log-2025-11-24T15\:10\:58+01\:00.csv \
   api-query-log-2025-11-24T15\:10\:58+01\:00-expanded.csv

The expanded file for this case is here: api-query-log-2025-11-24T15:10:58+01:00-expanded.csv

[Taepper]

Can you test whether the errors appear with dataset that contain only one query which is repeated N times? Then we can check for each of these 6, which one would lead to crashes

[pflanze]

You can find the following jobs running or at some point finished or in error status:

Reason                   Commit_id                                 Target_name   Custom_parameters 
bench_christian_adhoc    a69ded9c3ae5f48cbb232ee10020a258b6d2438e  api           CONCURRENCY=120,DATASET=SC2open,QUERIES=silo_queries-A6.ndjson,RANDOMIZED=1,REPEAT=5000,SORTED=0
bench_christian_adhoc    a69ded9c3ae5f48cbb232ee10020a258b6d2438e  api           CONCURRENCY=120,DATASET=SC2open,QUERIES=silo_queries-A2.ndjson,RANDOMIZED=1,REPEAT=15000,SORTED=0
bench_christian_adhoc    a69ded9c3ae5f48cbb232ee10020a258b6d2438e  api           CONCURRENCY=120,DATASET=SC2open,QUERIES=silo_queries-A1a.ndjson,RANDOMIZED=1,REPEAT=30000,SORTED=0
bench_christian_adhoc    a69ded9c3ae5f48cbb232ee10020a258b6d2438e  api           CONCURRENCY=120,DATASET=SC2open,QUERIES=silo_queries-A1b.ndjson,RANDOMIZED=1,REPEAT=30000,SORTED=0

They all have a different QUERIES setting, for using different queries files. You find those files in evobench@gs-staging-1:~/silo-benchmark-datasets/SC2open/v0.9.0/. The REPEAT setting is accordingly.

silo_queries-A6.ndjson has all 6 last queries.

silo_queries-A1*.ndjson have one of the Mutations queries each.

silo_queries-A2.ndjson has both Mutation queries.