Skip to content

REPL: first cross-index JOIN takes ~2.4s (up to 10s cold) vs ~100ms for subsequent ones — one-time init lands in the user's first query #163

Description

@fupelaqu

The first cross-index JOIN in a REPL session takes seconds; every subsequent identical JOIN takes ~100ms. The work is one-time initialisation, not query cost — but it lands in the user's first query, which is exactly where it is most visible (and, for the launch demo, most embarrassing).

Reproduction

Three identical JOINs plus a non-JOIN in a single JVM (softclient4es -f perf.sql, 5 rows in emp, 3 in dept, ES 8.18.3 local):

=> SELECT e.name, e.salary, d.dept_name FROM emp e JOIN dept d ON e.dept_id = d.dept_id ORDER BY e.salary DESC
📊 5 row(s) (2431ms)      <-- first
📊 5 row(s) (104ms)       <-- second
📊 5 row(s) (86ms)        <-- third

An interactive session on a cold machine showed 9784ms for the first JOIN then 349ms — same shape, larger constant (cold OS page cache over the 278 jars in lib/, plus a first-ever native-library extraction).

Measured breakdown of the 2431ms

From the REPL log timeline (first JOIN starts at 17:07:55.131):

Phase Cost Evidence
Extension discovery + initialize() 442ms 55.131 SQL received → 55.573 "🔌 Initializing Cross-index JOIN extension". ExtensionRegistry.extensions is a lazy val (core/.../client/ExtensionRegistry.scala:37-51) that runs ServiceLoader.load(classOf[ExtensionSpi]) across 278 jars and initialises every extension on first access
Arrow allocator + license guard 43ms 55.577 BaseAllocator init → 55.616 "Federation license guard passed: Community"
Leg queries against ES 420ms 55.61656.036: PIT open + scroll on emp and dept, both mappings retrieved
DuckDB first use ~1520ms 56.036 ("✅ Index 'dept' retrieved successfully") → 57.583 (next query) — a completely silent window, no log line in it

The DuckDB attribution is backed by the artefact itself: lib/duckdb_jdbc-1.5.2.1.jar is 80 MB and contains a 103 MB libduckdb_java.so_osx_universal (plus linux amd64/arm64 and windows payloads). The first DriverManager.getConnection("jdbc:duckdb::memory:…") (arrow-join/.../executor/DuckDBJoinExecutor.scala:267) extracts and loads that native library. Runs 2 and 3 reuse it — hence the collapse to ~100ms.

Note the two costs are triggered by different events: extension discovery is forced by the first query of any kind, DuckDB loading by the first JOIN. A session that runs a plain SELECT first has already paid the 442ms.

Proposed fixes, highest value first

  1. Warm up inside JoinExtension.initialize() — asynchronously. The engine belongs to the extension that owns it, so the warm-up belongs in its SPI lifecycle hook (arrow-ext/.../join/JoinExtension.scala:80-91), which already receives the Config and today only stashes arrow.join.max-memory / query-timeout-seconds. Fire a daemon-thread warm-up that opens and immediately closes a jdbc:duckdb::memory: connection, forcing the native-library load, and return Right(()) at once.

    It must be asynchronous. initialize() is called synchronously inside the ExtensionRegistry.extensions lazy val (ExtensionRegistry.scala:45), which is forced by the first query of any kind — a blocking load there would just relocate the 1.5s onto the first plain SELECT, a regression for users who never JOIN. The join path should await the shared warm-up Future rather than racing or re-triggering it.

    Two constraints: a warm-up failure must not fail initialize() (that deregisters the extension and disables JOINs entirely — log it and let the first real JOIN surface a genuine error), and it must open-then-close rather than hold a connection, since the cost is JVM-global native-library loading and DuckDBJoinExecutor deliberately closes connections after each query with "no shared state".

    This beats warming up from the REPL, which was the original proposal here: elasticsql core has no DuckDB dependency (it arrives only transitively via the extension), so core cannot open that connection without hardcoding a JDBC URL for one specific extension's engine — precisely the coupling the SPI boundary exists to prevent. Doing it in the extension also covers every venue at once (REPL, JDBC driver, Flight SQL, federation, ADBC) and is naturally inert under --no-extensions.

  2. Initialise extensions eagerly instead of on first access, folding the 442ms into startup (naturally covered by fix 1).

  3. AppCDS — generate a class-data archive and add -XX:SharedArchiveFile in bin/softclient4es. Class loading across 278 jars is a large share of both JVM startup and first query.

  4. Reduce the jar countarrow-ext alone resolves to ~256 dependency jars. A shaded extension artifact would shrink the ServiceLoader scan and the classpath walk.

Batch mode caveat

This cost is per JVM. Interactive sessions pay it once, but -c / -f invocations pay it on every run — scripted or CI usage that shells out per query eats ~2.4s each time.

Async warm-up (fix 1) gives batch mode only a partial win: the warm-up starts when the extension initialises and overlaps the ~420ms of leg queries, so a one-shot JOIN recovers some but not all of the 1.5s. Closing the rest for batch mode needs the work itself reduced (fixes 3–4). Worth deciding whether batch mode deserves its own treatment.

Acceptance criteria

  1. In an interactive session, the first JOIN completes in the same order of magnitude as subsequent ones (target: within ~2× rather than ~28×).
  2. A session that never runs a JOIN does not get slower. This is the main regression risk of warming up at extension-init time: initialize() runs on the first query of any kind, so a plain SELECT-only workload must be unaffected (i.e. the warm-up is genuinely off-thread). Measure a SELECT-only session before/after.
  3. The REPL prompt still appears immediately — warm-up must not block startup.
  4. --no-extensions installs and Java-8-era setups are unaffected (no new hard dependency on the arrow classes being present).
  5. Ideally the silent ~1.5s DuckDB window gains a log line, so this is diagnosable next time without bisecting timestamps.

Found while verifying the 0.20.1 REPL after the #158 fix.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions