How to debug Ash query explosion

Ash Forum Ash Questions / Help
1

I’m working on a little prototype and I have ended up with a query explosion:

[info] Sent 200 in 29ms
[info] CONNECTED TO Phoenix.LiveView.Socket in 14µs
  Transport: :websocket
  Serializer: Phoenix.Socket.V2.JSONSerializer
  Parameters: %{"_csrf_token" => "Ry4kGj1zJ2dCLTQKAwNQAAB7Gwg-ESYutXP-u8e7pTl9BDaerVLjyGgV", "_live_referer" => "undefined", "_mount_attempts" => "0", "_mounts" => "0", "_track_static" => %{"0" => "http://localhost:4000/assets/app.css", "1" => "http://localhost:4000/assets/app.js"}, "vsn" => "2.0.0"}
[debug] MOUNT TimedWeb.TrackingLive
  Parameters: %{"day" => "2025-03-30"}
  Session: %{"_csrf_token" => "3vt7HKBP2yX3AG1er-WbGVAx"}
[debug] Replied in 76µs
[debug] HANDLE PARAMS in TimedWeb.TrackingLive
  Parameters: %{"day" => "2025-03-30"}
[debug] QUERY OK source="tracking_report" db=0.3ms idle=205.8ms
SELECT t0."id", t0."date", t0."rejected", t0."added", t0."comment", t0."duration", t0."user_id", t0."billed", t0."not_billable", t0."review", t0."task_id", t0."updated", t0."verified_by_id" FROM "tracking_report" AS t0 WHERE (t0."date"::date::date = $1::date::date) ORDER BY t0."id" [~D[2025-03-30]]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] Replied in 881µs
[debug] QUERY OK source="tracking_report" db=2.6ms idle=207.2ms
SELECT t0."id", t0."date", t0."rejected", t0."added", t0."comment", t0."duration", t0."user_id", t0."billed", t0."not_billable", t0."review", t0."task_id", t0."updated", t0."verified_by_id" FROM "tracking_report" AS t0 WHERE (t0."date"::date::date >= $1::date::date) AND (t0."date"::date::date <= $2::date::date) [~D[2025-03-18], ~D[2025-04-07]]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.3ms idle=210.6ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=211.3ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=211.6ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=211.8ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.3ms idle=211.9ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=212.4ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=212.2ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=165.8ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=13.3ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.1ms idle=9.5ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=8.3ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=7.6ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.3ms idle=7.7ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.5ms idle=8.8ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.4ms idle=9.8ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=9.9ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.3ms idle=10.1ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.6ms idle=11.1ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.4ms idle=12.5ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.2ms idle=13.3ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="employment_user" db=0.6ms idle=14.0ms
SELECT e0."id", e0."username", e0."password", e0."date_joined", e0."email", e0."first_name", e0."is_accountant", e0."is_active", e0."is_staff", e0."is_superuser", e0."last_login", e0."last_name", e0."tour_done" FROM "employment_user" AS e0 WHERE (e0."id"::bigint::bigint = $1::bigint::bigint) [1]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785
[debug] QUERY OK source="projects_customer" db=0.3ms idle=15.3ms
SELECT p0."id", p0."name", p0."reference", p0."comment", p0."email", p0."archived", p0."website" FROM "projects_customer" AS p0 ORDER BY p0."name" LIMIT $1 [10]
↳ anonymous fn/3 in AshPostgres.DataLayer.run_query/2, at: lib/data_layer.ex:785

I have commented out all components and what not in my liveview and I have every removed all mentions of User. How can I try where this query originates from?

The anonymous fn/3 in AshPostgres.DataLayer.run_query/2 is not helpful.

2

It seems like authentication? Are you using AshAuthentication?

3

Yes and no. I do have AushAuthentication in the project but I have tried to comment out the :load_from_session that AshAuthentication adds to the router:

defmodule TimedWeb.Router do
  use TimedWeb, :router

  use AshAuthentication.Phoenix.Router

  import AshAuthentication.Plug.Helpers

  pipeline :browser do
    plug :accepts, ["html"]
    plug :fetch_session
    plug :fetch_live_flash
    plug :put_root_layout, html: {TimedWeb.Layouts, :root}
    plug :protect_from_forgery
    plug :put_secure_browser_headers
    # plug :load_from_session
  end

  scope "/", TimedWeb do
    live "/tracking", TrackingLive, :index  # <--- this is the route im looking at
  end
end
4

Do you not have something in the live session?

5

I found it. The problem is that when you create a record like this:

Ash.Changeset.for_create(SomeResource, :create, %{user: %{id: 1}})

and you have a create action like this:

create :create do
  accept [:date, :reports]
  argument :user, :map, allow_nil?: false

  change manage_relationship(:user, type: :append)
end

it will do a query for the relationship on every insert.

6

Yes it has to do that to verify you have access to what you are trying to manage. You can put the manage relationship in an after action to mitigate I think.

7

I’m gonna try to use a bulk_action first but otherwise I will try your suggestion.

Nevertheless, it would be nice if Ash provided a little bit more debugging information. This is a really simple app and it was already trial and error to pinpoint the source of the query.

8

I don’t disagree per se, but this is more about knowing that each keypress will run the full change (think of it as an analogue to running YourSchema.changeset(…) like we do in old ecto style usage in liveview).

Then it makes sense to want to put a side effect, which manage relationship truly is, to an after action so it does not run and fully validate on each keystroke.

9

We could add some debug level logging for each action executed. We had tried something like this and it ultimately turned into a lot of noise. It could be enabled on an action-by-action basis potentially, but in those cases you’d have to go find the right actions to enable anyway.

Open to ideas on that front :smile: Could have a configuration like config :ash, log_action_calls?: true

1 Like
10

Perhaps something more granular that could be used both for debugging but also everyday important actions, like config :ash, log_actions: true | [{module, atom}]:

config :ash, log_actions: [
  {SomeResource, :create},
  {SomeResource, :update},
]

I would recommend using info/notice-level logging if you are giving users the option to enable/disable/configure. I think of “debug” level logging as coredump tier verbosity when I need every part of the system to report as much as possible, but if I in the drivers seat can be selective about what logs Ash emits, I’d want it in info or notice level, since I’ve decided it provides useful information to me I want to notice.

Alternatively, Ash could use the config to choose between emitting debug or info/notice logs per action instead. Sadly I think Phoenix generators default to dev -> debug, prod -> info, when I think saner defaults should be dev -> info, prod -> notice, precisely so that library authors can have a lower level they are free to be verbose in that consumers can select for only when they need that deep debugging context.

11

Probably what we would do is something like config :ash, :logging, action_log_level: :debug so you provide us a level always to start. We can add only_actions potentially later on too.

1 Like