How to debug slow Ash tests?

Ash Forum Ash Questions / Help
, ,
1

I’ve really been enjoying ash so far and the speed at which I can try out different things, however I’ve finally gotten around to writing some tests and I’ve been a little surprised how slow the tests run. I’m not really sure how to further debug the cause of the slowness.

I have one test that uses an Ash resource where its not required for the data to be persisted but I was using a setup fixture that called a create action for that resource so I can use it in all my tests. When I moved the test outside of the describe block so it didn’t run the create action and manually constructed the resource struct, the test time went from 250ms to 15ms.

I thought initially it was because of the multi-tenant extension running multi tenant migrations between tests but removing that didn’t improve test time. Then I thought it was the PubSub notifier extension but remove that didn’t help either. Running mix.test --slowest showed that all tests using some kind of an ash create action as a setup fixture took longer than 200ms. Any help debugging the slow speed would be appreciated because otherwise I’m loving ash.

2

Interesting…if you’re using schema based multi tenancy, do you have one of your resources set up to manage the schema? I.e “organization” that creates the schema when you create it? Is it any create action or only for specific resources? If you add a second create action call does it double the time? Or is it only the first call that is long?

It’s possible we introduced some kind of performance issue for create actions at some point, but it should be a solvable issue if so :slight_smile:

3

Adding multiple calls to the create action didn’t meaningfully increase the time any more. This happens with pure create actions and upsert style create actions too. Also removing multi tenancy entirely did not improve time at all.

Everything appears to run fast in dev and prod, it’s just running all tests with a watcher that 200ms adds up and you can feel the slowness

4

Here is the code for my resource and tests if that might help.

Resource

defmodule Project.Microsoft.Token do
  @moduledoc false
  use Ash.Resource, data_layer: AshPostgres.DataLayer, notifiers: [Ash.Notifier.PubSub]
    pub_sub do
    module Project.Notifier
    prefix "microsoft_token"

    publish :upsert, ["upsert", :user_id]
    publish :destroy, ["destroy", :user_id]
  end

  actions do
    defaults [:read, :destroy]

    read :by_id do
      argument :id, :uuid, allow_nil?: false
      get? true
      filter expr(id == ^arg(:id))
    end

    read :by_user_id do
      argument :id, :uuid, allow_nil?: false
      get? true
      filter expr(user_id == ^arg(:id))
    end

    create :upsert do
      upsert? true
      upsert_identity :unique_user
      upsert_fields [:access_token, :refresh_token, :expires_at]
    end
  end

  attributes do
    uuid_primary_key :id

    attribute :access_token, :string, allow_nil?: false
    attribute :refresh_token, :string, allow_nil?: false
    attribute :expires_at, :naive_datetime, allow_nil?: false

    attribute :task_list_id, :string
  end

  identities do
    identity :unique_user, [:user_id]
  end

  relationships do
    belongs_to :user, Project.Accounts.User do
      allow_nil? false
      attribute_writable? true
    end
  end

  postgres do
    table "microsoft_tokens"
    repo Project.Repo
  end
end

Test

    test "upsert action upserts tokens and expires time then broadcasts", %{token: token} do
      assert token.access_token == "some access token"
      assert token.refresh_token == "some refresh token"

      new_params = %{
        refresh_token: "new refresh token",
        access_token: "new access token",
        expires_at: ~N[2021-01-01 00:00:00],
        user_id: token.user_id
      }

      topic = "microsoft_token:upsert:#{token.user_id}"
      Project.Notifier.subscribe("microsoft_token:upsert:#{token.user_id}")

      assert {:ok, %Token{} = token} = Token.upsert(new_params)
      assert token.access_token == "new access token"
      assert token.refresh_token == "new refresh token"
      assert token.expires_at == ~N[2021-01-01 00:00:00]

      assert length(Token.read_all!()) == 1
      assert_received {^topic, %Ash.Notifier.Notification{resource: Token}}
    end

Fixture

  def token_fixture(attrs \\ %{}) do
    attrs
    |> Map.new()
    |> Map.put_new_lazy(:user_id, fn ->
      Project.AccountsFixtures.user_fixture().id
    end)
    |> Enum.into(%{
      refresh_token: "some refresh token",
      access_token: "some access token",
      expires_at: NaiveDateTime.utc_now()
    })
    |> Microsoft.Token.upsert!()
  end
5

I can see essentially this same effect in AshPostgres tests, although it doesn’t take 250ms for me, more like ~120ms. I think it has something to do with the way Ecto caches queries/inserts etc. The first time is slower than subsequent calls. If I run two tests instead of one, and they both call a create action, the first one takes ~120ms and the second one takes ~2.8ms. I can reproduce this with a direct repo insert as well, although it’s 27ms to 2.4ms instead of 120ms to 2.8ms. So after the first call, it’s roughly the same amount of time, but the first one is longer when used with Ash, pretty strange.

Something worth trying, although I’ve only seen marginal speed improvements here, is using Ash.Seed to directly insert into the database, i.e Ash.Seed.seed!(%Post{...}) to see if the that a meaningful impact. Perhaps there is some way to “prime” the cache for all tests in one go? This might be an ecto specific question with that in mind.

6

I tried using Ash.Seed and didn’t notice any meaningful increase in speed (still taking over 200ms). I also ran the same test in a non ash project with this upsert function and that test takes 15ms. Running the ash create action in development in iex took 10ms which is much more expected. Does Ash or AshPostgres run some additional setup/teardown in tests that I’m not noticing?

  def upsert_token(user_id, params) do
    %Token{}
    |> Token.changeset(Map.put(params, :user_id, user_id))
    |> Repo.insert(on_conflict: {:replace, [:access_token, :refresh_token, :expires_at]}, conflict_target: [:user_id])
  end
7

It could be a relatively recent change we made to make everything use insert_all everywhere instead of insert (as an internal simplification). Does doing Repo.insert instead of Ash.Seed.seed! help?

8

I found the issue, my setup function calls the accounts fixtures which in turn uses AshAuthentication’s password strategy to register a new user. I have a similar setup function in a non ash project but phx.gen.live configures the test environment with:

config :bcrypt_elixir, :log_rounds, 1

The majority of the time was spent hashing the password, setting this config option in test.exs made each test take less than 20ms as expected. It might be a good idea to add a note in the getting started with Ash Authentication for anyone else that runs into this. Thank you for the help debugging and for creating the ash framework

5 Likes
9

This is a great catch. Any chance you can raise an issue against AA suggesting that we put a hint in the guide about this?

10

Just changed this in my project and my tests went from taking 147.8 seconds to 13.8 seconds.

Damn, this should be in bold letters in AshAuthentication front page :sweat_smile:

1 Like