Slow queries logging improvements: added EXPLAIN results, listed params, improved...
authorIvan Tashkinov <ivantashkinov@gmail.com>
Sun, 19 Dec 2021 17:35:00 +0000 (20:35 +0300)
committerIvan Tashkinov <ivantashkinov@gmail.com>
Sun, 19 Dec 2021 17:45:28 +0000 (20:45 +0300)
lib/pleroma/telemetry/logger.ex

index 1dea13acdbed7f3c8ea2745ff68fb6016b976149..c079f34f2657150eb28e0918bc5d339cbe6d2c0b 100644 (file)
@@ -101,13 +101,19 @@ defmodule Pleroma.Telemetry.Logger do
   def handle_event(
         [:pleroma, :repo, :query] = _name,
         %{query_time: query_time} = _measurements,
-        %{source: source, query: query} = _metadata,
+        %{source: source, query: query, params: query_params, repo: repo} = _metadata,
         _config
       )
       when query_time > 500_000 and source not in [nil, "oban_jobs"] do
     {:current_stacktrace, stacktrace} = Process.info(self(), :current_stacktrace)
 
-    stacktrace =
+    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
+
+    pleroma_stacktrace =
       Enum.filter(stacktrace, fn
         {__MODULE__, _, _, _} ->
           false
@@ -120,13 +126,17 @@ defmodule Pleroma.Telemetry.Logger do
 
     Logger.warn(fn ->
       """
-      Query took longer than 500ms!
+      Slow query!
 
       Total time: #{query_time / 1_000}ms
 
-      #{inspect(query)}
+      #{query}
+
+      #{inspect(query_params)}
+
+      #{sql_explain}
 
-      #{inspect(stacktrace, pretty: true)}
+      #{Exception.format_stacktrace(pleroma_stacktrace)}
       """
     end)
   end