Slow queries logging improvements: added EXPLAIN results, listed params, improved stacktrace.

This commit is contained in:
Ivan Tashkinov 2021-12-19 20:35:00 +03:00
parent 949a53e327
commit e009950845

View file

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