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

</details?

[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.

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/