查看源代码 遥测

本指南将向您展示如何在 Phoenix 应用程序中对 :telemetry 事件进行监控和报告。

te·lem·e·try - 指记录和传输仪器读数的过程。

在您阅读本指南的过程中,我们将向您介绍遥测的核心概念,您将初始化一个报告器来捕获应用程序在运行过程中的事件,并指导您通过使用 :telemetry 正确监控自己的函数的步骤。让我们仔细看看遥测在您的应用程序中是如何工作的。

概述

[:telemetry] 库允许您在应用程序生命周期的各个阶段发出事件。然后,您可以通过多种方式响应这些事件,例如将它们聚合为指标并将指标数据发送到报告目的地。

遥测通过名称将事件存储在 ETS 表中,以及每个事件的处理程序。然后,当执行某个事件时,遥测会查找其处理程序并调用它。

Phoenix 的遥测工具为您提供了一个主管,该主管使用 Telemetry.Metrics 来定义要处理的遥测事件列表以及如何处理这些事件,即如何将它们构建为特定类型的指标。该主管与遥测报告器一起工作,通过将事件聚合为适当的指标并将其发送到正确的报告目的地来响应指定的遥测事件。

遥测主管

从 v1.5 版本开始,新的 Phoenix 应用程序生成时会自带一个遥测主管。此模块负责管理遥测进程的生命周期。它还定义了一个 metrics/0 函数,该函数返回应用程序定义的 Telemetry.Metrics 列表。

默认情况下,主管还会启动 :telemetry_poller。只需将 :telemetry_poller 添加为依赖项,您就可以在指定的时间间隔内接收与 VM 相关的事件。

如果您使用的是旧版本的 Phoenix,请安装 :telemetry_metrics:telemetry_poller

{:telemetry_metrics, "~> 1.0"},
{:telemetry_poller, "~> 1.0"}

并在 lib/my_app_web/telemetry.ex 中创建您的遥测主管

# lib/my_app_web/telemetry.ex
defmodule MyAppWeb.Telemetry do
  use Supervisor
  import Telemetry.Metrics

  def start_link(arg) do
    Supervisor.start_link(__MODULE__, arg, name: __MODULE__)
  end

  def init(_arg) do
    children = [
      {:telemetry_poller, measurements: periodic_measurements(), period: 10_000}
      # Add reporters as children of your supervision tree.
      # {Telemetry.Metrics.ConsoleReporter, metrics: metrics()}
    ]

    Supervisor.init(children, strategy: :one_for_one)
  end

  def metrics do
    [
      # Phoenix Metrics
      summary("phoenix.endpoint.stop.duration",
        unit: {:native, :millisecond}
      ),
      summary("phoenix.router_dispatch.stop.duration",
        tags: [:route],
        unit: {:native, :millisecond}
      ),
      # VM Metrics
      summary("vm.memory.total", unit: {:byte, :kilobyte}),
      summary("vm.total_run_queue_lengths.total"),
      summary("vm.total_run_queue_lengths.cpu"),
      summary("vm.total_run_queue_lengths.io")
    ]
  end

  defp periodic_measurements do
    [
      # A module, function and arguments to be invoked periodically.
      # This function must call :telemetry.execute/3 and a metric must be added above.
      # {MyApp, :count_users, []}
    ]
  end
end

请确保用您的实际应用程序名称替换 MyApp。

然后将其添加到您的主应用程序的监督树中(通常在 lib/my_app/application.ex 中)

children = [
  MyAppWeb.Telemetry,
  MyApp.Repo,
  MyAppWeb.Endpoint,
  ...
]

遥测事件

许多 Elixir 库(包括 Phoenix)已经使用 :telemetry 包作为一种方法,通过在应用程序生命周期的关键时刻发出事件来为用户提供对其应用程序行为的更多洞察。

