Segfault when exceeding DBConnection timeout

[LostKobrakai]

I was debugging a sudden reboot on our nerves system with a expensive query. I had the memory usage and OOM in mind, but today I found out that raising the timeout actually makes the query succeed (no reboot). Making the timout be exceeded on my local machine I could reproduce the issue and even get the seg fault message (see below). I don't think the query matters for as long as the timeout is exceeded.

iex(6)> Task.start(fn -> Repo.checkout(fn -> Ecto.Adapters.SQL.query!(Repo, query) end, timeout: :timer.seconds(1)) end)
{:ok, #PID<0.2359.0>}
iex(7)> 11:24:58.427 [error] Exqlite.Connection (#PID<0.2164.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2359.0> timed out because it queued and checked out the connection for longer than 1000ms

#PID<0.2359.0> was at location:

    (exqlite 0.8.6) lib/exqlite/sqlite3.ex:91: Exqlite.Sqlite3.multi_step/3
    (exqlite 0.8.6) lib/exqlite/sqlite3.ex:138: Exqlite.Sqlite3.fetch_all/4
    (exqlite 0.8.6) lib/exqlite/connection.ex:529: Exqlite.Connection.get_rows/2
    (exqlite 0.8.6) lib/exqlite/connection.ex:475: Exqlite.Connection.execute/4
    (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
    (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
    (db_connection 2.4.1) lib/db_connection.ex:650: DBConnection.execute/4

11:25:00.283 [debug] …
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed
[os_mon] memory supervisor port (memsup): Erlang has closed
[1]    37300 segmentation fault  iex -S mix

[LostKobrakai]

I just saw this one, which is probably related: #127

[SebastianSzturo]

I am still seeing the segfault described above in my app.

19:21:45.978 [error] Exqlite.Connection (#PID<0.2619.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2866.0> timed out because it queued and checked out the connection for longer than 15000m
signal: segmentation fault

Is there a way to increase this timeout? I don't think any of the timeout settings are affecting it for me.
Any way I can help to debug it?

[warmwaffles]

Which version are you running?

Do you have a reliable way to reproduce the segfault?

[SebastianSzturo]

I am running on master. I'll try to reproduce it in a test file to share and report back 👍🏻

[keatz55]

Experiencing the same issue. In our case, we've set DBConnection :timeout and Exqlite :busy_timeout to the same value. Could a potential cause be that the DBConnection execute times out and terminates Exqlite before it has an opportunity to free up memory? Then on the subsequent connection creation, Exqlite attempts to allocate memory on the wrong block of data?

[warmwaffles]

Could a potential cause be that the DBConnection execute times out and terminates Exqlite before it has an opportunity to free up memory?

So as it stands right now with the DirtyNIF implementation, the DBConnection will crash but the query running in the background never actually gets terminated. If you are operating on a large database it is quite possible that your query would continue to run even if the connection timed out.

I have been meaning to find time to swap out the DirtyNIF model for a runtime that can cancel running queries.

Then on the subsequent connection creation, Exqlite attempts to allocate memory on the wrong block of data?

We are using enif_alloc/1 and enif_free/1 under the hood for all sqlite memory allocations. This is so that when you look at the live dashboard or query the VM you can see accurate memory usage by the erlang process. Otherwise the bytes that sqlite uses would not be tracked.

exqlite/c_src/sqlite3_nif.c

Lines 32 to 107 in 2c9fa05

	static void*
	exqlite_malloc(int bytes)
	{
	assert(bytes > 0);
	int* p = enif_alloc(bytes + sizeof(int));
	if (p) {
	p[0] = bytes;
	p++;
	}
	return p;
	}
	static void
	exqlite_free(void* prior)
	{
	if (!prior) {
	return;
	}
	int* p = prior;
	// Shift the pointer back to free the proper block of data
	p--;
	enif_free(p);
	}
	static void*
	exqlite_realloc(void* prior, int bytes)
	{
	assert(prior);
	assert(bytes > 0);
	int* p = prior;
	p--;
	p = enif_realloc(p, bytes + sizeof(int));
	if (p) {
	p[0] = bytes;
	p++;
	}
	return p;
	}
	static int
	exqlite_mem_size(void* prior)
	{
	if (!prior) {
	return 0;
	}
	int* p = prior;
	p--;
	return p[0];
	}
	static int
	exqlite_mem_round_up(int bytes)
	{
	return (bytes + 7) & ~7;
	}
	static int
	exqlite_mem_init(void* ptr)
	{
	return SQLITE_OK;
	}
	static void
	exqlite_mem_shutdown(void* ptr)
	{
	}

It is entirely possible that I encoded a bug there, but I don't think that is the case. The first sizeof(int) of the bytes allocated are reserved for the block size of memory.

[warmwaffles]

What would be really helpful is if there is a way I can replicate this error repeatedly.

[pavancse17]

Hey @warmwaffles ,

I have been working with @keatz55 on recreating this issue. here is the test case that you can use to reproduce in your machine. Also what we noticed in our testing is that when we adjust timeout value to double the value of busy_timeout. we are not getting any segfaults.

test "Reproduce seg fault" do
    path = "./test.db"

    {:ok, conn} =
      DBConnection.start_link(Connection,
        busy_timeout: 50000,
        pool_size: 50,
        timeout: 1,
        database: "./test.db",
        journal_mode: :wal
      )

    query = %Query{statement: "create table foo(id integer, val integer)"}
    {:ok, _, _} = DBConnection.execute(conn, query, [])

    values = for i <- 1..1000, do: "(#{i}, #{i})"

    insert_query = %Query{
      statement: "insert into foo(id, val) values #{Enum.join(values, ",")}"
    }

    Task.async_stream(1..5000, fn _val ->
      try do
        DBConnection.execute(conn, insert_query, [],
          busy_timeout: 50000,
          timeout: 1
        )
      catch
        kind, reason ->
          IO.inspect("#{inspect(kind)} #{inspect(reason)}", label: "Error")
      end
    end)
    |> Stream.run()
  end

Output:

00:46:45.859 [error] Exqlite.Connection (#PID<0.277.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.519.0> timed out because it queued and checked out the connection for longer than 1ms

#PID<0.519.0> was at location:

    (exqlite 0.11.4) lib/exqlite/connection.ex:500: Exqlite.Connection.prepare/3
    (exqlite 0.11.4) lib/exqlite/connection.ex:194: Exqlite.Connection.handle_execute/4
    (db_connection 2.4.2) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
    (db_connection 2.4.2) lib/db_connection.ex:1364: DBConnection.run_execute/5
    (db_connection 2.4.2) lib/db_connection.ex:1459: DBConnection.run/6
    (db_connection 2.4.2) lib/db_connection.ex:652: DBConnection.execute/4
    test/exqlite/integration_test.exs:225: anonymous fn/3 in Exqlite.IntegrationTest."test Reproduce seg fault"/1
    (elixir 1.13.4) lib/task/supervised.ex:89: Task.Supervised.invoke_mfa/2
    (elixir 1.13.4) lib/task/supervised.ex:34: Task.Supervised.reply/4
    (stdlib 4.0.1) proc_lib.erl:240: :proc_lib.init_p_do_apply/3

zsh: segmentation fault  mix test test/exqlite/integration_test.exs:202

[warmwaffles]

Excellent news! I'll take a look at this soon.

[warmwaffles]

The busy_timeout here

        DBConnection.execute(conn, insert_query, [],
          busy_timeout: 50000,
          timeout: 1
        )

Has no effect on the query itself. The busy_timeout is used for only connecting to the database which runs PRAGMA busy_timeout = 50000

But that timeout is definitely something happening with the DBConnection pooling.