Ecto: The :queue_target setting does not work with the Ecto.Adapters.SQL.Sandbox adapter

Created on 31 Jan 2019 · 4Comments · Source: elixir-ecto/ecto

Environment

Elixir version (elixir -v): 1.7.3
Database and version (PostgreSQL 9.4, MongoDB 3.2, etc.): PostgreSQL 9.4
Ecto version (mix deps): 3.0.6
Database adapter and version (mix deps): postgrex 0.14.1
Operating system: Mac OS 10.14.2

Current behavior

I have a test that is failing with the following error message:

     ** (EXIT from #PID<0.582.0>) an exception was raised:
         ** (DBConnection.ConnectionError) connection not available and request was dropped from queue after 177ms. You can configure how long requests wait in the queue using :queue_target and :queue_interval. See DBConnection.start_link/2 for more information
             (db_connection) lib/db_connection.ex:778: DBConnection.transaction/3
             (core) lib/core/peers/peers.ex:33: Core.Peers.add_user/4
             test/peers/concurrency_test.exs:29: anonymous fn/1 in Core.PeerConcurrencyTest."test add many users concurrently, target size should not be exeeded, user_count should be correct"/1
             (elixir) lib/task/supervised.ex:89: Task.Supervised.do_apply/2
             (elixir) lib/task/supervised.ex:38: Task.Supervised.reply/5
             (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

Expected behavior

Setting the :queue_target in config/test.exs like this should fix the issue:

config :core, Core.Repo,
  pool: Ecto.Adapters.SQL.Sandbox,
  queue_target: 1000,
  url: "postgresql://postgres:postgres@postgres/events_test"

But it appears that the :queue_target setting never makes it into the DBConnection.Ownership.Proxy. Other settings, like :timeout end up in DBConnection.Ownership.Proxy just fine, so I'm quite confident that I'm actually configuring the right thing.

After digging through the code for a few hours, I came up with a way to make it work manually by setting the :queue_target like this in my test_helper.exs:

{adapter, %{opts: opts} = config} = Ecto.Repo.Registry.lookup(Core.Repo)
config = {adapter, Map.put(config, :opts, opts ++ [queue_target: 1000])}

Core.Repo
|> GenServer.whereis()
|> Ecto.Repo.Registry.associate(config)

Source

jonasschmidt

Most helpful comment

It is fixed in ecto_sql master, so if you use it, you should be golden. :)

josevalim on 5 Feb 2019

❤2 🎉2

All 4 comments

I'm also seeing issue. Unfortunately since it's being passed around as an app environment and/or option keyword, I havn't had much success in tracing it down. Posting some data here in case it helps.

Any pointers for me to debug/fix this issue would be grateful too! ❤️

Overview

We're basically mini-hammering the application with 200 concurrent workers inserting records during the test.

Config

config :local_ledger_db, LocalLedgerDB.Repo,
  adapter: Ecto.Adapters.Postgres,
  pool: Ecto.Adapters.SQL.Sandbox,
  url: {:system, "LOCAL_LEDGER_DATABASE_URL", "postgres://localhost/local_ledger_test"},
  migration_timestamps: [type: :naive_datetime_usec],
  queue_target: 1_000,
  queue_interval: 5_000

_Original code: https://github.com/omisego/ewallet/blob/master/apps/local_ledger_db/config/test.exs_

Test code

test "..." do
  caller_pid = self()
  num_spawns = 200

  tasks =
    for _ <- 1..num_spawns do
      Task.async(fn ->
        Sandbox.allow(Repo, caller_pid, self())
        Transaction.insert(...)
      end)
    end

    # ... continue with assertions
end

_Original code: https://github.com/omisego/ewallet/blob/master/apps/local_ledger/test/local_ledger/transaction_test.exs#L393-L489_

Error

09:49:22.615 [error] Task #PID<0.4583.0> started from #PID<0.4439.0> terminating
** (DBConnection.ConnectionError) connection not available and request was dropped from queue after 210ms. You can configure how long requests wait in the queue using :queue_target and :queue_interval. See DBConnection.start_link/2 for more information
    (db_connection) lib/db_connection.ex:778: DBConnection.transaction/3
    (local_ledger) lib/local_ledger/transaction.ex:108: LocalLedger.Transaction.insert/3
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

...

09:49:22.615 [error] Task #PID<0.4522.0> started from #PID<0.4439.0> terminating
** (DBConnection.ConnectionError) connection not available and request was dropped from queue after 313ms. You can configure how long requests wait in the queue using :queue_target and :queue_interval. See DBConnection.start_link/2 for more information
    (ecto_sql) lib/ecto/adapters/sql.ex:620: Ecto.Adapters.SQL.raise_sql_call_error/1
    (ecto_sql) lib/ecto/adapters/sql.ex:553: Ecto.Adapters.SQL.execute/5
    (ecto) lib/ecto/repo/queryable.ex:147: Ecto.Repo.Queryable.execute/4
    (ecto) lib/ecto/repo/queryable.ex:18: Ecto.Repo.Queryable.all/3
    (ecto) lib/ecto/repo/queryable.ex:66: Ecto.Repo.Queryable.one/3
    (local_ledger_db) lib/local_ledger_db/wallet.ex:95: LocalLedgerDB.Wallet.get_or_insert/1
    (local_ledger) lib/local_ledger/entry.ex:29: anonymous fn/1 in LocalLedger.Entry.build_all/1
    (elixir) lib/enum.ex:1327: Enum."-map/2-lists^map/1-0-"/2
    (elixir) lib/enum.ex:1327: Enum."-map/2-lists^map/1-0-"/2
    (local_ledger) lib/local_ledger/transaction.ex:107: LocalLedger.Transaction.insert/3
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

The workaround

Setting the config via config :my_app, MyRepo, queue_target: 1_000 does not work, but using @jonasschmidt's workaround above would always pass.

{adapter, %{opts: opts} = config} = Ecto.Repo.Registry.lookup(LocalLedgerDB.Repo)
config = {adapter, Map.put(config, :opts, opts ++ [queue_target: 1000])}

LocalLedgerDB.Repo
|> GenServer.whereis()
|> Ecto.Repo.Registry.associate(config)

I can confirm that the workaround above is taking effect because setting it with queue_target > 200 made the test passed, and setting to < 200 always made the test failed. Where 200 is the number of tasks I spawn in the test. While doing the same in the config file does not work.