遥测事件由以下部分组成

  • name - 字符串(例如 "my_app.worker.stop")或唯一标识事件的原子列表。

  • measurements - 原子键(例如 :duration)和数值的映射。

  • metadata - 可用于标记指标的键值对映射。

Phoenix 示例

以下是来自您端点的事件示例

  • [:phoenix, :endpoint, :stop] - 由 Plug.Telemetry(您端点中的默认插件之一)在发送响应时发出。
    • 度量:%{duration: native_time}

    • 元数据:%{conn: Plug.Conn.t}

这意味着在每次请求之后,Plug 将通过 :telemetry 发出 "stop" 事件,并测量获取响应所花费的时间。

:telemetry.execute([:phoenix, :endpoint, :stop], %{duration: duration}, %{conn: conn})

Phoenix 遥测事件

可以在 Phoenix.Logger 中找到所有 Phoenix 遥测事件的完整列表。

指标

指标是具有特定名称的遥测事件的聚合,提供了对系统行为随时间推移的视图。

Telemetry.Metrics

Telemetry.Metrics 包为定义指标提供了一个通用接口。它公开了 五个指标类型函数,这些函数负责将给定的遥测事件构建为特定测量值。

该包本身不执行任何测量值的聚合。相反,它会向报告器提供遥测事件作为测量值定义,然后报告器使用该定义执行聚合并进行报告。

我们将在下一节中讨论报告器。

让我们看一些示例。

使用 Telemetry.Metrics,您可以定义一个计数器指标,它可以统计完成的 HTTP 请求数量。

Telemetry.Metrics.counter("phoenix.endpoint.stop.duration")

或者,您可以使用分布指标来查看在特定时间段内完成的请求数量。

Telemetry.Metrics.distribution("phoenix.endpoint.stop.duration")

这种检查 HTTP 请求的能力非常强大 - 而且这只是 Phoenix 框架发出的 *许多* 遥测事件中的一个!我们将在本指南后面的 "Phoenix 指标" 部分讨论更多这些事件,以及从 Phoenix/Plug 事件中提取有价值数据的特定模式。

从 Phoenix 发出的 :telemetry 事件的完整列表及其测量值和元数据可以在 Phoenix.Logger 模块文档的 "监控" 部分找到。

Ecto 示例

与 Phoenix 一样,Ecto 也自带内置的遥测事件。这意味着您可以使用相同的工具深入了解您的 Web 层和数据库层。

以下是在 Ecto 存储库启动时由 Ecto 执行的遥测事件示例

  • [:ecto, :repo, :init] - 由 Ecto.Repo 发出。
    • 度量:%{system_time: native_time}

    • 元数据:%{repo: Ecto.Repo, opts: Keyword.t()}

这意味着每当 Ecto.Repo 启动时,它会通过 :telemetry 发出事件,并测量启动时的系统时间。

:telemetry.execute([:ecto, :repo, :init], %{system_time: System.system_time()}, %{repo: repo, opts: opts})

Ecto 适配器会执行其他遥测事件。

其中一个适配器特定事件是 [:my_app, :repo, :query] 事件。例如,如果您想绘制查询执行时间的图表,可以使用 Telemetry.Metrics.summary/2 函数来指示您的报告器计算 [:my_app, :repo, :query] 事件的统计信息,例如最大值、平均值、百分位数等。

Telemetry.Metrics.summary("my_app.repo.query.query_time",
  unit: {:native, :millisecond}
)

或者,您可以使用 Telemetry.Metrics.distribution/2 函数为另一个适配器特定事件定义直方图:[:my_app, :repo, :query, :queue_time],从而可视化查询在队列中等待的时间。

Telemetry.Metrics.distribution("my_app.repo.query.queue_time",
  unit: {:native, :millisecond}
)

您可以在 Ecto.Repo 模块文档的 "遥测事件" 部分了解更多关于 Ecto 遥测的信息。

到目前为止,我们已经看到了 Phoenix 应用程序中常见的遥测事件,以及一些关于它们各种测量值和元数据的示例。有了所有这些等待被消费的数据,让我们谈谈报告器。

