Big result queries are slow compared to SQLite3 CLI or other clients

[SebastianSzturo]

I've noticed that large queries are significantly slower via ecto_sqlite3 than through the sqlite3 CLI when using Ecto or Exqlite.Connection (not with Exlite.Sqlite3)

Here is the example data of ~650k rows: dev.db.zip

Via SQLite3 CLI or any other SQLite3 GUI (with wal mode enabled):

sqlite> .timer on
sqlite> SELECT transaction_date, transaction_amount FROM transactions;
Run Time: real 2.680 user 0.423684 sys 0.323269
sqlite>

With Exqlite.Connection: 21.98 s

     {:ok, db} =
      DBConnection.start_link(Exqlite.Connection,
        database: "./dev.db",
        journal_mode: :wal,
        cache_size: -64000,
        temp_store: :memory
      )

    {:ok, _, result} =
      DBConnection.execute(
        db,
        %Exqlite.Query{
          statement: "SELECT transaction_date, transaction_amount FROM transactions"
        },
        []
      )

 Name                         ips        average  deviation         median         99th %
exqlite_connection     0.00005 K        21.98 s     ±0.00%        21.98 s        21.98 s

Same with Ecto : 21520.2ms

Ecto.Adapters.SQL.query(
  Repo,
  "SELECT transaction_date, transaction_amount FROM transactions"
)

[debug] QUERY OK db=21520.2ms decode=1.4ms idle=106.7ms
SELECT transaction_date, transaction_amount FROM transactions []

Any idea what this could be caused by and how to debug it further?

[SebastianSzturo]

Here is a full benchmark example of the performance difference with a limit 10000 to make the performance difference clearer without having the client timeout in the connection example:

EDIT: This benchmark is wrong, and bot approaches are equally slow.

```elixir Benchee.run(%{ "exqlite_direct" => fn -> {:ok, conn} = Exqlite.Sqlite3.open("./dev.db") {:ok, statement} = Exqlite.Sqlite3.prepare( conn, "SELECT transaction_date, transaction_amount FROM transactions limit 10000" ) end, "exqlite_connection" => fn -> {:ok, db} = DBConnection.start_link(Exqlite.Connection, database: "./dev.db", journal_mode: :wal, cache_size: -64000, temp_store: :memory ) {:ok, _, result} = DBConnection.execute( db, %Exqlite.Query{ statement: "SELECT transaction_date, transaction_amount FROM transactions limit 10000" }, [] ) end }) ``` ``` Operating System: macOS CPU Information: Apple M1 Number of Available Cores: 8 Available memory: 16 GB Elixir 1.13.3 Erlang 24.3.3 Benchmark suite executing with the following configuration: warmup: 2 s time: 5 s memory time: 0 ns reduction time: 0 ns parallel: 1 inputs: none specified Estimated total run time: 14 s Benchmarking exqlite_connection ... Benchmarking exqlite_direct ... Name ips average deviation median 99th % exqlite_direct 5.51 K 0.182 ms ±107.54% 0.166 ms 1.28 ms exqlite_connection 0.0620 K 16.12 ms ±14.25% 15.52 ms 25.96 ms Comparison: exqlite_direct 5.51 K exqlite_connection 0.0620 K - 88.76x slower +15.94 ms ```

[warmwaffles]

DB Connection has the overhead of pooling connections and all that jazz that makes it play nice with postgres, mysql, and mssql. This is something to keep in mind.

[warmwaffles]

In your test you also do not send the same options for {:ok, conn} = Exqlite.Sqlite3.open("./dev.db")

[warmwaffles]

I'll definitely look into this more and maybe throw this into a benchmark that we similarly do for ecto_sqlite3

[SebastianSzturo]

Thank you for your reply and taking a look at this, I really appreciate it the hard work you are doing on this package! 🙇🏻‍♂️

Also sorry, I've messed up a bunch of things in the benchmarks. I also forget to actually call step on the statement in the first example... here is a bit of a more complete benchmark but still reproduces the same issue:

EDIT: This benchmark is wrong, and bot approaches are equally slow.

