Repository navigation
Dense build: 93% of DEEP-10M build time is JVector graph construction, and the build pool is availableProcessors()/2 - is the halving deliberate? #5577
Description
Activity
Profiled the graph-build phase, and the answer is not the pool. 30.3% of build CPU is a statistics counter in ArcadeDB, not work in JVector.
What was measured
DEEP-10M (9.99M x 96d),
maxConnections=32, released 26.8.1.dev22, cpuset 0-11, 24g heap. async-profiler CPU, armed five minutes afterBuilding JVector graph indexappears so the sample lands in the steady middle of the phase, 900 s window, 546,235 samples.Top of the profile by self time
share frame 45.8% PanamaVectorUtilSupport.squareDistancePreferred30.3% java.util.concurrent.atomic.LongAdder.add5.3% AbstractLongHeap.upHeap5.0% AbstractLongHeap.add5.0% org.agrona.collections.IntHashSet.add2.3% VamanaDiversityProvider.isDiverseThe 45.8% in SIMD distance is exactly what a graph build should look like and there is nothing to do about it. The 30.3% is the finding.
Where the LongAdder traffic comes from
Attributing every
LongAdder.addsample to its nearest non-atomic ancestor gives one caller, and it is yours rather than JVector's:100.0% com/arcadedb/index/vector/VectorCache.getVectorCache.get()increments unconditionally on every lookup:final Entry e0 = slots.get(base); if (e0 != null && e0.vectorId == vectorId) { hits.increment(); // every hit return e0.vector; } ... misses.increment(); // every miss
and the class javadoc says exactly why that is expensive here:
Used on the hottest path of the whole vector engine: every distance evaluation of a beam search (and of a graph build) resolves its operand through here.
So every distance evaluation performs a
LongAdder.increment()on one of two process-wide counters, with the whole build pool contending on them.LongAdderis the right structure for contended counting, but at one increment per distance evaluation it still costs a third of the phase.What this does to the question I opened this issue with
It largely answers it, and not the way I expected. I asked whether
getOrCreateGraphBuildPool()sizing atavailableProcessors()/2was costing build time. The pool question is now secondary, and the A/B I have queued needs reading in this light: if a third of each thread's time is contention on two shared counters, doubling the thread count may buy much less than the idle cores suggest, and could plausibly make the contention worse. I will post that result either way, but I would no longer expect it to be the main lever.It also connects to #5412. The shared vector cache was added to fix query latency, which it did (p50 5.5 to 0.81 ms). Its unconditional statistics are now the second-largest consumer of build CPU. That is not a criticism of the cache, it is the ordinary thing that happens when a counter lands on a path that turns out to be hotter than the counter's author expected.
Not proposing a specific fix
You know the constraints better than I do, and there are several shapes: gate counting behind a stats flag, count only misses and derive hits from a total tracked elsewhere, sample every Nth lookup, or move to per-thread counters folded on read. Which of those is acceptable depends on what consumes
getStats(), and our own harness readsvectorCacheHits/vectorCacheMissesfrom it, so I am not neutral about them disappearing entirely.Happy to re-profile with any change applied. The corpus, the box and the profiling setup are all still staged.
Correcting my own framing on this issue: I filed asking about the build pool because that was the only ArcadeDB-side lever I could see by reading. It was not the right question, and the flame graph found the one I could not have guessed from source.
Correcting one number from my profile comment above, and reporting something I found while doing it.
The build has a third phase, and it is 55% of the wall clock
I had been treating the DEEP-10M build as ingest plus graph construction. Timing the phases from the engine's own log lines across three independent runs:
phase run 1 run 2 run 3 share ArcadeDB ingest (before the first Graph build buildingline)180 s 187 s 197 s ~7% graph insertion (first to last Graph build buildingline)1020 s 1078 s 1032 s 38% after the last progress line, until the build returns 1459 s 1548 s 1475 s 55% total 2659 s 2813 s 2704 s The last progress line is always around 9,989,000 of 9,990,000, so insertion is essentially finished when the logging stops. The engine then does something for roughly 24 minutes that emits no log line at all, not even on completion, at a steady ~600% CPU on a 12-thread cpuset. The proportions are stable to about a percentage point across the three runs, so this is structural rather than one bad run.
What that does to my 28% claim
I said "the graph phase is 93.4% of the build, so ~28% of the entire dense build is a statistics counter", and offered ~2,700 s toward ~1,940 s on that basis. Withdrawing the extrapolation. It assumed the profiled window was representative of the whole graph phase, and the phase table above says it is not: my 900 s window was armed 5 minutes after
Building JVector graph index, so it covered roughly 720 s of insertion and 180 s of whatever follows. The 30.3% is a blend of two phases in unknown proportion, not a rate that can be scaled to the full build.What still stands, because it is a direct reading rather than an extrapolation:
- 45.8%
PanamaVectorUtilSupport.squareDistancePreferredand 30.3%LongAdder.addwithin that window; - 100% of the
LongAddersamples attribute tocom.arcadedb.index.vector.VectorCache.get, which increments unconditionally on a path its own javadoc calls "every distance evaluation"; - so an unconditional counter on the distance path is expensive, and that is worth addressing regardless of the exact whole-build share.
What is not established is how much of the build it costs, and I would rather say that than defend a number I derived from an assumption I had not checked. I am re-profiling per phase and will post the split.
A small ask that would help anyone profiling this
One log line when insertion finishes and the next phase starts, and one when that phase completes, would make this phase directly measurable instead of inferable from an absence of output. Right now the only way to know the phase boundary exists is to notice that the log went quiet while the CPU did not. It cost me a wrong number, and I am probably not the last person who will profile a build here.
Happy to be told the silent phase is well understood on your side and simply not logged, in which case the ask is just the log line.
- 45.8%
The A/B is done, and it answers the question I opened this issue with. It also corrects the speculation I added when I posted the profile, so that first.
The pool A/B
DEEP-10M fp32,
maxConnections=32, released 26.8.1.dev22, cpuset 0-11, 24g heap, one build per arm. The forced arm is-XX:ActiveProcessorCount=24, which takesavailableProcessors()/2from 6 to 12. Both arms verified at the pool width they were supposed to have, by sampling container CPU every 30 s for the whole build:default forced CPU, median of samples 600.32% 1201.68% CPU, p25 to p75 599.70 to 600.62 1200.47 to 1202.28 build 2648.2 s 2196.2 s recall@10 0.9502 0.9526 So yes, the halving costs build time: 17.1% of the whole build, with recall unchanged. That is a real number and it is yours to weigh against whatever query headroom the halving was protecting.
Where it comes from, and where it does not
Splitting each build by its own log markers:
phase default forced scaling ArcadeDB ingest + validate 180 s 179 s n/a JVector insertion ( Graph build buildinglines)1023 s 534 s 1.92x JVector finishing (last progress line to JVector graph index built successfully)1407 s 1442 s 1.00x ArcadeDB page persist 38 s 41 s n/a Insertion scales at 1.92x on 2x the threads, which is about as good as it gets. The whole-build figure is only 17% because insertion is 38% of the build.
I was wrong about the contention. When I posted the profile I said "if a third of each thread's time is contention on two shared counters, doubling the thread count may buy much less than the idle cores suggest, and could plausibly make the contention worse". Insertion scaled 1.92x. Whatever the
LongAddertraffic costs in absolute terms, it is not limiting the insertion phase at 12 threads, and I should not have guessed that it would.The finding I did not expect
JVector's post-insertion phase takes the same wall-clock time on 12 threads as on 6, while burning twice the CPU. 1407 s against 1442 s, and the CPU samples say it is using the full pool in both arms: the per-sample distribution is a single tight cluster at 600% and at 1200% respectively, not bimodal, so the phase is not idling through a window that the insertion samples then pull up.
That phase is 53% of the default build and 66% of the forced one. It is the ceiling, not the pool. Doubling the pool again would presumably move insertion a little further and leave two thirds of the build untouched.
I have a per-phase profile queued to find out what it is actually doing, and will post it. If it turns out to be a known serial finalisation step that simply spends its time waiting on something, that is worth a sentence in the docs, because from the outside it looks like a 24-minute stall at full CPU.
Related: the progress meter cannot show this phase
Graph build building: n/Nhasn = min(vectorAccesses, totalVectors). The first line of a 10M build reads9060381/9990000about five seconds in, and the last reads9990000/9990000 (vector accesses=9990006). So the bar starts at 90.7% because the build touches every vector once up front, and reaches 100% with 23.5 minutes of work left.That is why neither of us had noticed a phase worth half the build. It is also the concrete version of the log-line ask in my previous comment: a line when insertion ends and another when the finishing phase ends would make the phase measurable, and would stop the meter claiming completion while the majority of the work is still ahead.
What I would take from this
The halving is worth undoing if build time matters more than query headroom during an online build, and 17% is the price. But the pool is not where the remaining time is, and I would not spend effort on pool tuning past this point without first knowing what the finishing phase is doing.
Happy to re-run either arm, or a 24-thread arm, on request. The corpus and the box are staged.
Per-phase profiles are in, and they restore the extrapolation I withdrew. They also make the pool result from my last comment much stranger.
The two phases are the same work
One DEEP-10M build on released 26.8.1.dev23, profiled twice: 600 s inside the logged insertion phase, then 600 s inside the phase that emits nothing. Boundary detected as "the progress-line count stopped growing", since there is no marker.
frame insertion (361,510 samples) silent (365,073 samples) PanamaVectorUtilSupport.squareDistancePreferred45.3% 46.3% LongAdder.add28.1% 29.3% AbstractLongHeap.upHeap7.6% 6.5% AbstractLongHeap.add5.0% 4.1% IntHashSet.add4.9% 5.0% VamanaDiversityProvider.isDiverse2.7% 2.0% Compositionally these are the same phase. The silent stretch is JVector still building the graph, evaluating distances and maintaining the same heaps, just with no progress output. So the answer to what it is doing is: the same thing, for another 23 minutes.
Which means I was wrong to withdraw the number
I withdrew "~28% of the entire dense build is a statistics counter" on the grounds that it scaled a rate measured in one phase across a build I had not checked for uniformity. That was the right thing to do with the evidence I had. Having now checked, the build is uniform across the 91.7% that is JVector, so the extrapolation holds:
LongAdder 28.1% x 0.386 (insertion) + 29.3% x 0.531 (silent) = 26.4% of the build squareDistance 45.3% x 0.386 + 46.3% x 0.531 = 42.1% of the build26.4%, against the 28% I originally claimed and then retracted. The retraction was methodologically correct and the number survived it.
VectorCache.getincrementinghits/misseson every distance evaluation costs roughly a quarter of a DEEP-10M build.The part that does not fit, and that I cannot explain
From the pool A/B in my previous comment:
phase 6 threads 12 threads scaling insertion 1023 s 534 s 1.92x silent 1407 s 1442 s 1.00x The two phases run the same code in the same proportions, and CPU sampling says the silent phase genuinely uses the whole pool in both arms (single tight cluster at 600% and at 1200%, not bimodal). So on 12 threads that phase burns twice the CPU for the same wall clock, while the phase next to it, doing the same work, scales almost perfectly.
I do not have an explanation. The obvious candidate is that ~29% of it is contention on two shared
LongAdders and contention gets worse with threads, but that cannot be the whole story or insertion would not have scaled 1.92x with the same 28% share. Something about the second phase's parallel structure differs from the first in a way the profile does not show me.Worth saying plainly: this is the opposite of what I guessed on this issue twice. I first said contention would limit the pool win, and insertion refuted that. Now the phase where contention plausibly does bite is the one I had no theory about at all.
What I think is actionable
- The counter is worth removing or gating regardless: 26.4% of a 45-minute build, measured per phase rather than extrapolated.
- The pool halving is worth undoing if build time matters, but it only reaches 38.6% of the build, which is why the whole-build win was 17.1%.
- The 53% phase is where the remaining time is, and it does not respond to threads. If you know why
cleanup-style work there would saturate the pool without going faster, that is the lever, and I would happily measure any hypothesis you have.
Corpus, box and profiler staged. Happy to run a variant with the counters stubbed out if you want the counterfactual rather than the attribution.
I said I had no explanation for the phase that burns 2x the CPU for 1.00x the throughput. I now have a candidate mechanism, and the reason nothing had found it is that the obvious instrument is structurally blind to it.
What I measured
Default configuration this time (cpuset 0-11, so
availableProcessors()/2gives a 6-thread pool, and the container sat at 600% CPU throughout). DEEP-10M fp32 build on released 26.8.1.dev23, profiled from t=1200s to t=1800s, which the earlier phase timings put inside the silent phase.Monitor contention: none.
asprof -e lock, 300 s : 0 stacks, 0 bytesThread balance: perfect.
ForkJoinPool-1-worker-1 16.16% ForkJoinPool-1-worker-2 16.16% ForkJoinPool-1-worker-3 16.16% ForkJoinPool-1-worker-4 16.16% ForkJoinPool-1-worker-5 16.16% ForkJoinPool-1-worker-6 16.16% (GC and G1 Conc threads take the remaining ~3%)Six workers, identical to two decimal places. No straggler, no idle worker, no imbalance.
OS-level parking: none. Strictly matching
Unsafe.park,LockSupport.park,Object.wait: 0.00%. The 16.66% that a looser pattern catches is allForkJoinTask.awaitDone, which is the join point doing work-stealing rather than blocking. Real lock frames (ReentrantReadWriteLock) total 0.34%.So the phase is not contended, not imbalanced, and not parked. Every worker is busy the whole time.
What they are busy with
47.66% PanamaVectorUtilSupport.squareDistancePreferred 31.04% LongAdder.add 5.07% AbstractLongHeap.upHeap 5.04% IntHashSet.add 4.62% AbstractLongHeap.add 2.20% VamanaDiversityProvider.isDiverseThe candidate mechanism
LongAddercontention is CAS contention, and-e lockcannot see it.That event instruments monitor and park contention.
LongAdderis lock-free: under contention it does not block, it spins on compare-and-swap against its striped cells. Threads that lose a CAS retry, which burns CPU without making progress, and which appears in a CPU profile as ordinary time insideLongAdder.add.That fits every observation at once:
- an empty lock profile is exactly what a CAS-contended counter looks like;
- the pool is saturated and balanced because every thread genuinely has work, some of it being retry;
- adding threads adds CAS pressure on the same cells, so 2x the threads can yield 2x the CPU and roughly 1x the throughput;
- and it is invisible to every instrument tried so far, which is why three rounds of profiling described the phase accurately without explaining it.
I want to be clear about the epistemic status. The six facts above are measured. The mechanism is a hypothesis that fits them. It is not proven by them.
The test that would settle it
Stub or gate the
VectorCachehit/miss counters and re-run the 6-thread against 12-thread A/B. If the mechanism is right, the silent phase starts scaling and the 1.00x moves toward the insertion phase's 1.92x. If it does not move, the counter is expensive but not the scaling limiter, and the next candidate is memory bandwidth, which needs hardware counters rather than a profiler.This is the same counterfactual I offered before and it is now much better motivated: it is no longer just "26.4% of the build is a statistics counter", it is "the counter is the only shared mutable state in a phase that is otherwise perfectly parallel".
I have the corpus, the box and the profiler staged, and I am happy to run that A/B against any branch with the counters gated. Given that the counter is 31% of this phase and 26.4% of the whole build, and that on this evidence it is also the reason the build pool cannot be widened profitably, gating it looks like it buys more than the arithmetic alone suggested.
One methodological note, since it cost me a run
My first attempt at this profiled the wrong phase.
l3d_dense.pyprints exactly one line, at the end, so my "wait for progress output to stop" detector fired 100 seconds in, while the build was still memory-mapping the dataset, and armed the profiler on the data load. The second attempt targets the phase by elapsed time using the fractions measured earlier (insertion 38.6%, silent 53.1%).I also ran a positive control before believing the empty lock profile: six threads hammering one
ReentrantLockin the same container with the same binary and the same command produced 1,013,125 units across one stack. The event works here. The zero is real.- added a commit that references this issue
on Aug 7, 2026 Fixed in #5869 (merged, 12707d0). Thank you for this one - the measurement quality made all three findings actionable, and the last one was only findable because you kept going after the first answer did not fit.
1. The counter is gone
You were right, and right about why the usual instrument could not see it.
VectorCache.get()now increments per-thread striped counters on their own cache lines with plain (opaque) reads and writes instead of two process-wideLongAdders. An isolated benchmark of the lookup path measures 2-5x less time per lookup depending on thread count;VectorCacheCounterBenchmarkis in the tree under@Tag("benchmark")if you want to re-run it on your box.vectorCacheHits/vectorCacheMissessurvive ingetStats()- your harness keeps working. They are now approximate: two threads landing on the same stripe can lose an increment, so a count can come out low, never high. A hit ratio is unaffected.2. The halving was not deliberate
git log -Ssettles it: it arrived in d22882c, "fix: use own pool for vector index rebuild". That commit exists so a build can be cancelled on close, and the/2came along for the ride. It was never measured against anything.The automatic width is now the core count minus one, and
arcadedb.vectorIndex.graphBuildParallelismoverrides it. One core is deliberately left free: a rebuild can fire on a live index at any time and must not be able to occupy every core the request, I/O and GC threads need. For your bulk-import case, set it to the full count.getStats()reports the effective width asgraphBuildParallelism.3. There is no silent phase
This is the part worth reading, because it invalidates the phase split all three of your profiling rounds were built on.
The meter polled JVector's
getIdUpperBound(), which is "highest node id touched so far + 1". Insertion isIntStream.range(0, size).parallel(), and Java'sForEachTask.compute()forks the left half and descends into the right - so the submitting worker walks to the top leaf of the range and processes it first. The meter therefore pins at 100% once one worker has finished roughly1/leavesof the corpus, whereleaves ≈ 4 × parallelism.That reproduces your numbers exactly:
- your first progress line read 9,060,381 five seconds in. That is not 90.7% of the work done, it is the start of the top leaf - the range position where the first worker began;
- the meter then crept to 9,990,000 as that one worker walked its own leaf, and hit 100% when it finished it;
- doubling the pool doubles the leaf count and halves that leaf. 1023 s → 534 s. Your "1.92x insertion scaling" is the leaf halving, measured to two significant figures, and has nothing to do with throughput;
- which is why the "silent" remainder showed 1.00x: it is simply everything the meter stopped reporting, and it grows by exactly what the first bucket lost.
Summing the two buckets, JVector's real scaling on your A/B is 2430 s → 1976 s = 1.23x. Sublinear, unremarkable, and the whole-build 17.1% follows from it. There was never a phase that burned 2x the CPU for 1x the throughput - so the empty lock profile, the perfect thread balance and the absent parking were all telling you the truth about a phase boundary that did not exist. Your instruments were fine; the clock they were synchronised to was not.
Fixed properly rather than patched: the build now drives JVector's insertion and its
cleanup()pass itself (the same two stepsbuild()performs, on the same pool) and counts insertions that have actually returned.processedNodesmeans what it says, andprocessedNodes + insertsInProgresscan no longer exceed the corpus size - the invariant the old meter broke, which your own9990000/9990000 (vector accesses=9990006)line recorded. That is what the new regression test asserts, and it fails against the old meter with the same signature;- you get the log lines you asked for twice: one when insertion ends and one when the post-insertion pass ends, each with its elapsed time, so the phase is measurable instead of inferable from an absence of output;
GraphBuildCallbackgains anoptimizingphase for that pass, documented as explicitly not a quick finalisation.
One thing your report led to that is not fixed here
Writing a cancellation test for the build pool turned up a separate, pre-existing defect:
shutdownNow()on the build pool does not reliably abort an in-flight build, so closing a database can leave a thread parked onForkJoinTask.join()- roughly half of runs in a local repro. It predates this change (the samesubmit(...).join()shape is inside JVector'sbuild()), so it was kept out of #5869 rather than shipped with a flaky test. Filed separately as #5872.If you re-run DEEP-10M against
main, the interesting number is no longer the whole-build time but the two phase lines: insertion and optimization are now separately measurable for the first time.- addedconcurrencyThreading / concurrency / MVCCThreading / concurrency / MVCCengineCore engine: document/schema APICore engine: document/schema APIvectorVector index and embedding searchVector index and embedding search
on Sep 2, 2026
A question rather than a defect report, with the measurement that prompted it.
Where the dense build time actually goes
Our paper carries a dense build-time loss (DEEP-10M, 9.99M vectors, 96d,
maxConnections=32,beamWidth=100): 2,693 s against 142 s for Milvus and 516 s for Qdrant. We had been treating that as an ArcadeDB storage-path cost and were about to go profiling. We did not need to: your own log timestamps the boundary, so the split was free to compute from a run already on disk.Building JVector graph indextoBuilt graph(2,913 s total on the 16 GiB-heap run; the two markers are
LSMVectorIndexBuilding graph with 9990000 vectorsandBuilt graph.)So the record path is not the problem. ArcadeDB ingests 10M vectors at roughly 52,000/s and that is 7% of the build; essentially all of the rest is graph construction inside JVector. We have corrected our own framing accordingly, and the paper now attributes that row to the library rather than to your storage layer.
The question
The one ArcadeDB-side lever we can see inside that 93% is the build pool:
On our 12-CPU cpuset that is 6 threads while 6 CPUs sit idle, for the phase that is 93% of the build. Is the halving deliberate? The reasons we can think of are good ones: leaving headroom so an online index build does not starve concurrent query traffic, or a build that is memory-bandwidth-bound where extra threads buy nothing. If either is the reason, that is the answer and we will stop here.
What we are running either way
An A/B that doubles the pool without patching anything, using
-XX:ActiveProcessorCount=24so the JVM reports 24 and the pool becomes 12 on the same 12 real CPUs. Same wheel, same data, samemaxConnections=32. Container CPU is sampled through the graph phase, since 6 saturated threads read about 600% and 12 read about 1200%, which checks that the pool size is what changed rather than inferring it from elapsed time. There is a guard that aborts if the flag does not actually moveavailableProcessors(), because an unread knob would make both arms identical and read as a tidy null result.If forcing 12 threads cuts the graph phase materially, that is a concrete report about the heuristic and we will bring the numbers. If it does not, the halving costs nothing, and the remaining gap is a JVector question rather than yours. We will post the result whichever way it goes.
Not asking for anything yet. If the
/2is intentional it would be worth a sentence in the Javadoc saying why, since the next person to look at a 45-minute graph build on a half-idle box will ask exactly this.