报告器

报告器使用 Telemetry.Metrics 提供的通用接口订阅遥测事件。然后,它们将测量值(数据)聚合成指标,以提供有关应用程序的有意义信息。

例如,如果将以下 Telemetry.Metrics.summary/2 调用添加到遥测主管的 metrics/0 函数中

summary("phoenix.endpoint.stop.duration",
  unit: {:native, :millisecond}
)

那么报告器将附加一个针对 "phoenix.endpoint.stop.duration" 事件的监听器,并将通过计算使用给定事件元数据的摘要指标并将其报告到相应的来源来响应此事件。

Phoenix.LiveDashboard

对于对遥测指标实时可视化感兴趣的开发人员,您可能希望安装 LiveDashboard。LiveDashboard 充当 Telemetry.Metrics 报告器,将您的数据呈现为仪表盘上美观、实时的图表。

Telemetry.Metrics.ConsoleReporter

Telemetry.Metrics 附带一个 ConsoleReporter,可用于将事件和指标打印到终端。您可以使用此报告器来试验本指南中讨论的指标。

在您的遥测监督树中(通常在 lib/my_app_web/telemetry.ex 中),取消注释或添加以下内容到子项列表中

{Telemetry.Metrics.ConsoleReporter, metrics: metrics()}

有许多可用的报告器,用于 StatsD、Prometheus 等服务。您可以在 hex.pm 上搜索 "telemetry_metrics" 来找到它们。

Phoenix 指标

之前我们查看了由 Plug.Telemetry 发出的 "stop" 事件,并使用它来统计 HTTP 请求的数量。实际上,仅仅能够看到请求的总数是有一定帮助的。如果您想查看每个路由的请求数量,或者每个路由和方法的请求数量呢?

让我们看一下在 HTTP 请求生命周期中发出的另一个事件,这次来自 Phoenix.Router

  • [:phoenix, :router_dispatch, :stop] - 由 Phoenix.Router 在成功分发到匹配的路由后发出。
    • 度量:%{duration: native_time}

    • 元数据:%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom]}

让我们首先按路由对这些事件进行分组。将以下内容(如果不存在)添加到遥测主管的 metrics/0 函数中(通常在 lib/my_app_web/telemetry.ex 中)

# lib/my_app_web/telemetry.ex
def metrics do
  [
    ...metrics...
    summary("phoenix.router_dispatch.stop.duration",
      tags: [:route],
      unit: {:native, :millisecond}
    )
  ]
end

重新启动服务器,然后向一两个页面发出请求。在您的终端中,您应该看到 ConsoleReporter 打印它接收到的遥测事件的日志,这些日志是根据您提供的指标定义生成的。

每个请求的日志行包含该请求的特定路由。这是由于为摘要指标指定了 :tags 选项,该选项满足了我们的第一个要求;我们可以使用 :tags 按路由对指标进行分组。请注意,报告器将根据使用的底层服务以不同的方式处理标签。

仔细查看 Router "stop" 事件,您可以看到表示请求的 Plug.Conn 结构体存在于元数据中,但是您如何访问 conn 中的属性呢?

幸运的是,Telemetry.Metrics 提供了以下选项来帮助您分类事件

  • :tags - 用于分组的元数据键列表;

  • :tag_values - 将元数据转换为所需形状的函数;请注意,此函数会为每个事件调用,因此如果事件速率很高,请确保其执行速度快。

了解Telemetry.Metrics 模块文档中所有可用的指标选项。

让我们了解如何从元数据中包含 conn 的事件中提取更多标签。

从 Plug.Conn 中提取标签值

让我们为路由事件添加另一个指标,这次按路由和方法进行分组。

summary("phoenix.router_dispatch.stop.duration",
  tags: [:method, :route],
  tag_values: &get_and_put_http_method/1,
  unit: {:native, :millisecond}
)

