Help understanding Ecto Telemetry events (according to Appsignal)

[jmurphyweb]

I’m trying to understand more about the telemetry events emitted from a poorly performing query.

I’m looking at the AppSignal dashboard which records the events and puts them into a timeline.

The query has many preloads, but they don’t seem to show up in the timeline:

---

My questions:

• Why is only one of the preloads showing up in each of the screenshots above?
• Is that dead-time between the first query and the last preload just time spend doing the preloads? Is that expected? if not is this likely a telemetry events issue or an appsignal issue?

---

The offending code:

# in data_plugs
  @decorate transaction_event()
  def add_project_offers_to_conn(conn, _ops) do
    project = conn.assigns.project
    offers = Production.list_offers([project_id: project.id], [:custom_fields])

    conn
    |> assign(:proj_offers, offers)
  end

  def list_offers(filters, preloads \\ []) when is_list(filters) and is_list(preloads) do
    preloads =
      preloads ++
        [
          :engagement,
          :original_offer,
          :replacement_offer,
          :job_title,
          :department,
          :contract_type,
          :document,
          altered_documents: :document,
          envelope_events: EnvelopeEventAPI.preload_query()
        ]

    query =
      from(o in Offer, preload: ^preloads)
      |> Queries.apply_filters(filters)

    Repo.all(query)
  end

[jmurphyweb]

For anyone interested, the cause is that preloads happen in parallel by default, therefore any request_id is lost.

We can add the request id for any custom telemetry event handlers that we write manually like so:

# in Repo module:
  def default_options(_atom) do
    [telemetry_options: [logger_metadata: Logger.metadata()]]
  end

  # in telemetry callback handler
  def handle_event([:my_app, :repo, :query], measurements, metadata, _config) do
    if meta = metadata.options[:logger_metadata],
      do: Logger.metadata(meta)

But this is not picked up by AppSignals handlers of course. I will forward to them nowl.

[jmurphyweb]

I now have all preloads showing up in appsignal:

MyApp.Repo

  def default_options(_atom) do
    [
      telemetry_options: [
        appsignal_parent_span: Appsignal.Tracer.current_span()
      ]
    ]
  end

MyApp.Telemetry

  def handle_event([:ev2, :repo, :query], measurements, metadata, config) do
    :ok = send_preload_to_appsignal(measurements, metadata, config)

    :ok
  end

  defp send_preload_to_appsignal(
         %{total_time: total_time},
         %{repo: repo, query: query, options: options},
         _config
       ) do
    parent_span = options[:appsignal_parent_span]

    # if current_span is not nil then the event is already sent by appsignal library
    if parent_span && is_nil(Appsignal.Tracer.current_span()) do
      # appsignal library uses :os.system_time so using here for consistency
      time = :os.system_time()

      "http_request"
      |> Appsignal.Tracer.create_span(parent_span, start_time: time - total_time)
      |> Appsignal.Span.set_name("Query #{inspect(repo)}")
      |> Appsignal.Span.set_attribute("appsignal:category", "query.ecto")
      |> Appsignal.Span.set_sql(query)
      |> Appsignal.Tracer.close_span(end_time: time)
    end

    :ok
  end

[epilgrim]

jey @jmurphyweb !
just wanted to say: Thank you! for following up and posting your solution. I was looking for this today.

Have a nice day!