|
1 | | -defmodule LoggerJSON.Ecto do |
2 | | - @moduledoc """ |
3 | | - A telemetry handler that logs Ecto query metrics in JSON format. |
| 1 | +if Code.ensure_loaded?(Ecto) and Code.ensure_loaded?(:telemetry) do |
| 2 | + defmodule LoggerJSON.Ecto do |
| 3 | + @moduledoc """ |
| 4 | + A telemetry handler that logs Ecto query metrics in JSON format. |
4 | 5 |
|
5 | | - This module is not recommended to be used in production, as it can be |
6 | | - costly to log every single database query. |
7 | | - """ |
8 | | - require Logger |
| 6 | + This module is not recommended to be used in production, as it can be |
| 7 | + costly to log every single database query. |
| 8 | + """ |
| 9 | + require Logger |
9 | 10 |
|
10 | | - @doc """ |
11 | | - Attaches the telemetry handler to the given event. |
| 11 | + @doc """ |
| 12 | + Attaches the telemetry handler to the given event. |
12 | 13 |
|
13 | | - ### Available options |
| 14 | + ### Available options |
14 | 15 |
|
15 | | - * `:level` - log level which is used to log requests. Defaults to `:info`. |
| 16 | + * `:level` - log level which is used to log requests. Defaults to `:info`. |
16 | 17 |
|
17 | | - ### Dynamic log level |
| 18 | + ### Dynamic log level |
18 | 19 |
|
19 | | - In some cases you may wish to set the log level dynamically |
20 | | - on a per-query basis. To do so, set the `:level` option to |
21 | | - a tuple, `{Mod, Fun, Args}`. The query and map of time measures |
22 | | - will be prepended to the provided list of arguments. |
| 20 | + In some cases you may wish to set the log level dynamically |
| 21 | + on a per-query basis. To do so, set the `:level` option to |
| 22 | + a tuple, `{Mod, Fun, Args}`. The query and map of time measures |
| 23 | + will be prepended to the provided list of arguments. |
23 | 24 |
|
24 | | - When invoked, your function must return a |
25 | | - [`Logger.level()`](`t:Logger.level()/0`) or `false` to |
26 | | - disable logging for the request. |
| 25 | + When invoked, your function must return a |
| 26 | + [`Logger.level()`](`t:Logger.level()/0`) or `false` to |
| 27 | + disable logging for the request. |
27 | 28 |
|
28 | | - ### Examples |
| 29 | + ### Examples |
29 | 30 |
|
30 | | - Attaching the telemetry handler to the `MyApp.Repo` events with the `:info` log level: |
| 31 | + Attaching the telemetry handler to the `MyApp.Repo` events with the `:info` log level: |
31 | 32 |
|
32 | | - LoggerJSON.Ecto.attach("logger-json-queries", [:my_app, :repo, :query], :info) |
| 33 | + LoggerJSON.Ecto.attach("logger-json-queries", [:my_app, :repo, :query], :info) |
33 | 34 |
|
34 | | - For more details on event and handler naming see |
35 | | - (`Ecto.Repo` documentation)[https://hexdocs.pm/ecto/Ecto.Repo.html#module-telemetry-events]. |
36 | | - """ |
37 | | - @spec attach( |
38 | | - name :: String.t(), |
39 | | - event :: [atom()], |
40 | | - level :: |
41 | | - Logger.level() |
42 | | - | {module :: module(), function :: atom(), arguments :: [term()]} |
43 | | - | false |
44 | | - ) :: :ok | {:error, :already_exists} |
45 | | - def attach(name, event, level) do |
46 | | - :telemetry.attach(name, event, &__MODULE__.telemetry_logging_handler/4, level) |
47 | | - end |
| 35 | + For more details on event and handler naming see |
| 36 | + (`Ecto.Repo` documentation)[https://hexdocs.pm/ecto/Ecto.Repo.html#module-telemetry-events]. |
| 37 | + """ |
| 38 | + @spec attach( |
| 39 | + name :: String.t(), |
| 40 | + event :: [atom()], |
| 41 | + level :: |
| 42 | + Logger.level() |
| 43 | + | {module :: module(), function :: atom(), arguments :: [term()]} |
| 44 | + | false |
| 45 | + ) :: :ok | {:error, :already_exists} |
| 46 | + def attach(name, event, level) do |
| 47 | + :telemetry.attach(name, event, &__MODULE__.telemetry_logging_handler/4, level) |
| 48 | + end |
48 | 49 |
|
49 | | - @doc """ |
50 | | - A telemetry handler that logs Ecto query along with it's metrics in a structured format. |
51 | | - """ |
52 | | - @spec telemetry_logging_handler( |
53 | | - event_name :: [atom()], |
54 | | - measurements :: %{ |
55 | | - query_time: non_neg_integer(), |
56 | | - queue_time: non_neg_integer(), |
57 | | - decode_time: non_neg_integer(), |
58 | | - total_time: non_neg_integer() |
59 | | - }, |
60 | | - metadata :: %{required(:query) => String.t(), required(:repo) => module()}, |
61 | | - level :: |
62 | | - Logger.level() |
63 | | - | {module :: module(), function :: atom(), arguments :: [term()]} |
64 | | - | false |
65 | | - ) :: :ok |
66 | | - def telemetry_logging_handler(_event_name, measurements, %{query: query, repo: repo}, level) do |
67 | | - query_time = Map.get(measurements, :query_time) |> format_time(:nanosecond) |
68 | | - queue_time = Map.get(measurements, :queue_time) |> format_time(:nanosecond) |
69 | | - decode_time = Map.get(measurements, :decode_time) |> format_time(:nanosecond) |
70 | | - latency = Map.get(measurements, :total_time) |> format_time(:nanosecond) |
71 | | - |
72 | | - metadata = [ |
73 | | - query: %{ |
74 | | - repo: inspect(repo), |
75 | | - execution_time_μs: query_time, |
76 | | - decode_time_μs: decode_time, |
77 | | - queue_time_μs: queue_time, |
78 | | - latency_μs: latency |
79 | | - } |
80 | | - ] |
81 | | - |
82 | | - if level = level(level, query, measurements) do |
83 | | - Logger.log(level, query, metadata) |
84 | | - else |
85 | | - :ok |
| 50 | + @doc """ |
| 51 | + A telemetry handler that logs Ecto query along with it's metrics in a structured format. |
| 52 | + """ |
| 53 | + @spec telemetry_logging_handler( |
| 54 | + event_name :: [atom()], |
| 55 | + measurements :: %{ |
| 56 | + query_time: non_neg_integer(), |
| 57 | + queue_time: non_neg_integer(), |
| 58 | + decode_time: non_neg_integer(), |
| 59 | + total_time: non_neg_integer() |
| 60 | + }, |
| 61 | + metadata :: %{required(:query) => String.t(), required(:repo) => module()}, |
| 62 | + level :: |
| 63 | + Logger.level() |
| 64 | + | {module :: module(), function :: atom(), arguments :: [term()]} |
| 65 | + | false |
| 66 | + ) :: :ok |
| 67 | + def telemetry_logging_handler(_event_name, measurements, %{query: query, repo: repo}, level) do |
| 68 | + query_time = Map.get(measurements, :query_time) |> format_time(:nanosecond) |
| 69 | + queue_time = Map.get(measurements, :queue_time) |> format_time(:nanosecond) |
| 70 | + decode_time = Map.get(measurements, :decode_time) |> format_time(:nanosecond) |
| 71 | + latency = Map.get(measurements, :total_time) |> format_time(:nanosecond) |
| 72 | + |
| 73 | + metadata = [ |
| 74 | + query: %{ |
| 75 | + repo: inspect(repo), |
| 76 | + execution_time_μs: query_time, |
| 77 | + decode_time_μs: decode_time, |
| 78 | + queue_time_μs: queue_time, |
| 79 | + latency_μs: latency |
| 80 | + } |
| 81 | + ] |
| 82 | + |
| 83 | + if level = level(level, query, measurements) do |
| 84 | + Logger.log(level, query, metadata) |
| 85 | + else |
| 86 | + :ok |
| 87 | + end |
86 | 88 | end |
87 | | - end |
88 | 89 |
|
89 | | - defp level({m, f, a}, query, measurements), do: apply(m, f, [query, measurements | a]) |
90 | | - defp level(level, _query, _measurements) when is_atom(level), do: level |
| 90 | + defp level({m, f, a}, query, measurements), do: apply(m, f, [query, measurements | a]) |
| 91 | + defp level(level, _query, _measurements) when is_atom(level), do: level |
91 | 92 |
|
92 | | - defp format_time(nil, _unit), do: 0 |
93 | | - defp format_time(time, unit), do: System.convert_time_unit(time, unit, :microsecond) |
| 93 | + defp format_time(nil, _unit), do: 0 |
| 94 | + defp format_time(time, unit), do: System.convert_time_unit(time, unit, :microsecond) |
| 95 | + end |
94 | 96 | end |
0 commit comments