我们在这里引入了 :tag_values 选项,因为我们需要对事件元数据进行转换才能获得所需的值。

将以下私有函数添加到 Telemetry 模块中,以从 Plug.Conn 结构中提取 :method 值。

# lib/my_app_web/telemetry.ex
defp get_and_put_http_method(%{conn: %{method: method}} = metadata) do
  Map.put(metadata, :method, method)
end

重启服务器并发出更多请求。您应该开始看到带有 HTTP 方法和路由标签的日志。

请注意,:tags:tag_values 选项可以应用于所有 Telemetry.Metrics 类型。

使用标签值重命名值标签

有时,在显示指标时,可能需要转换值标签以提高可读性。例如,以下指标显示了每个 LiveView 的 mount/3 回调的持续时间,按 connected? 状态分类。

summary("phoenix.live_view.mount.stop.duration",
  unit: {:native, :millisecond},
  tags: [:view, :connected?],
  tag_values: &live_view_metric_tag_values/1
)

以下函数将 metadata.socket.viewmetadata.socket.connected? 提升为 metadata 上的顶级键,就像我们在前面的示例中所做的那样。

# lib/my_app_web/telemetry.ex
defp live_view_metric_tag_values(metadata) do
  metadata
  |> Map.put(:view, metadata.socket.view)
  |> Map.put(:connected?, Phoenix.LiveView.connected?(metadata.socket))
end

但是,在 LiveDashboard 中渲染这些指标时,值标签会输出为 "Elixir.Phoenix.LiveDashboard.MetricsLive true"

为了使值标签更易于阅读,我们可以更新我们的私有函数以生成更人性化的名称。我们将通过 inspect/1 运行 :view 的值以删除 Elixir. 前缀,并调用另一个私有函数将 connected? 布尔值转换为人类可读的文本。

# lib/my_app_web/telemetry.ex
defp live_view_metric_tag_values(metadata) do
  metadata
  |> Map.put(:view, inspect(metadata.socket.view))
  |> Map.put(:connected?, get_connection_status(Phoenix.LiveView.connected?(metadata.socket)))
end

defp get_connection_status(true), do: "Connected"
defp get_connection_status(false), do: "Disconnected"

现在,值标签将呈现为 "Phoenix.LiveDashboard.MetricsLive Connected"

希望这能激发您使用 :tag_values 选项的灵感。请记住,此函数是在每次事件发生时调用的,因此请确保其执行速度快。

周期性测量

您可能希望定期测量应用程序中的键值对。幸运的是,:telemetry_poller 包提供了自定义测量的机制,这对于检索进程信息或定期执行自定义测量非常有用。

将以下内容添加到 Telemetry 监督程序的 periodic_measurements/0 函数中的列表中,该函数是一个私有函数,用于返回在指定间隔内要执行的测量列表。

# lib/my_app_web/telemetry.ex
defp periodic_measurements do
  [
    {MyApp, :measure_users, []},
    {:process_info,
      event: [:my_app, :my_server],
      name: MyApp.MyServer,
      keys: [:message_queue_len, :memory]}
  ]
end

其中 MyApp.measure_users/0 可以这样编写。

# lib/my_app.ex
defmodule MyApp do
  def measure_users do
    :telemetry.execute([:my_app, :users], %{total: MyApp.users_count()}, %{})
  end
end

现在,在测量到位后,您可以为上面的事件定义指标。

# lib/my_app_web/telemetry.ex
def metrics do
  [
    ...metrics...
    # MyApp Metrics
    last_value("my_app.users.total"),
    last_value("my_app.my_server.memory", unit: :byte),
    last_value("my_app.my_server.message_queue_len")
    summary("my_app.my_server.call.stop.duration"),
    counter("my_app.my_server.call.exception")
  ]
end

您将在 自定义事件 部分实现 MyApp.MyServer。

使用 Telemetry 的库

Telemetry 正在迅速成为 Elixir 中包仪器的实际标准。以下是一些当前正在发出 :telemetry 事件的库列表。

