From 949a53e327fa2d4ca2099cd4ca6fa2e3fd9e789a Mon Sep 17 00:00:00 2001 From: Alex Gleason Date: Sun, 5 Dec 2021 17:46:56 -0500 Subject: [PATCH 1/4] Log Ecto queries > 500ms --- lib/pleroma/telemetry/logger.ex | 45 +++++++++++++++++++++++++++++++-- 1 file changed, 43 insertions(+), 2 deletions(-) diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex index 44d2f48dc..1dea13acd 100644 --- a/lib/pleroma/telemetry/logger.ex +++ b/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, @@ -91,4 +97,39 @@ 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, query: query} = _metadata, + _config + ) + when query_time > 500_000 and source not in [nil, "oban_jobs"] do + {:current_stacktrace, stacktrace} = Process.info(self(), :current_stacktrace) + + stacktrace = + Enum.filter(stacktrace, fn + {__MODULE__, _, _, _} -> + false + + {mod, _, _, _} -> + mod + |> to_string() + |> String.starts_with?("Elixir.Pleroma.") + end) + + Logger.warn(fn -> + """ + Query took longer than 500ms! + + Total time: #{query_time / 1_000}ms + + #{inspect(query)} + + #{inspect(stacktrace, pretty: true)} + """ + end) + end + + def handle_event([:pleroma, :repo, :query], _measurements, _metadata, _config), do: :ok end From e009950845c6d1e7864bb68ea1258c58438ee3aa Mon Sep 17 00:00:00 2001 From: Ivan Tashkinov Date: Sun, 19 Dec 2021 20:35:00 +0300 Subject: [PATCH 2/4] 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 From 3e9e7178bc90754ad6f5414417079f6484b421e9 Mon Sep 17 00:00:00 2001 From: Ivan Tashkinov Date: Sun, 26 Dec 2021 22:49:00 +0300 Subject: [PATCH 3/4] Configurability of slow queries logging ([:pleroma, :telemetry, :slow_queries_logging]). Adjusted log messages truncation to 65 kb (was default: 8 kb). Non-truncated logging of slow query params. --- config/config.exs | 5 +++++ lib/pleroma/telemetry/logger.ex | 33 +++++++++++++++++++++++---------- 2 files changed, 28 insertions(+), 10 deletions(-) diff --git a/config/config.exs b/config/config.exs index b50c910b1..656778007 100644 --- a/config/config.exs +++ b/config/config.exs @@ -148,6 +148,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", @@ -852,6 +854,9 @@ config :pleroma, ConcurrentLimiter, [ {Pleroma.Web.ActivityPub.MRF.MediaProxyWarmingPolicy, [max_running: 5, max_waiting: 5]} ] +config :pleroma, :telemetry, + slow_queries_logging: [exclude_sources: [nil, "oban_jobs"], min_duration: 500_000] + # 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" diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex index c079f34f2..0f73ecc02 100644 --- a/lib/pleroma/telemetry/logger.ex +++ b/lib/pleroma/telemetry/logger.ex @@ -100,19 +100,34 @@ defmodule Pleroma.Telemetry.Logger do def handle_event( [:pleroma, :repo, :query] = _name, - %{query_time: query_time} = _measurements, - %{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) + %{query_time: query_time} = measurements, + %{source: source} = metadata, + config + ) do + logging_config = Pleroma.Config.get([:telemetry, :slow_queries_logging], []) + if 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__, _, _, _} -> @@ -128,11 +143,11 @@ defmodule Pleroma.Telemetry.Logger do """ Slow query! - Total time: #{query_time / 1_000}ms + Total time: #{round(query_time / 1_000)} ms #{query} - #{inspect(query_params)} + #{inspect(query_params, limit: :infinity)} #{sql_explain} @@ -140,6 +155,4 @@ defmodule Pleroma.Telemetry.Logger do """ end) end - - def handle_event([:pleroma, :repo, :query], _measurements, _metadata, _config), do: :ok end From 08c0f09bad040ea713893be822342867f589efbe Mon Sep 17 00:00:00 2001 From: Ivan Tashkinov Date: Mon, 27 Dec 2021 09:13:31 +0300 Subject: [PATCH 4/4] Made slow queries logging disabled by default. --- config/config.exs | 6 +++++- lib/pleroma/telemetry/logger.ex | 4 +++- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/config/config.exs b/config/config.exs index 656778007..30113a2e3 100644 --- a/config/config.exs +++ b/config/config.exs @@ -855,7 +855,11 @@ config :pleroma, ConcurrentLimiter, [ ] config :pleroma, :telemetry, - slow_queries_logging: [exclude_sources: [nil, "oban_jobs"], min_duration: 500_000] + 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. diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex index 0f73ecc02..d7fea9c0f 100644 --- a/lib/pleroma/telemetry/logger.ex +++ b/lib/pleroma/telemetry/logger.ex @@ -106,7 +106,9 @@ defmodule Pleroma.Telemetry.Logger do ) do logging_config = Pleroma.Config.get([:telemetry, :slow_queries_logging], []) - if logging_config[:min_duration] && query_time > logging_config[:min_duration] and + 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)