From e009950845c6d1e7864bb68ea1258c58438ee3aa Mon Sep 17 00:00:00 2001 From: Ivan Tashkinov Date: Sun, 19 Dec 2021 20:35:00 +0300 Subject: [PATCH] Slow queries logging improvements: added EXPLAIN results, listed params, improved stacktrace. --- lib/pleroma/telemetry/logger.ex | 20 +++++++++++++++----- 1 file changed, 15 insertions(+), 5 deletions(-) diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex index 1dea13acd..c079f34f2 100644 --- a/lib/pleroma/telemetry/logger.ex +++ b/lib/pleroma/telemetry/logger.ex @@ -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(stacktrace, pretty: true)} + #{inspect(query_params)} + + #{sql_explain} + + #{Exception.format_stacktrace(pleroma_stacktrace)} """ end) end