Merge branch 'log-slow-queries' into 'develop'

Log slow Ecto queries

See merge request pleroma/pleroma!3553

config/config.exs

@@ -149,6 +149,8 @@ config :pleroma, Pleroma.Web.Endpoint,
   ]
 
 # Configures Elixir's Logger
+config :logger, truncate: 65536
+
 config :logger, :console,
   level: :debug,
   format: "\n$time $metadata[$level] $message\n",
@@ -853,6 +855,13 @@ config :pleroma, ConcurrentLimiter, [
   {Pleroma.Web.ActivityPub.MRF.MediaProxyWarmingPolicy, [max_running: 5, max_waiting: 5]}
 ]
 
+config :pleroma, :telemetry,
+  slow_queries_logging: [
+    enabled: false,
+    min_duration: 500_000,
+    exclude_sources: [nil, "oban_jobs"]
+  ]
+
 # Import environment specific config. This must remain at the bottom
 # of this file so it overrides the configuration defined above.
 import_config "#{Mix.env()}.exs"

lib/pleroma/telemetry/logger.ex

@@ -12,10 +12,16 @@ defmodule Pleroma.Telemetry.Logger do
     [:pleroma, :connection_pool, :reclaim, :stop],
     [:pleroma, :connection_pool, :provision_failure],
     [:pleroma, :connection_pool, :client, :dead],
-    [:pleroma, :connection_pool, :client, :add]
+    [:pleroma, :connection_pool, :client, :add],
+    [:pleroma, :repo, :query]
   ]
   def attach do
-    :telemetry.attach_many("pleroma-logger", @events, &handle_event/4, [])
+    :telemetry.attach_many(
+      "pleroma-logger",
+      @events,
+      &Pleroma.Telemetry.Logger.handle_event/4,
+      []
+    )
   end
 
   # Passing anonymous functions instead of strings to logger is intentional,
@@ -87,4 +93,64 @@ defmodule Pleroma.Telemetry.Logger do
   end
 
   def handle_event([:pleroma, :connection_pool, :client, :add], _, _, _), do: :ok
+
+  def handle_event(
+        [:pleroma, :repo, :query] = _name,
+        %{query_time: query_time} = measurements,
+        %{source: source} = metadata,
+        config
+      ) do
+    logging_config = Pleroma.Config.get([:telemetry, :slow_queries_logging], [])
+
+    if logging_config[:enabled] &&
+         logging_config[:min_duration] &&
+         query_time > logging_config[:min_duration] and
+         (is_nil(logging_config[:exclude_sources]) or
+            source not in logging_config[:exclude_sources]) do
+      log_slow_query(measurements, metadata, config)
+    else
+      :ok
+    end
+  end
+
+  defp log_slow_query(
+         %{query_time: query_time} = _measurements,
+         %{source: _source, query: query, params: query_params, repo: repo} = _metadata,
+         _config
+       ) do
+    sql_explain =
+      with {:ok, %{rows: explain_result_rows}} <-
+             repo.query("EXPLAIN " <> query, query_params, log: false) do
+        Enum.map_join(explain_result_rows, "\n", & &1)
+      end
+
+    {:current_stacktrace, stacktrace} = Process.info(self(), :current_stacktrace)
+
+    pleroma_stacktrace =
+      Enum.filter(stacktrace, fn
+        {__MODULE__, _, _, _} ->
+          false
+
+        {mod, _, _, _} ->
+          mod
+          |> to_string()
+          |> String.starts_with?("Elixir.Pleroma.")
+      end)
+
+    Logger.warn(fn ->
+      """
+      Slow query!
+
+      Total time: #{round(query_time / 1_000)} ms
+
+      #{query}
+
+      #{inspect(query_params, limit: :infinity)}
+
+      #{sql_explain}
+
+      #{Exception.format_stacktrace(pleroma_stacktrace)}
+      """
+    end)
+  end
 end