Help with debugging sqlite's 'busy' error with Ecto3

Hi all

This issue: https://github.com/elixir-sqlite/sqlite_ecto2/issues/244

I’ve been trying a gung-ho approach to updating ecto_sqlite2 to support ecto3, and on the surface it seems to be straightforward enough: implement the new callbacks, make sure functions return updated responses etc. And now I’m stuck in an issue when running ecto tests:

when running ecto’s Migrator.up , the code seemingly runs all the statement until it tries to insert data into one of the tables. Sqlite returns busy , and then the migration fails with

{"busy",0}
{"busy",1}
{"busy",2}
{"busy",3}
{"busy",4}
{"busy",5}


Sqelect.DbConnection.Protocol (#PID<0.278.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.319.0> exited
** (Sqelect.DbConnection.Error) {{:bad_return_value, :too_many_tries}, {GenServer, :call, [#PID<0.315.0>, {:query_rows, "INSERT INTO \"schema_migrations\" (\"version\",\"inserted_at\") VALUES (?1,?2)", [timeout: :infinity, decode: :manual, types: true, bind: [0, "2020-07-28T13:25:33"]]}, :infinity]}}
    (ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:593: Ecto.Adapters.SQL.raise_sql_call_error/1
    (ecto 3.4.5) lib/ecto/repo/schema.ex:661: Ecto.Repo.Schema.apply/4
    (ecto 3.4.5) lib/ecto/repo/schema.ex:263: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (ecto_sql 3.4.5) lib/ecto/migrator.ex:641: Ecto.Migrator.verbose_schema_migration/3
    (ecto_sql 3.4.5) lib/ecto/migrator.ex:293: Ecto.Migrator.async_migrate_maybe_in_transaction/6
    (ecto_sql 3.4.5) lib/ecto/migrator.ex:211: anonymous fn/5 in Ecto.Migrator.up/4
    (ecto_sql 3.4.5) lib/ecto/migrator.ex:493: Ecto.Migrator.lock_for_migrations/4
    integration/sqelect/test_helper.exs:93: (file)

The problem is: I don’t have enough knowledge of either Ecto or Elixir to properly debug this issue. If anyone has some spare time to look at this, it would be greatly appreciated.

Not sure you can get any guarantees since the library is only guaranteed to work with Ecto 2.

But, in this case maybe you just haven’t opened it with the right mode (should be serial).

1 Like

Not sure you can get any guarantees since the library is only guaranteed to work with Ecto 2.

That’s why I’m attempting to port it to Ecto 3 :slight_smile:

in this case maybe you just haven’t opened it with the right mode (should be serial).

Thank you, I’ll look into that! (even though the underlying esqlite doesn’t let you provide modes)

:wave:

AFAIK Ecto 3 locks tables and uses two connections to the db during migrations. Maybe you can use some combination of :migration_lock option and the number of connections pool_size: 1 to work around your problem.


I couldn’t make your example work since it’s missing a dependency:

Unchecked dependencies for environment dev:
* sqlitex (deps/sqlitex)
  the dependency is not available
** (Mix) Can't continue due to errors on dependencies
1 Like

Well, I am authoring an sqlite3 Elixir library (which is a bridge to an excellent Rust library) but life hasn’t been kind this year and I am just beginning to recover and might resume work on the first stable release Soon™.

1 Like

Ah! Thank you for the tip on the migration_lock_option! I’ll definitely look into that.

I couldn’t make your example work since it’s missing a dependency:

Replace {:sqlitex, "~>1.7.1", path: "deps/sqlitex"} with {:sqlitex, "~>1.7.1"} in mix.exs. I use path to sprinkle dependencies’ code with IO.inspect :slight_smile:

Just tried migration_lock: nil, pool_size: 1 and got a different error:

** (DBConnection.ConnectionError) could not checkout the connection owned by #PID<0.304.0>. 
When using the sandbox, connections are shared, so this may imply another process is using 
a connection. Reason: connection not available and request was dropped from queue after 2975ms. 
This means requests are coming in and your connection pool cannot serve them fast enough. 

Well, it’s progress :slight_smile: So I can look into the underlying cause more closely

I should’ve inspected more

Basically, the tests end up opening multiple connections anyway. For TestRepo:

{:connect,
 [
   pool_index: 1,
   repo: Ecto.Integration.PoolRepo,
   telemetry_prefix: [:ecto, :integration, :pool_repo],
   otp_app: :ecto,
   timeout: 15000,
   adapter: Sqelect,
   database: "/tmp/test_repo.db",
   pool_size: 10,
   migration_lock: nil,
   pool_size: 1
 ]}
{:connect,
 [
   pool_index: 1,
   repo: Ecto.Integration.TestRepo,
   telemetry_prefix: [:ecto, :integration, :test_repo],
   otp_app: :ecto,
   timeout: 15000,
   adapter: Sqelect,
   database: "/tmp/test_repo.db",
   migration_lock: nil,
   pool_size: 1
 ]}
{:connect,
 [
   pool_index: 6,
   repo: Ecto.Integration.PoolRepo,
   telemetry_prefix: [:ecto, :integration, :pool_repo],
   otp_app: :ecto,
   timeout: 15000,
   adapter: Sqelect,
   database: "/tmp/test_repo.db",
   pool_size: 10,
   migration_lock: nil,
   pool_size: 1
 ]}
...

For a total of 11 connections. And in my code I end up starting 11 sqlite gen servers which … is not ideal :slight_smile:

1 Like

Hello :wave:

I am rather fond of Sqlite and thought it would be fun to update sqlite_ecto2 so it works with Ecto 3.

I have hit the same {"busy",0..5} issue as @dmitriid.

This appears to be due to the Ecto migrator running the migration in a transaction via an async task, but before the transaction commits the parent task tries to insert into the schema_migrations table. I believe this is the cause of the busy responses because the SQLite database is locked at the beginning of the transaction which prevents the insert to the schema_migrations table from the parent connection.

This home-baked debug output from running the tests shows the PIDs associated with the relevant queries and you can see #PID<0.425.0> starts a transaction but then the parent #PID<0.426.0> tries an insert before the original transaction commits.

{#PID<0.426.0>,
 "CREATE TABLE IF NOT EXISTS \"schema_migrations\" (\"version\" BIGINT PRIMARY KEY, \"inserted_at\" NAIVE_DATETIME)"}
{#PID<0.426.0>, "SELECT s0.\"version\" FROM \"schema_migrations\" AS s0"}
{#PID<0.426.0>, "SELECT s0.\"version\" FROM \"schema_migrations\" AS s0"}

{#PID<0.425.0>, "BEGIN"}
12:09:43.870 [info]  == Running 0 Ecto.Integration.Migration.change/0 forward
12:09:43.873 [info]  create table users
{#PID<0.425.0>,
 "CREATE TABLE \"users\" (\"id\" INTEGER PRIMARY KEY, \"name\" TEXT, \"custom_id\" UUID, \"inserted_at\" NAIVE_DATETIME NOT NULL, \"updated_at\" NAIVE_DATETIME NOT NULL)"}
12:09:43.875 [info]  == Migrated 0 in 0.0s

{#PID<0.426.0>,
 "INSERT INTO \"schema_migrations\" (\"version\",\"inserted_at\") VALUES (?1,?2)"}

{"busy",0}
{"busy",1}
{"busy",2}
{"busy",3}
{"busy",4}
{"busy",5}

This seems to be related to the following function in ecto_sql:

Can anybody point me in the right direction so I can solve this in the adapter? I had a play with implementing lock_for_migrations/3 but don’t think this is relevant as there isn’t, to my knowledge, an SQLite command that would modify the behaviour I’m seeing.

I can get around the error by setting supports_ddl_transaction? to false in the adapter, but that doesn’t feel right as Sqlite3 does support DDL in transactions.

2 Likes

Hi @Lankester and @dimitarvp , have you made some progress on your implementations of Sqlite3 / Ecto3 ?

I would be glad to help. PM me :slight_smile:

Ah, I’ve got nothing to hide.

Recently started a new job and it’s taking most of my time – initial good impressions, you know.

Also due to the closure of the gyms I got hit by very low energy levels and I am not motivated to work on anything beyond the main job.

Happily though both things will come to an end soon (not the job itself, just the initial flurry of tasks in it) and I expect to resume work on xqlite. Going to spend an hour on the treadmill in the gym at Monday or I’ll change my name!

Last status was that I completely reworked the Rust code and it’s at least 5x faster now, plus much cleaner. And for my library the Rust code is honestly 90% of the work.

What can you do to help? Well, once I have the Rust code in place (which I do, but have to do a few final iterations on it, add some more unit tests and optionally benchmarks) and push it in the GitHub repo, you can contribute test scenarios and the tests themselves. Also I’d appreciate a second pair of eyes on the Elixir API design. Promise to keep you in the loop since you expressed interest. Expect actual updates in the next 2-4 weeks.

3 Likes

Don’t worry :slight_smile: We’re all at low energy levels. So take all the time you need.

Congrats on the new job!

1 Like

Today is treadmill day ! I wish you well :slight_smile:

2 Likes

We have one more SQLite 3 library! :clap:

Mentioning it as it’s code may give you some hints. Maybe even it’s author @warmwaffles would give @dmitriid some help.

4 Likes

I was pretending to help @warmwaffles as he did 100% of the work.

4 Likes

I’m excited that I’ve had quite a few people start pitching in. I love all the help I can get.

2 Likes