OxQL slows down a lot when multiple queries run concurrently

[david-crespo]

(See also oxidecomputer/console#2736 about not firing a query on every keydown in the time field.)

As the video shows: one or two queries run concurrently take under a second. Trigger 4 together and they take 5-6 seconds each and all finish at the same time. Run 10 and they take 13-15 seconds.

2025-03-03-time-range-change.mp4

Some tests scaling to higher numbers of queries.

I ran about 50 and got a fun pattern where the latter ones would all 503 at 30s but the earlier ones did not.

[askfongjojo]

We might need to reduce the frequency of sensor data collection. Currently, it's every 1s and there is a large volume of those temperature and power readings.

As we'll keep adding more types of metrics, the load on ClickHouse will keep growing. I wonder if there are policies or guidance on the frequency of collection so that we have a more controlled ingestion of data for different areas of the rack. Using EC2 CloudWatch as a reference, we can perhaps scale back to every 5 minute by default, and every minute for areas that needs more granular metrics for troubleshooting?

[wfchandler]

Profiling Clickhouse on dogfood, I noticed that it's using the system allocator, rather than jemalloc or similar.

This appears to be adding a creating a significant amount of contention on what I assume is a global lock on the allocator. Running the following query with 1, 3, and 5 parallel requests, the total time in allocation related tasks is between 70 and 80%.

get hardware_component:fan_speed | filter timestamp > @now() - 1m | last 1

Here is a detail of a reverse flamegraph with 5 requests running, searching for malloc|free:

For comparison, the same with a single request:

Full flamegraphs

@bnaecker has suggested using LDPRELOAD to see if using umem improves this, which I'll test out shortly.

Full flamegraphs

One query - Standard flamegraph

One query - Reverse flamegraph

Five queries - Standard flamegraph

[wfchandler]

It turns out that Clickhouse will unset LD_PRELOAD and similar environment variables as a security measure.

will@atrium ~ $ penv $(pgrep -u will clickhouse) | grep LD_PRELOAD
envp[6]: LD_PRELOAD=

We can probably just patch this out, at least temporarily, given the level of control we have over the environment we run Clickhouse in. Longer run, a patch to support umem and/or enable jemalloc will be needed.

[wfchandler]

I updated our build script to set -DENABLE_UMEM=on in our cmake command, and added a quick and dirty patch to Clickhouse to link libumem, matching how jemalloc is linked:

diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt
index ed33ea3800..0123e34a32 100644
--- a/src/CMakeLists.txt
+++ b/src/CMakeLists.txt
@@ -169,6 +169,14 @@ if (TARGET ch_contrib::jemalloc)
     target_link_libraries (clickhouse_storages_system PRIVATE ch_contrib::jemalloc)
 endif()
 
+if (OS_SUNOS AND ENABLE_UMEM)
+    message (STATUS "Using umem")
+    find_library(LIBUMEM NAMES umem)
+    target_link_libraries (clickhouse_new_delete PRIVATE ${LIBUMEM})
+    target_link_libraries (clickhouse_common_io PRIVATE ${LIBUMEM})
+    target_link_libraries (clickhouse_storages_system PRIVATE ${LIBUMEM})
+endif ()
+
 if (TARGET ch_contrib::azure_sdk)
     target_link_libraries(clickhouse_storages_system PRIVATE ch_contrib::azure_sdk)
 endif()

Steps:

1. On atrium, run the patched CH with @bnaecker's scripts in /staff/ben/clickhouse-runs/run.sh
2. Connect to CH using oxdb --address 172.20.3.69 oxql
3. Run query get hardware_component:fan_speed | filter timestamp > @now() - 1m | last 1

With the system malloc, this resulted in query times of:

2025.05.01 14:22:37.307870 [ 3 ] {2d3ef430-9b61-41f4-afa0-b8a9853f4ac9} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.219997 sec., 41742532.85272072 rows/sec., 318.47 MiB/sec.
2025.05.01 14:22:45.612967 [ 3 ] {e1d106a6-2de1-461c-8f88-eef73e986e8b} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.179978 sec., 51024191.84567003 rows/sec., 389.28 MiB/sec.
2025.05.01 14:22:49.334686 [ 3 ] {062ab195-e262-4e3a-a25f-517230e51652} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.179358 sec., 51200570.925188735 rows/sec., 390.63 MiB/sec.
2025.05.01 14:22:52.865730 [ 3 ] {79331d3c-6d2a-4693-99ee-3ead321c52c2} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.177275 sec., 51802183.04893527 rows/sec., 395.22 MiB/sec.

With libumem we see a speedup of roughly 3x once the cache is warmed up:

2025.05.01 14:24:00.227874 [ 3 ] {5ec5546d-5097-4cd0-848a-82a397055da4} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.116975 sec., 78505937.16606113 rows/sec., 598.95 MiB/sec.
2025.05.01 14:24:05.888836 [ 3 ] {6179b023-6bc9-4f8b-832b-5c4e78aaeeaf} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.047621 sec., 192839965.561412 rows/sec., 1.44 GiB/sec.
2025.05.01 14:24:09.352962 [ 3 ] {477a2805-1f0d-4fdb-8304-299ad82aab49} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.048365 sec., 189873503.56662875 rows/sec., 1.41 GiB/sec.
2025.05.01 14:24:12.166495 [ 3 ] {9776917a-cfa5-4765-9af8-c91b2420b477} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.045644 sec., 201192533.52028745 rows/sec., 1.50 GiB/sec.
2025.05.01 14:24:14.505098 [ 3 ] {3f43ac8f-b916-42a0-81ea-d4d538a67368} <Debug> executeQuery: Read 9183232 rows, 70.06 MiB in 0.046221 sec., 198680945.89039615 rows/sec., 1.48 GiB/sec.

Unlike the flamegraphs I took from dogfood, we don't see the allocator lock dominating the CH processes using libc, which is a bit surprising given the performance differences we see.

Flamegraphs

System allocator

System allocator - reverse flamegraph

libumem

libumem - reverse flamegraph

[bnaecker]

This is a great, easy win, thanks for doing this. I'm guessing we don't see the lock in the graphs using libc's allocator because we're not running many queries in parallel. That would exacerbate lock contention, and produce the most egregious behavior while different threads try to acquire it. You might want to try to repro that specifically, to compare the allocators in that real scenario.

[wfchandler]

Ok, I do see the same contention with three simultaneous queries. Throughput also falls from ~400 MiB/s to ~250 MiB/s, which fits with what we see in production.

[bnaecker]

Awesome, it's great that we can repro the contended path. What do the flamegraphs look like with umem and the same number of concurrent queries?

[wfchandler]

No obvious bottlenecks due to allocation. We spend 8.1% of our time in malloc|free, vs 64% with libc.

Flamegraphs

With umem, standard flamegraph

With umem, reverse flamegraph

With libc, reverse flamegraph

Compressed as it's larger than 10 MiB.

libc_rev.svg.gz