库作者积极鼓励发送 PR 添加自己的库(请按字母顺序排列)。

自定义事件

如果您需要在应用程序中进行自定义指标和仪器,您可以像使用您喜欢的框架和库一样使用 :telemetry 包 (https://hexdocs.erlang.ac.cn/telemetry)。

以下是一个简单的 GenServer 的示例,它会发出 Telemetry 事件。在您应用程序的 lib/my_app/my_server.ex 中创建此文件。

# lib/my_app/my_server.ex
defmodule MyApp.MyServer do
  @moduledoc """
  An example GenServer that runs arbitrary functions and emits telemetry events when called.
  """
  use GenServer

  # A common prefix for :telemetry events
  @prefix [:my_app, :my_server, :call]

  def start_link(fun) do
    GenServer.start_link(__MODULE__, fun, name: __MODULE__)
  end

  @doc """
  Runs the function contained within this server.

  ## Events

  The following events may be emitted:

    * `[:my_app, :my_server, :call, :start]` - Dispatched
      immediately before invoking the function. This event
      is always emitted.

      * Measurement: `%{system_time: system_time}`

      * Metadata: `%{}`

    * `[:my_app, :my_server, :call, :stop]` - Dispatched
      immediately after successfully invoking the function.

      * Measurement: `%{duration: native_time}`

      * Metadata: `%{}`

    * `[:my_app, :my_server, :call, :exception]` - Dispatched
      immediately after invoking the function, in the event
      the function throws or raises.

      * Measurement: `%{duration: native_time}`

      * Metadata: `%{kind: kind, reason: reason, stacktrace: stacktrace}`
  """
  def call!, do: GenServer.call(__MODULE__, :called)

  @impl true
  def init(fun) when is_function(fun, 0), do: {:ok, fun}

  @impl true
  def handle_call(:called, _from, fun) do
    # Wrap the function invocation in a "span"
    result = telemetry_span(fun)

    {:reply, result, fun}
  end

  # Emits telemetry events related to invoking the function
  defp telemetry_span(fun) do
    start_time = emit_start()

    try do
      fun.()
    catch
      kind, reason ->
        stacktrace = System.stacktrace()
        duration = System.monotonic_time() - start_time
        emit_exception(duration, kind, reason, stacktrace)
        :erlang.raise(kind, reason, stacktrace)
    else
      result ->
        duration = System.monotonic_time() - start_time
        emit_stop(duration)
        result
    end
  end

  defp emit_start do
    start_time_mono = System.monotonic_time()

    :telemetry.execute(
      @prefix ++ [:start],
      %{system_time: System.system_time()},
      %{}
    )

    start_time_mono
  end

  defp emit_stop(duration) do
    :telemetry.execute(
      @prefix ++ [:stop],
      %{duration: duration},
      %{}
    )
  end

  defp emit_exception(duration, kind, reason, stacktrace) do
    :telemetry.execute(
      @prefix ++ [:exception],
      %{duration: duration},
      %{
        kind: kind,
        reason: reason,
        stacktrace: stacktrace
      }
    )
  end
end

并将其添加到应用程序的监督程序树中(通常在 lib/my_app/application.ex 中),并为其提供一个在调用时调用的函数。

# lib/my_app/application.ex
children = [
  # Start a server that greets the world
  {MyApp.MyServer, fn -> "Hello, world!" end},
]

现在启动一个 IEx 会话并调用服务器。

iex> MyApp.MyServer.call!

您应该看到类似以下输出的内容。

[Telemetry.Metrics.ConsoleReporter] Got new event!
Event name: my_app.my_server.call.stop
All measurements: %{duration: 4000}
All metadata: %{}

Metric measurement: #Function<2.111777250/1 in Telemetry.Metrics.maybe_convert_measurement/2> (summary)
With value: 0.004 millisecond
Tag values: %{}

"Hello, world!"