App in production crashing with DBConnection.ConnectionError

Was a crash_dump generated?

No, I said it “crash” but in fact the server just starts to timeout all requests. I’ll check next time if the docker container generates any files on disk.

I would start by adding more metrics around the application. Having such a large connection number is likely going to lead to worse performance, as they won’t ever be effectively used and the runtime now has to spend more time managing them.

If you suspect this is related to the database, you should log the metrics emitted by Ecto, such as query time, checkout time, idle time and so on.

I would also log the memory metrics from the VM and, most important, the Erlang VM run queues, which tells you how much CPU/IO work it has to do. You can get those by running Phoenix LiveDashboard on the repo, but ideally you want to push these to an external tool too.

Are you by chance using Bandit? I was experiencing a similar symptom, although w/ no resource issues that I noticed, just sudden timeouts that felt like port exhaustion.

If so, there’s a PR @mtrudel put out for thousand_island (Refine acceptor behaviour on abnormal conditions by mtrudel · Pull Request #103 · mtrudel/thousand_island · GitHub) that resolves an issue where the kernel might kill a connection, but the process responsible for it was not restarting since it looked “normal” to it. I was similarly seeing it occur during peaks, but it was mostly just coincidence since that’s when the most activity and aborted connections were occurring. I also saw large numbers of DB timeouts right after, but it was a red herring.

@felix-starman It was cowboy then yesterday I moved to bandit: same result.

@josevalim how many db connections do you recommend? 100 or even less ?

more about my app:

• Graphql to communicate with front-end
• Use graphql subscribe (over websocket) only to chat.
• Nebulex to in-memory cache
• Phoenix.Tracker to track users online (all 5k users put in same topic)
• A Genserver that starts a postgres listen service

application.rb

def start(_type, _args) do
    # import Supervisor.Spec
    :logger.add_handler(:sentry_handler, Sentry.LoggerHandler, %{})

    children = [
      D4.Cache,
      D4.Repo,
      # {DNSCluster, query: Application.get_env(:d4, :dns_cluster_query) || :ignore},
      {Phoenix.PubSub, name: D4.PubSub},
      {D4Web.Presence, [name: D4Web.Presence, pubsub_server: D4.PubSub]},
      D4Web.Endpoint,
      {Absinthe.Subscription, D4Web.Endpoint},
      {Task.Supervisor, name: D4.TaskSupervisor},
      D4.PGListener,
      D4Web.Telemetry,
      D4Web.CacheClient,
      D4Web.RateLimit
    ]

    # See https://hexdocs.pm/elixir/Supervisor.html
    # for other strategies and supported options
    opts = [strategy: :one_for_one, name: D4.Supervisor]
    Supervisor.start_link(children, opts)
  end

pg listen (there is no issue releted to that I think):

# TODO: testar de alguma forma
defmodule D4.PGListener do
  @moduledoc """
    Listen for notifications from postgres
  """

  use GenServer
  require Logger

  def start_link(opts \\ []) do
    GenServer.start_link(__MODULE__, opts, name: __MODULE__)
  end

  def init(opts) do
    with {:ok, pid} <- Postgrex.Notifications.start_link(D4.Repo.config()),
         {:ok, _} <- Postgrex.Notifications.listen(pid, "user_updated") do
      {:ok, opts}
    else
      error -> {:stop, error}
    end
  end

  def handle_info({:notification, _pid, _ref, "user_updated", payload}, _state) do
    case Jason.decode(payload) do
      {:ok, data} ->
        D4.Helpers.broadcast_user_update(data["id"], data)
        D4.Guardian.delete_from_cache(%D4.User{id: data["id"]})
        :telemetry.execute([:d4, :pglistener, :ok], %{}, %{event: :user_updated, user_id: data["id"]})

      {:error, err} ->
        Logger.error("PG_LISTENER #{Exception.format_banner(:error, err)}")
        :telemetry.execute([:d4, :pglistener, :error], %{}, %{event: :user_updated, error: err})
    end

    {:noreply, :event_handled}
  end
end

deps version and deps tree:

absinthe 1.7.6
  absinthe_phoenix 2.0.2
  absinthe_plug 1.5.8
  bamboo 2.3.0
  bandit 1.1.2
  bcrypt_elixir 3.1.0
  bunt 1.0.0
  castore 1.0.5
  certifi 2.12.0
  combine 0.10.0
  comeonin 5.4.0
  cors_plug 3.0.3
  cowboy 2.10.0
  cowboy_telemetry 0.4.0
  cowlib 2.12.1
  credo 1.7.2
  dataloader 2.0.0
  db_connection 2.6.0
  decimal 2.1.1
  ecto 3.11.1
  ecto_psql_extras 0.7.15
  ecto_sql 3.11.1
  elixir_make 0.7.7
  eqrcode 0.1.10
  ex_aws 2.5.0
  ex_aws_s3 2.5.2
  expo 0.5.1
  feeder 2.3.2
  feeder_ex 1.1.0
  file_system 1.0.0
  gettext 0.24.0
  guardian 2.3.2
  hackney 1.20.1
  hpax 0.1.2
  httpoison 2.2.1
  idna 6.1.1
  jason 1.4.1
  jose 1.11.6
  meck 0.9.2
  metrics 1.0.1
  mime 2.0.5
  mimerl 1.2.0
  mock 0.3.8
  nebulex 2.5.2
  nimble_options 1.1.0
  nimble_parsec 1.4.0
  parse_trans 3.4.1
  phoenix 1.7.10
  phoenix_ecto 4.4.3
  phoenix_html 3.3.3
  phoenix_live_dashboard 0.8.3
  phoenix_live_view 0.20.2
  phoenix_pubsub 2.1.3
  phoenix_template 1.0.4
  plug 1.15.2
  plug_cowboy 2.6.1
  plug_crypto 2.0.0
  postgrex 0.17.4
  ranch 1.8.0
  remote_ip 1.1.0
  sentry 10.1.0
  shards 1.1.0
  ssl_verify_fun 1.1.7
  table_rex 4.0.0
  telemetry 1.2.1
  telemetry_metrics 0.6.1
  telemetry_poller 1.0.0
  thousand_island 1.2.0
  timex 3.7.11
  tzdata 1.1.1
  ua_inspector 2.2.0
  unicode_util_compat 0.7.0
  uuid 1.1.8
  websock 0.5.3
  websock_adapter 0.5.5
  xxhash 0.3.1
  yamerl 0.10.0

d4
├── absinthe ~> 1.7 (Hex package)
│   ├── dataloader ~> 1.0.0 or ~> 2.0 (Hex package)
│   ├── decimal ~> 1.0 or ~> 2.0 (Hex package)
│   ├── nimble_parsec ~> 1.2.2 or ~> 1.3 (Hex package)
│   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
├── absinthe_phoenix ~> 2.0 (Hex package)
│   ├── absinthe ~> 1.5 (Hex package)
│   ├── absinthe_plug ~> 1.5 (Hex package)
│   ├── decimal ~> 1.0 or ~> 2.0 (Hex package)
│   ├── phoenix ~> 1.5 (Hex package)
│   ├── phoenix_html ~> 2.13 or ~> 3.0 (Hex package)
│   └── phoenix_pubsub ~> 2.0 (Hex package)
├── absinthe_plug ~> 1.5 (Hex package)
│   ├── absinthe ~> 1.5 (Hex package)
│   └── plug ~> 1.4 (Hex package)
│       ├── mime ~> 1.0 or ~> 2.0 (Hex package)
│       ├── plug_crypto ~> 1.1.1 or ~> 1.2 or ~> 2.0 (Hex package)
│       └── telemetry ~> 0.4.3 or ~> 1.0 (Hex package)
├── bamboo ~> 2.0 (Hex package)
│   ├── hackney >= 1.15.2 (Hex package)
│   │   ├── certifi ~> 2.12.0 (Hex package)
│   │   ├── idna ~> 6.1.0 (Hex package)
│   │   │   └── unicode_util_compat ~> 0.7.0 (Hex package)
│   │   ├── metrics ~> 1.0.0 (Hex package)
│   │   ├── mimerl ~> 1.1 (Hex package)
│   │   ├── parse_trans 3.4.1 (Hex package)
│   │   ├── ssl_verify_fun ~> 1.1.0 (Hex package)
│   │   └── unicode_util_compat ~> 0.7.0 (Hex package)
│   ├── jason ~> 1.0 (Hex package)
│   ├── mime ~> 1.4 or ~> 2.0 (Hex package)
│   └── plug ~> 1.0 (Hex package)
├── bandit ~> 1.0 (Hex package)
│   ├── hpax ~> 0.1.1 (Hex package)
│   ├── plug ~> 1.14 (Hex package)
│   ├── telemetry ~> 0.4 or ~> 1.0 (Hex package)
│   ├── thousand_island ~> 1.0 (Hex package)
│   │   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
│   └── websock ~> 0.5 (Hex package)
├── bcrypt_elixir ~> 3.0 (Hex package)
│   ├── comeonin ~> 5.3 (Hex package)
│   └── elixir_make ~> 0.6 (Hex package)
│       └── castore ~> 0.1 or ~> 1.0 (Hex package)
├── comeonin ~> 5.0 (Hex package)
├── cors_plug ~> 3.0 (Hex package)
│   └── plug ~> 1.13 (Hex package)
├── cowboy ~> 2.0 (Hex package)
│   ├── cowlib 2.12.1 (Hex package)
│   └── ranch 1.8.0 (Hex package)
├── credo ~> 1.3 (Hex package)
│   ├── bunt ~> 0.2.1 or ~> 1.0 (Hex package)
│   ├── file_system ~> 0.2 or ~> 1.0 (Hex package)
│   └── jason ~> 1.0 (Hex package)
├── dataloader ~> 2.0 (Hex package)
│   ├── ecto >= 3.4.3 and < 4.0.0 (Hex package)
│   │   ├── decimal ~> 2.0 (Hex package)
│   │   ├── jason ~> 1.0 (Hex package)
│   │   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
│   └── telemetry ~> 1.0 (Hex package)
├── ecto_psql_extras ~> 0.2 (Hex package)
│   ├── ecto_sql ~> 3.7 (Hex package)
│   ├── postgrex ~> 0.16.0 or ~> 0.17.0 (Hex package)
│   └── table_rex ~> 3.1.1 or ~> 4.0.0 (Hex package)
├── ecto_sql ~> 3.0 (Hex package)
│   ├── db_connection ~> 2.4.1 or ~> 2.5 (Hex package)
│   │   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
│   ├── ecto ~> 3.11.0 (Hex package)
│   ├── postgrex ~> 0.16.0 or ~> 0.17.0 or ~> 1.0 (Hex package)
│   └── telemetry ~> 0.4.0 or ~> 1.0 (Hex package)
├── eqrcode ~> 0.1.10 (Hex package)
├── ex_aws ~> 2.0 (Hex package)
│   ├── hackney ~> 1.16 (Hex package)
│   ├── jason ~> 1.1 (Hex package)
│   ├── mime ~> 1.2 or ~> 2.0 (Hex package)
│   └── telemetry ~> 0.4.3 or ~> 1.0 (Hex package)
├── ex_aws_s3 ~> 2.0 (Hex package)
│   └── ex_aws ~> 2.0 (Hex package)
├── feeder_ex ~> 1.0 (Hex package)
│   └── feeder ~> 2.2 (Hex package)
├── gettext ~> 0.11 (Hex package)
│   └── expo ~> 0.5.1 (Hex package)
├── guardian ~> 2.0 (Hex package)
│   ├── jose ~> 1.8 (Hex package)
│   └── plug ~> 1.3.3 or ~> 1.4 (Hex package)
├── httpoison ~> 2.0 (Hex package)
│   └── hackney ~> 1.17 (Hex package)
├── jason ~> 1.0 (Hex package)
│   └── decimal ~> 1.0 or ~> 2.0 (Hex package)
├── jose ~> 1.11 (Hex package)
├── mock ~> 0.3.0 (Hex package)
│   └── meck ~> 0.9.2 (Hex package)
├── nebulex ~> 2.2 (Hex package)
│   ├── shards ~> 1.1 (Hex package)
│   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
├── phoenix ~> 1.7.0 (Hex package)
│   ├── castore >= 0.0.0 (Hex package)
│   ├── jason ~> 1.0 (Hex package)
│   ├── phoenix_pubsub ~> 2.1 (Hex package)
│   ├── phoenix_template ~> 1.0 (Hex package)
│   │   └── phoenix_html ~> 2.14.2 or ~> 3.0 or ~> 4.0 (Hex package)
│   ├── plug ~> 1.14 (Hex package)
│   ├── plug_cowboy ~> 2.6 (Hex package)
│   ├── plug_crypto ~> 1.2 or ~> 2.0 (Hex package)
│   ├── telemetry ~> 0.4 or ~> 1.0 (Hex package)
│   └── websock_adapter ~> 0.5.3 (Hex package)
│       ├── bandit >= 0.6.0 (Hex package)
│       ├── plug ~> 1.14 (Hex package)
│       ├── plug_cowboy ~> 2.6 (Hex package)
│       └── websock ~> 0.5 (Hex package)
├── phoenix_ecto ~> 4.0 (Hex package)
│   ├── ecto ~> 3.5 (Hex package)
│   ├── phoenix_html ~> 2.14.2 or ~> 3.0 or ~> 4.0 (Hex package)
│   └── plug ~> 1.9 (Hex package)
├── phoenix_html ~> 3.3 (Hex package)
│   └── plug ~> 1.5 (Hex package)
├── phoenix_live_dashboard ~> 0.8.2 (Hex package)
│   ├── ecto ~> 3.6.2 or ~> 3.7 (Hex package)
│   ├── ecto_psql_extras ~> 0.7 (Hex package)
│   ├── mime ~> 1.6 or ~> 2.0 (Hex package)
│   ├── phoenix_live_view ~> 0.19 or ~> 1.0 (Hex package)
│   │   ├── jason ~> 1.0 (Hex package)
│   │   ├── phoenix ~> 1.6.15 or ~> 1.7.0 (Hex package)
│   │   ├── phoenix_html ~> 3.3 or ~> 4.0 (Hex package)
│   │   ├── phoenix_template ~> 1.0 (Hex package)
│   │   ├── plug ~> 1.15 (Hex package)
│   │   └── telemetry ~> 0.4.2 or ~> 1.0 (Hex package)
│   └── telemetry_metrics ~> 0.6 or ~> 1.0 (Hex package)
├── phoenix_pubsub ~> 2.0 (Hex package)
├── plug_cowboy ~> 2.1 (Hex package)
│   ├── cowboy ~> 2.7 (Hex package)
│   ├── cowboy_telemetry ~> 0.3 (Hex package)
│   │   ├── cowboy ~> 2.7 (Hex package)
│   │   └── telemetry ~> 1.0 (Hex package)
│   └── plug ~> 1.14 (Hex package)
├── postgrex >= 0.0.0 (Hex package)
│   ├── db_connection ~> 2.1 (Hex package)
│   ├── decimal ~> 1.5 or ~> 2.0 (Hex package)
│   └── jason ~> 1.0 (Hex package)
├── remote_ip ~> 1.1.0 (Hex package)
│   ├── combine ~> 0.10 (Hex package)
│   └── plug ~> 1.14 (Hex package)
├── sentry ~> 10.0 (Hex package)
│   ├── hackney ~> 1.8 (Hex package)
│   ├── jason ~> 1.1 (Hex package)
│   ├── nimble_options ~> 1.0 (Hex package)
│   ├── plug ~> 1.6 (Hex package)
│   └── plug_cowboy ~> 2.3 (Hex package)
├── shards ~> 1.0 (Hex package)
├── telemetry ~> 1.2.0 (Hex package)
├── telemetry_metrics ~> 0.5 (Hex package)
│   └── telemetry ~> 0.4 or ~> 1.0 (Hex package)
├── telemetry_poller ~> 1.0 (Hex package)
│   └── telemetry ~> 1.0 (Hex package)
├── timex ~> 3.0 (Hex package)
│   ├── combine ~> 0.10 (Hex package)
│   ├── gettext ~> 0.20 (Hex package)
│   └── tzdata ~> 1.1 (Hex package)
│       └── hackney ~> 1.17 (Hex package)
├── ua_inspector ~> 2.0 (Hex package)
│   ├── hackney ~> 1.0 (Hex package)
│   └── yamerl ~> 0.7 (Hex package)
├── uuid ~> 1.0 (Hex package)
└── xxhash ~> 0.3.1 (Hex package)

Key configs from runtime/prod.exs (private data was changed):

config :d4, D4.Repo,
  hostname: System.get_env("PG_HOSTNAME"),
  database: System.get_env("PG_DATABASE"),
  username: System.get_env("PG_USERNAME"),
  password: System.get_env("PG_PASSWORD"),
  prepare: :unnamed, #that was added to fix RDS Proxy
  pool_size: String.to_integer(System.get_env("PG_POOL_SIZE", "196")),
  timeout: String.to_integer(System.get_env("PG_TIMEOUT", "4000")),
  queue_target: String.to_integer(System.get_env("PG_QTARGET", "1000")),
  queue_interval: String.to_integer(System.get_env("PG_QINTERVAL", "5000"))

config :d4, D4Web.Endpoint,
  secret_key_base: System.get_env("PHOENIX_KEY"),
  http: [ip: {0, 0, 0, 0}, port: System.get_env("PORT") || 4000],
  url: [host: hostname, schema: "https", port: 443],
  debug_errors: false,
  code_reloader: false,
  check_origin: false,
  force_ssl: false,
  server: true,
  root: ".",
  version: Mix.Project.config()[:version]
  
config :d4, D4Web.Mailer,
  adapter: Bamboo.SendGridAdapter,
  api_key: {:system, "SENDGRID_API_KEY"}  
  
config :d4, D4.Cache,
  backend: :shards,
  allocated_memory: 16_000_000_000,
  gc_interval: :timer.hours(6),
  gc_cleanup_min_timeout: :timer.minutes(10),
  gc_cleanup_max_timeout: :timer.minutes(60)  
  
config :d4, D4Services.Geo.LocationiqApi,
  token: System.get_env("LOCATION_IQ_TOKEN"),
  url: "https://us1.locationiq.com/v1"

config :d4, D4Services.Geo.GoogleMapsApi,
  token: System.get_env("GOOGLE_MAPS_TOKEN"),
  url: ""  

config :sentry,
  dsn: System.get_env("SENTRY_DNS"),
  environment_name: :prod,
  enable_source_code_context: true,
  root_source_code_path: [File.cwd!()]  
  
config :logger,
  discard_threshold: 1000,
  backends: [:console],
  level: :info,
  handle_otp_reports: true,
  utc_log: true,  
  compile_time_purge_matching: [[level_lower_than: :info]]

config :logger, :console,
  format: {D4Web.LoggerJsonFormat, :format},
  metadata: [:telemetry, :cid, :sid, :ip, :aws_id, :request_id, :label]  
  
  

When I am faced with these kinds of high-load issues I rely on recon and remote nodes. I’d suggest trying to come up with a load test that simulates this error (maybe 1/4 of the max users on 1/4 of the CPUs?), then connect to your Phoneix app using a remote node and poke around. Check scheduler usage across your CPUs, check processes with high memory / reductions, etc.

Ofcourse this can be done through automated metrics gathering by sweeping the system periodically and measuring / logging the most ‘heavy’ processes, but sometimes the proactive approach is easier to work with. You can see process state, what the current stacktrace is, etc.

Checking out Microstate Accounting and Lock Profiling can also help if nothing really stands out with scheduler usage or processes. Also try giving Erlang in Anger a read.

@josevalim here is my telemetry logic, I’m log queries that takes over 700ms (and I have about 10 por minute)

1 - I’m not sure if this is the correct way to log things.
2 - I’ve already tried disabling logging completely, with no effect.

IMPORT: before I said 35 thousand requests per second, but it is per minute.

#
# TODO: enviar para sentry errors de authentification ?
#
defmodule D4Web.Telemetry do
  require Logger

  use Supervisor
  import Telemetry.Metrics

  @slow System.convert_time_unit(700, :millisecond, :native)

  def start_link(arg) do
    Supervisor.start_link(__MODULE__, arg, name: __MODULE__)
  end

  def init(_arg) do
    children = [
      {:telemetry_poller, measurements: measurements(), period: 30_000}
      # {Telemetry.Metrics.ConsoleReporter, metrics: metrics()}
    ]

    setup()
    Supervisor.init(children, strategy: :one_for_one)
  end

  def metrics() do
    [
      last_value("vm.memory.total", unit: {:byte, :megabyte}),
      last_value("vm.total_run_queue_lengths.total"),
      last_value("vm.total_run_queue_lengths.cpu"),
      last_value("vm.total_run_queue_lengths.io"),
      last_value("d4.cache.size.value", tags: [:cache, :node]),
      last_value("d4.presence.size.value")
    ]
  end

  def measurements() do
    [
      {D4.Cache, :dispatch_cache_size, []},
      {D4Web.Presence, :dispatch_online_user, []}
    ]
  end

  def setup do
    events = [
      #
      # phoenix
      # https://hexdocs.pm/phoenix/Phoenix.Logger.html
      #
      # [:plug_adapter, :call, :start],
      # [:plug_adapter, :call, :stop],
      # [:plug_adapter, :call, :exception],
      # [:phoenix, :endpoint, :start],
      # [:phoenix, :endpoint, :stop],
      # [:phoenix, :router_dispatch, :start],
      [:phoenix, :router_dispatch, :stop],
      [:phoenix, :router_dispatch, :exception],
      # [:phoenix, :error_rendered],
      # [:phoenix, :socket_connected],
      # [:phoenix, :channel_joined],
      # [:phoenix, :channel_handled_in],

      #
      # absinthe graphql
      #
      # [:absinthe, :execute, :operation, :start], # when the operation starts
      # [:absinthe, :execute, :operation, :stop], # when the operation finishes
      # [:absinthe, :subscription, :publish, :start], # when a subscription starts
      # [:absinthe, :subscription, :publish, :stop], # when a subscription finishes
      # [:absinthe, :resolve, :field, :start], # when field resolution starts
      # [:absinthe, :resolve, :field, :stop], # when field resolution finishes
      # [:absinthe, :middleware, :batch, :start], # when the batch processing starts
      # [:absinthe, :middleware, :batch, :stop], # when the batch processing finishes

      #
      # ecto
      # https://hexdocs.pm/ecto/Ecto.Repo.html#module-telemetry-events
      #
      [:d4, :repo, :query],

      # app
      [:d4_web, :graphql, :stop],
      [:d4, :repo, :black_word],
      [:d4, :repo, :black_email],
      [:d4, :authorization],
      [:d4_pay, :request, :stop],
      [:d4_pay, :request, :exception],
      # [:d4, :pglistener, :ok],
      [:d4, :pglistener, :error],
      [:d4_web, :rate_limit]
      # [:d4, :pg, :d4error]
    ]

    events =
      if Application.get_env(:d4, :prod?),
        do: events ++ [[:d4_web, :presences]],
        else: events

    unless Application.get_env(:d4, :test?) do
      :telemetry.attach_many("d4-telemetry", events, &D4Web.Telemetry.handle_event/4, nil)
    end
  end

  # #
  # #
  # #
  # def handle_event([:phoenix, :router_dispatch, :stop], %{duration: time}, %{conn: conn}, _) do
  #   path = conn.request_path

  #   if path not in ["/api/graphiql", "/favicon.ico", "/ping", "/sw.js", "/manifest.json"] do
  #     level  = if conn.status >= 500,
  #       do: :error,
  #     else: :info

  #     log level, "REQUEST", %{
  #       status: conn.status,
  #       path: path,
  #       method: conn.method,
  #       duration: parse_time(time)
  #     }
  #   end
  # end

  def handle_event([:phoenix, :router_dispatch, :stop], %{duration: time}, %{conn: conn}, _) do
    path = conn.request_path

    if String.starts_with?(path, "/wh/") do
      level =
        if conn.status == 200 || conn.status == 201,
          do: :info,
          else: :error

      log(level, "REQUEST", %{
        status: conn.status,
        path: path,
        method: conn.method,
        duration: parse_time(time)
      })
    end
  end

  #
  #
  #
  def handle_event(
        [:phoenix, :router_dispatch, :exception],
        _,
        %{kind: kind, reason: reason, stacktrace: stacktrace},
        _
      ) do
    log(:error, "REQUEST", %{
      exception: Exception.format(kind, reason, stacktrace)
    })
  end

  #
  # measurements:
  #  %{start: 10, stop: 10, time: 2}
  # metadata
  #  %{resolution: resolution, identifier: identifier, path: path}
  # TODO: distinguir cs_error (warnig) de error (error)
  #
  def handle_event([:d4_web, :graphql, :stop], %{duration: time}, metadata, _config) do
    errors = %{}
    level = :info

    {level, errors} =
      if Enum.any?(metadata.errors || []),
        do: {:error, Map.merge(errors, %{errors: metadata.errors})},
        else: {level, errors}

    {level, errors} =
      if match?(%{ok: false}, metadata.value),
        do: {:warning, Map.merge(errors, %{cs_errors: metadata.value.errors})},
        else: {level, errors}

    data =
      Map.merge(errors, %{
        identifier: metadata.identifier,
        path: metadata.path,
        duration: parse_time(time)
      })

    log(level, "GRAPHQL", data)
  end

  #
  # measurements:
  #   %{decode_time: 4000, query_time: 6335000, queue_time: 74000, total_time: 6413000}
  # metadata:
  #   %{parameters: [1], source: 'users', query: "the sql query string" }
  #
  #
  def handle_event([:d4, :repo, :query], measurements, metadata, _config) do
    query_time = measurements[:query_time] || 0
    queue_time = measurements[:queue_time] || 0

    if query_time + queue_time > @slow do
      idle_time = measurements[:idle_time] || 0

      log(:warning, "QUERY", %{
        slow: true,
        source: metadata.source,
        duration: parse_time(query_time),
        idle: parse_time(idle_time),
        queue: parse_time(queue_time),
        db: parse_time(query_time),
        sql: metadata.query,
        params: metadata.params
      })
    end
  end

  #
  #
  #
  def handle_event([:d4, :repo, :black_word], _, metadata, _config) do
    log(:warning, "BLACK_WORD", %{
      word: metadata.word,
      text: metadata.text
    })
  end

  #
  #
  #
  def handle_event([:d4, :repo, :black_email], _, metadata, _config) do
    log(:warning, "BLACK_EMAIL", %{email: metadata.email})
  end

  #
  #
  #
  def handle_event([:d4, :authorization], _, %{struct: struct, action: action}, _config) do
    log(:error, "AUTHORIZATION", %{
      action: action,
      struct: extract_struct(struct)
    })
  end

  #
  # mensurements %{total, joins, leaves}
  #
  def handle_event([:d4_web, :presences], mensurements, _, _) do
    log(:info, "PRESENCES", mensurements)
  end

  #
  # D4 PAY (MERCADO PAGO)
  #
  def handle_event(
        [:d4_pay, :request, :stop],
        %{duration: duration},
        %{response: response} = meta,
        _
      ) do
    sc = response.status_code
    kd = if sc in [200, 201], do: :info, else: :error
    # bd = if sc not in [200, 201], do: response.body, else: nil

    log(kd, "D4PAY_REQUEST", %{
      duration: parse_time(duration),
      path: meta[:path],
      status_code: sc
    })
  end

  def handle_event([:d4_pay, :request, :exception], %{duration: duration}, meta, _) do
    log(:error, "D4PAY_REQUEST", %{
      path: meta[:path],
      duration: parse_time(duration),
      exception: Exception.message(meta.reason),
      params: meta.params
    })
  end

  #
  # D4_PGLISTENER
  #
  def handle_event([:d4, :pglistener, :ok], _, meta, _) do
    log(:info, "D4_PGLISTENER", meta)
  end

  def handle_event([:d4, :pglistener, :error], _, meta, _) do
    log(:error, "D4_PGLISTENER", meta)
  end

  #
  # D4_WEB RATE_LIMIT
  #
  def handle_event([:d4_web, :rate_limit], _, %{key: {path, _}, limit: limit, name: name}, _) do
    log(:warning, "RATE_LIMIT", %{path: path, limit: limit, name: name})
  end

  def handle_event([:d4_web, :rate_limit], _, %{key: key, limit: limit, name: name}, _) do
    key = inspect(key)
    log(:warning, "RATE_LIMIT", %{key: key, limit: limit, name: name})
  end

  #
  # Handle no handler
  #
  def handle_event(event, measurements, metadata, _config) do
    log(:warning, "TELEMETRY", %{
      message: "No telemetry handler for #{inspect(event)} with #{inspect(measurements)} and metadata #{inspect(Map.keys(metadata))}"
    })
  end

  #
  #
  #
  defp log(level, what, telemetry) do
    Logger.log(level, fn -> {what, telemetry: telemetry} end)
  end

  defp parse_time(diff) do
    us = System.convert_time_unit(diff || 0, :native, :microsecond)
    div(us, 1000)
  end

  defp extract_struct(%_{id: id} = struct) do
    "#{D4.Helpers.get_type_name(struct)}:#{id}"
  end

  defp extract_struct(%_{} = struct) do
    "#{D4.Helpers.get_type_name(struct)}"
  end

  defp extract_struct(_) do
    ""
  end
end

Thank you very much for the tips and book, I’ve never needed to remotely debug an application in elixir/erlang, I’m going to read this book today. Thanks!

Likely unrelated, but what’s the provisioned storage size for the DB?

Years ago, ran into a situation where some flavors of RDS backed by EBS would limit disk IOPS based on size. We had an app that didn’t use a ton of data but was very read-heavy - it ran into similar weird “spikes” when a temporary load increase exhausted the available I/O.

likely unrelated disclaimer as well (kinda reminds me of this ), but, what do you keep in the cache?