1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
|
# Pleroma: A lightweight social networking server
# Copyright © 2017-2021 Pleroma Authors <https://pleroma.social/>
# SPDX-License-Identifier: AGPL-3.0-only
defmodule Pleroma.Telemetry.Logger do
@moduledoc "Transforms Pleroma telemetry events to logs"
require Logger
@events [
[:pleroma, :connection_pool, :reclaim, :start],
[:pleroma, :connection_pool, :reclaim, :stop],
[:pleroma, :connection_pool, :provision_failure],
[:pleroma, :connection_pool, :client, :dead],
[:pleroma, :connection_pool, :client, :add],
[:pleroma, :repo, :query]
]
def attach do
:telemetry.attach_many(
"pleroma-logger",
@events,
&Pleroma.Telemetry.Logger.handle_event/4,
[]
)
end
# Passing anonymous functions instead of strings to logger is intentional,
# that way strings won't be concatenated if the message is going to be thrown
# out anyway due to higher log level configured
def handle_event(
[:pleroma, :connection_pool, :reclaim, :start],
_,
%{max_connections: max_connections, reclaim_max: reclaim_max},
_
) do
Logger.debug(fn ->
"Connection pool is exhausted (reached #{max_connections} connections). Starting idle connection cleanup to reclaim as much as #{reclaim_max} connections"
end)
end
def handle_event(
[:pleroma, :connection_pool, :reclaim, :stop],
%{reclaimed_count: 0},
_,
_
) do
Logger.error(fn ->
"Connection pool failed to reclaim any connections due to all of them being in use. It will have to drop requests for opening connections to new hosts"
end)
end
def handle_event(
[:pleroma, :connection_pool, :reclaim, :stop],
%{reclaimed_count: reclaimed_count},
_,
_
) do
Logger.debug(fn -> "Connection pool cleaned up #{reclaimed_count} idle connections" end)
end
def handle_event(
[:pleroma, :connection_pool, :provision_failure],
%{opts: [key | _]},
_,
_
) do
Logger.error(fn ->
"Connection pool had to refuse opening a connection to #{key} due to connection limit exhaustion"
end)
end
def handle_event(
[:pleroma, :connection_pool, :client, :dead],
%{client_pid: client_pid, reason: reason},
%{key: key},
_
) do
Logger.warn(fn ->
"Pool worker for #{key}: Client #{inspect(client_pid)} died before releasing the connection with #{inspect(reason)}"
end)
end
def handle_event(
[:pleroma, :connection_pool, :client, :add],
%{clients: [_, _ | _] = clients},
%{key: key, protocol: :http},
_
) do
Logger.info(fn ->
"Pool worker for #{key}: #{length(clients)} clients are using an HTTP1 connection at the same time, head-of-line blocking might occur."
end)
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
|