```elixir Benchee.run(%{ "exqlite_direct" => fn -> {:ok, conn} = Exqlite.Sqlite3.open("./dev.db") {:ok, statement} = Exqlite.Sqlite3.prepare( conn, "PRAGMA journal_mode = wal;" <> "PRAGMA temp_store = memory;" <> "PRAGMA synchronous = normal;" <> "PRAGMA foreign_keys = on;" <> "PRAGMA cache_size = -64000;" <> "PRAGMA cache_spill = on;" <> "SELECT transaction_date, transaction_amount FROM transactions limit 10000" ) Exqlite.Sqlite3.multi_step(conn, statement) end, "exqlite_connection" => fn -> {:ok, db} = DBConnection.start_link(Exqlite.Connection, database: "./dev.db", journal_mode: :wal, cache_size: -64000, temp_store: :memory ) {:ok, _, result} = DBConnection.execute( db, %Exqlite.Query{ statement: "SELECT transaction_date, transaction_amount FROM transactions limit 10000" }, [] ) end }) ``` ``` Operating System: macOS CPU Information: Apple M1 Number of Available Cores: 8 Available memory: 16 GB Elixir 1.13.3 Erlang 24.3.3 Benchmark suite executing with the following configuration: warmup: 2 s time: 5 s memory time: 0 ns reduction time: 0 ns parallel: 1 inputs: none specified Estimated total run time: 14 s Benchmarking exqlite_connection ... Benchmarking exqlite_direct ... Name ips average deviation median 99th % exqlite_direct 5.84 K 0.171 ms ±92.80% 0.164 ms 0.98 ms exqlite_connection 0.0614 K 16.28 ms ±7.63% 16.06 ms 20.96 ms Comparison: exqlite_direct 5.84 K exqlite_connection 0.0614 K - 95.11x slower +16.11 ms ```

The Query is as fast as expected in other clients like Ruby (ActiveRecord & standalone) or Python

[warmwaffles]

I suspect something is funky with db connection or with how I implemented it.

[warmwaffles]

@SebastianSzturo multi_step/2 is not the function you want to call. You'll want to instead call fetch_all/2.

Multi step only goes into the NIF and runs sqlite3_step(statement->statement) chunk_size times. fetch_all/2 does exactly what the name says and grabs all the rows of the query. You'll probably find out that it is just as fast as exqlite_connection.

[SebastianSzturo]

You are totally right, now that I properly debugged my benchmark code and used fetch_all/2 for the direct approach, both codepaths are equally slow.

Some really amateur-ish IO.inspect debugging shows that it is indeed fetch_all and stepping through all results and building a list that takes a long time and not the database:

Connection.handle_execute.start: 2022-04-09 10:46:14.821665
handle_execute_start: 2022-04-09 10:46:14.822756
prepare_start: 2022-04-09 10:46:14.822766
prepare_ok: 2022-04-09 10:46:14.822842
handle_execute_before_execute: 2022-04-09 10:46:14.822864
execute_start: 2022-04-09 10:46:14.822872
bind_params: 2022-04-09 10:46:14.822879
get_columns: 2022-04-09 10:46:14.822890
get_columns_return: 2022-04-09 10:46:14.822906
get_rows: 2022-04-09 10:46:14.822917
fetch_all: 2022-04-09 10:46:36.672343 <--- Takes 22 seconds.
returning_result: 2022-04-09 10:46:36.672480
Result.new: 2022-04-09 10:46:36.675554
Connection.handle_execute.end: 2022-04-09 10:46:36.675590

And turns out you call this issue out in the comments: https://github.com/elixir-sqlite/exqlite/blob/main/lib/exqlite/sqlite3.ex/#L125-L133

It looks like other SQLite libraries like sqlite3-ruby do all of that in C. I am very surprised that it is so much slower in Elixir!

I am not sure how much of an impact this has on small queries but it seems to become really noticeable with >5000 rows. I am not quite sure how NIFs work in Erlang and what the bigger evil here would be of blocking the NIF for longer 😅

[SebastianSzturo]

Here is some interesting background on lists in Elixir/Erlang that you probably already know but helped me understand the problem better: https://www.wyeworks.com/blog/2019/03/01/to-use-or-not-to-use-the-++-operator-in-elixir/

[SebastianSzturo]

I've opened a PR to try to improve the performance by prepending the list and reversing at the end, instead of appending it: https://github.com/elixir-sqlite/exqlite/pull/200 (Up to 73x faster for 1m records!)

[SebastianSzturo]

Thanks for the quick review and merge. My queries are now blazing fast 🔥

SQLite3 + Livebook are a quite unbeatable team when it comes to analyzing big data sets. Thank you for making that possible!!