Parallel queries blocks nodejs/libuv worker pool

[alex3d]

node-sqlite3 runs queries for the distinct prepared statements in independent worker pool tasks but all sqlite3 queries to the same sqlite3 connection internally serialized on the mutex. So other libuv worker pool tasks (dns resolution, crypto, etc) could be delayed while the pool spends a large amount of time waiting on sqlite3 mutex.

Wall clock profiling flamegraph (thread pool spends ~34% of wall clock time waiting on sqlite3 mutex):

Probably all queries (including prepared statement queries) to the same Database should be scheduled in the single queue.

[indutny-signal]

This is a valid issue. For anyone wondering this is solved by calling db.serialize() (yes, without callback) right after opening the database.

[daniellockyer]

@alex3d Looks like we should fix that 🙂 Do you have a short reproduction we can test with?

[alex3d]

You could try this for (not too) short reproduction:

const sqlite3 = require('./lib/sqlite3');
const {promisify} = require('util');
const {performance} = require('perf_hooks');

const CONCURRENCY = 10;
const QUERIES = 2000;
const zlib = require('zlib');

async function main() {
  const db = new sqlite3.Database(':memory:');
  const prepare = (sql) => new Promise((resolve, reject) => {
    const stmt = db.prepare(sql, err => {
      if (err===null)
        resolve(stmt);
      else
        reject(err);
    });
  });

  await promisify(db.run).call(db, "CREATE TABLE lorem (info TEXT)");
  const insert = await prepare("INSERT INTO lorem VALUES (?)");
  for (let i = 0; i < 2000; i++) {
      await promisify(insert.run).call(insert, "Ipsum " + i);
  }

  const selectStatements = await Promise.all(Array.from({length: CONCURRENCY}, ()=>prepare("SELECT max(id), max(info) FROM (SELECT rowid AS id, info FROM lorem) GROUP BY id%500;")));
  const selectAll = selectStatements.map(s=>promisify(s.all.bind(s)));

  const T0 = Date.now(), ELU0=performance.eventLoopUtilization();

  const deflate = promisify(zlib.deflate);
  const deflateTiming = [];
  let int = setInterval(async ()=>{
    const T0=performance.now();
    await deflate(Buffer.from("asdf"));
    const T1=performance.now();
    deflateTiming.push(T1-T0);
  }, 10);

  await Promise.all(Array.from({length: QUERIES}, (_,i) => selectAll[i%selectAll.length]().then(v=>JSON.stringify(v)) ));

  deflateTiming.sort((a, b) => a-b);
  let medianTiming = deflateTiming[(deflateTiming.length/2)|0].toFixed(3);

  const T1 = Date.now(), ELU1=performance.eventLoopUtilization(ELU0);
  console.log(`${QUERIES} queries complete in ${(T1-T0)} ms,  ${(T1-T0)/QUERIES} ms per SELECT, event loop utilisation=${(ELU1.utilization*100).toFixed(0)}%`+
    `, median libuv thread pool queue latency = ${medianTiming} ms`);
  clearInterval(int);
}

main().catch(console.error);

CONCURRENCY= 1: 2000 queries complete in 1840 ms,  0.92 ms per SELECT, event loop utilisation=84%, median libuv thread pool queue latency = 0.924 ms
CONCURRENCY= 3: 2000 queries complete in 1748 ms,  0.874 ms per SELECT, event loop utilisation=88%, median libuv thread pool queue latency = 0.975 ms

CONCURRENCY=10: 2000 queries complete in 1688 ms,  0.844 ms per SELECT, event loop utilisation=91%, median libuv thread pool queue latency = 10.995 ms
CONCURRENCY=20: 2000 queries complete in 1936 ms,  0.968 ms per SELECT, event loop utilisation=81%, median libuv thread pool queue latency = 32.638 ms

As you could see when there are more than 4 concurrent queries (default libuv thread pool size) queue latency spikes up.
It is now shown by this repro but with 2-3 concurrent queries some thread pool threads are still uselessly blocked by node-sqlite3.