Is our Tokio runtime too loaded?

While running benchmarks, Francois noticed that on "small search queries" (as opposed to aggregations) on "relatively small datasets" quickwit was not doing well at all.

The benchmark was executed on Amazon, and the disk was EBS, which typically offer a latency of a few ms. Local OS page cache supposedly works as usual.

To a lesser extent the pathology was observed on a proper SSD too.
The following results are observations done on my laptop.

After have a look at what was happening via tracing/jaeger, we noticed that leaf_search_single_split tasks were starting with a noticeable staircase pattern... The Jaeger UI tends to make that kind of pattern very visible.
It is of about 400ms per call.

The IO operations are taking an unexpected amount of time, for data that is already in pagecache. One read is taking several milliseconds.
When working off the local filesystem, we are still using the StorageDirectory over the FileStorage. We could actually special case all of this and use an MmapDirectory and partially solve our problem, but I would like to understand the issue we are facing, as it problem could help us shave a few ms off search in the S3 use case too.

The FileStorage does IO using tokio fake async io. In main, it does the natural thing.
Opening the file... Performing a sync... Doing the read... (And then dropping the file object on drop).
Tokio does not do async io and simply schedule these operations on its dedicated thread pool for blocking work. Running all of these operations separately means a lot of back and force with the thread pool, which is not a problem in itself...

In https://github.com/quickwit-oss/quickwit/compare/bench-perf-investigation?expand=1, we pushed all of this operations explicitly in a spawn_blocking call using traditional std operation.

We also measure the actual time these operations took, to compare them with the amount of time taken by the get_slice async call.

The actual sequence of io operations took 40.159µs while the tokio task waiting for the spawnblocking result to finish takes 2ms. This suggests a latency induced by the tokio runtime, probably being too busy.

We need to confirm this hypothesis, and find how to make sure the runtime is snappy again.
This probably means identifying the few tasks blocking for too long during their poll run(s) and requiring

• a call to spawnblcoking
• a call to yield_now.

Tokio did not show a clear culprit, but AFAIK it is not great to investigate short lived tasks.

Possible suspects:

• the lookup in the term dictionary
• opening the hot directory and the serde_cbor deserialization
• chitchat digests (they suck but supposedly they should run only every second)

Important thing to note but you might already know that:

• a task does not yield necessarily on .await. If Poll is ready tokio will keep the taks running. Sometimes, it is important to add a yield now to make sure we start an io operation as soon as possible for instance.

Possible stuff to investigate

• attempt to schedule some weird canary tasks on all of the runtime thread. They would loop and yield explicitly, and measure how long it takes between 2 runs. If it takes more than 300microsecs, this could be a good sign we have a problem.
• tokio metrics has interesting information. You can curl quickwit on a loop with max_hits=0 and see how busy the runtime is maybe? There are also a task specific metrics.

Screenshot taken with
https://github.com/quickwit-oss/quickwit/compare/bench-perf-investigation?expand=1,