Add telemetry events

guides/endpoint.md

@@ -65,11 +65,11 @@ if code_reloading? do
 end
 ```
 
-[Plug.RequestId](https://hexdocs.pm/plug/Plug.RequestId.html) generates a unique id for each request and [Plug.Logger](https://hexdocs.pm/plug/Plug.Logger.html) logs the request path, status code and request time by default.
+[Plug.RequestId](https://hexdocs.pm/plug/Plug.RequestId.html) generates a unique id for each request and [Plug.Telemetry](https://hexdocs.pm/plug/Plug.Telemetry.html) adds instrumentation points so Phoenix can log the request path, status code and request time by default.
 
 ```elixir
 plug Plug.RequestId
-plug Plug.Logger
+plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint]
 ```
 
 [Plug.Session](https://hexdocs.pm/plug/Plug.Session.html) handles the session cookies and session stores.

installer/templates/phx_web/endpoint.ex

@@ -24,7 +24,7 @@ defmodule <%= endpoint_module %> do
   end
 
   plug Plug.RequestId
-  plug Plug.Logger
+  plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint]
 
   plug Plug.Parsers,
     parsers: [:urlencoded, :multipart, :json],

lib/phoenix.ex

@@ -44,6 +44,8 @@ defmodule Phoenix do
       :erlang.system_flag(:backtrace_depth, stacktrace_depth)
     end
 
+    Phoenix.Logger.install()
+
     # Start the supervision tree
     import Supervisor.Spec
 

lib/phoenix/channel/server.ex

@@ -32,9 +32,7 @@ defmodule Phoenix.Channel.Server do
     ref = make_ref()
     from = {self(), ref}
 
-    # TODO: When we migrate to DynamicSupervisor, we will start
-    # {channel, {payload, from, socket}} and have its child spec
-    # point back to this module start link.
+    # TODO: Migrate to DynamicSupervisor and invoke the channel child_spec.
     args = [channel, {payload, from, socket}]
 
     case PoolSupervisor.start_child(socket.endpoint, socket.handler, from, args) do
@@ -252,29 +250,13 @@ defmodule Phoenix.Channel.Server do
         private: Map.merge(channel.__socket__(:private), private)
     }
 
-    case channel_join(socket, channel, topic, auth_payload) do
-      {:ok, socket} ->
-        init_info(socket, channel, topic, %{}, from)
-
-      {:ok, reply, socket} ->
-        init_info(socket, channel, topic, reply, from)
-
-      {:error, reply} ->
-        log_join(socket, topic, fn -> "Replied #{topic} :error" end)
-        GenServer.reply(from, {:error, reply})
-        {:stop, :shutdown, socket}
-
-      other ->
-        raise """
-        channel #{inspect(socket.channel)}.join/3 is expected to return one of:
-
-            {:ok, Socket.t} |
-            {:ok, reply :: map, Socket.t} |
-            {:error, reply :: map}
-
-        got #{inspect(other)}
-        """
-    end
+    start = System.monotonic_time()
+    {reply, state} = channel_join(channel, topic, auth_payload, socket)
+    duration = System.monotonic_time() - start
+    metadata = %{params: auth_payload, socket: socket, result: elem(reply, 0)}
+    :telemetry.execute([:phoenix, :channel_joined], %{duration: duration}, metadata)
+    GenServer.reply(from, reply)
+    state
   end
 
   def handle_info(%Message{topic: topic, event: "phx_leave", ref: ref}, %{topic: topic} = socket) do
@@ -285,13 +267,12 @@ defmodule Phoenix.Channel.Server do
         %Message{topic: topic, event: event, payload: payload, ref: ref},
         %{topic: topic} = socket
       ) do
-    runtime = %{ref: ref, event: event, params: payload, socket: socket}
-
-    Phoenix.Endpoint.instrument(socket, :phoenix_channel_receive, runtime, fn ->
-      event
-      |> socket.channel.handle_in(payload, put_in(socket.ref, ref))
-      |> handle_in()
-    end)
+    start = System.monotonic_time()
+    result = socket.channel.handle_in(event, payload, put_in(socket.ref, ref))
+    duration = System.monotonic_time() - start
+    metadata = %{ref: ref, event: event, params: payload, socket: socket}
+    :telemetry.execute([:phoenix, :channel_handled_in], %{duration: duration}, metadata)
+    handle_in(result)
   end
 
   def handle_info(
@@ -379,29 +360,40 @@ defmodule Phoenix.Channel.Server do
 
   ## Joins
 
-  defp channel_join(socket, channel, topic, auth_payload) do
-    instrument = %{params: auth_payload, socket: socket}
+  defp channel_join(channel, topic, auth_payload, socket) do
+    case channel.join(topic, auth_payload, socket) do
+      {:ok, socket} ->
+        {{:ok, %{}}, init_join(socket, channel, topic)}
 
-    Phoenix.Endpoint.instrument(socket, :phoenix_channel_join, instrument, fn ->
-      channel.join(topic, auth_payload, socket)
-    end)
+      {:ok, reply, socket} ->
+        {{:ok, reply}, init_join(socket, channel, topic)}
+
+      {:error, reply} ->
+        {{:error, reply}, {:stop, :shutdown, socket}}
+
+      other ->
+        raise """
+        channel #{inspect(socket.channel)}.join/3 is expected to return one of:
+
+            {:ok, Socket.t} |
+            {:ok, reply :: map, Socket.t} |
+            {:error, reply :: map}
+
+        got #{inspect(other)}
+        """
+    end
   end
 
-  defp init_info(socket, channel, topic, reply, from) do
+  defp init_join(socket, channel, topic) do
     %{transport_pid: transport_pid, serializer: serializer, pubsub_server: pubsub_server} = socket
     Process.monitor(transport_pid)
 
     fastlane = {transport_pid, serializer, channel.__intercepts__()}
     PubSub.subscribe(pubsub_server, topic, link: true, fastlane: fastlane)
 
-    log_join(socket, topic, fn -> "Replied #{topic} :ok" end)
-    GenServer.reply(from, {:ok, reply})
     {:noreply, %{socket | joined: true}}
   end
 
-  defp log_join(%{private: %{log_join: false}}, _topic, _func), do: :noop
-  defp log_join(%{private: %{log_join: level}}, _topic, func), do: Logger.log(level, func)
-
   ## Handle results
 
   defp handle_result({:stop, reason, socket}, _callback) do

lib/phoenix/endpoint.ex

@@ -237,131 +237,45 @@ defmodule Phoenix.Endpoint do
 
   ## Instrumentation
 
-  Phoenix supports instrumentation through an extensible API. Each endpoint
-  defines an `c:instrument/3` macro that both users and Phoenix internals can call
-  to instrument generic events. This macro is responsible for measuring the time
-  it takes for the event to be processed and for notifying a list of interested
-  instrumenter modules of this measurement.
-
-  You can configure this list of instrumenter modules in the compile-time
-  configuration of your endpoint. (see the `:instrumenters` option above). The
-  way these modules express their interest in events is by exporting public
-  functions where the name of each function is the name of an event. For
-  example, if someone instruments the `:render_view` event, then each
-  instrumenter module interested in that event will have to export
-  `render_view/3`.
-
-  ### Callbacks cycle
-
-  The event callback sequence is:
-
-    1. The event callback is called *before* the event happens (in this case,
-       before the view is rendered) with the atom `:start` as the first
-       argument; see the "Before clause" section below
-    2. The event occurs (in this case, the view is rendered)
-    3. The same event callback is called again, this time with the atom `:stop`
-       as the first argument; see the "After clause" section below
-
-  The second and third argument that each event callback takes depends on the
-  callback being an "after" or a "before" callback i.e. it depends on the
-  value of the first argument, `:start` or `:stop`. For this reason, most of
-  the time you will want to define (at least) two separate clauses for each
-  event callback, one for the "before" and one for the "after" callbacks.
-
-  All event callbacks are run in the same process that calls the `c:instrument/3`
-  macro; hence, instrumenters should be careful to avoid performing blocking actions.
-  If an event callback fails in any way (exits, throws, or raises), it won't
-  affect anything as the error is caught, but the failure will be logged. Note
-  that "after" callbacks are not guaranteed to be called as, for example, a link
-  may break before they've been called.
-
-  #### "Before" clause
-
-  When the first argument to an event callback is `:start`, the signature of
-  that callback is:
-
-      event_callback(:start, compile_metadata, runtime_metadata)
-
-  where:
-
-    * `compile_metadata` is a map of compile-time metadata about the environment
-      where `instrument/3` has been called. It contains the module where the
-      instrumentation is happening (under the `:module` key), the file and line
-      (`:file` and `:line`), and the function inside which the instrumentation
-      is happening (under `:function`). This information can be used arbitrarily
-      by the callback
-    * `runtime_metadata` is a map of runtime data that the instrumentation
-      passes to the callbacks. This can be used for any purposes: for example,
-      when instrumenting the rendering of a view, the name of the view could be
-      passed in these runtime data so that instrumenters know which view is
-      being rendered (`instrument(:view_render, %{view: "index.html"}, fn
-      ...)`)
-
-  #### "After" clause
-
-  When the first argument to an event callback is `:stop`, the signature of that
-  callback is:
-
-      event_callback(:stop, time_diff, result_of_before_callback)
-
-  where:
-
-    * `time_diff` is an integer representing the time it took to execute the
-      instrumented function **in native units**
-
-    * `result_of_before_callback` is the return value of the "before" clause of
-      the same `event_callback`. This is a means of passing data from the
-      "before" clause to the "after" clause when instrumenting
-
-  The return value of each "before" event callback will be stored and passed to
-  the corresponding "after" callback.
-
-  ### Using instrumentation
-
-  Each Phoenix endpoint defines its own `instrument/3` macro. This macro is
-  called like this:
-
-      require MyApp.Endpoint
-      MyApp.Endpoint.instrument(:render_view, %{view: "index.html"}, fn ->
-        # actual view rendering
-      end)
-
-  All the instrumenter modules that export a `render_view/3` function will be
-  notified of the event so that they can perform their respective actions.
-
-  ### Phoenix default events
-
-  By default, Phoenix instruments the following events:
-
-    * `:phoenix_controller_call` - the entire controller pipeline.
-      The `%Plug.Conn{}` is passed as runtime metadata
-    * `:phoenix_controller_render` - the rendering of a view from a
-      controller. The map of runtime metadata passed to instrumentation
-      callbacks has the `:view` key - for the name of the view, e.g. `HexWeb.ErrorView`,
-      the `:template` key - for the name of the template, e.g.,
-      `"index.html"`, the `:format` key - for the format of the template, and
-      the `:conn` key - containing the `%Plug.Conn{}`
-    * `:phoenix_error_render` - the rendering of an error view when an exception,
-      throw, or exit is caught. The map of runtime metadata contains the `:status`
-      key of the error's HTTP status code, the `:conn` key containg the
-      `%Plug.Conn{}`, as well as the `:kind`, `:reason`, and `:stacktrace` of
-      the caught error
-    * `:phoenix_channel_join` - the joining of a channel. The `%Phoenix.Socket{}`
-      and join params are passed as runtime metadata via `:socket` and `:params`
-    * `:phoenix_channel_receive` - the receipt of an incoming message over a
-      channel. The `%Phoenix.Socket{}`, payload, event, and ref are passed as
-      runtime metadata via `:socket`, `:params`, `:event`, and `:ref`
-    * `:phoenix_socket_connect` - the connection of the user socket transport.
-      The map of runtime metadata contains the `:transport`, `:params`, a map of
-      `connect_info`, and the `:user_socket` module.
-
-  ### Dynamic instrumentation
-
-  If you want to instrument a piece of code, but the endpoint that should
-  instrument it (the one that contains the `c:instrument/3` macro you want to use)
-  is not known at compile time, only at runtime, you can use the
-  `Phoenix.Endpoint.instrument/4` macro. Refer to its documentation for more
-  information.
+  Phoenix uses the `:telemetry` library for instrumentation. The following events
+  are published by Phoenix with the following measurements and metadata:
+
+    * `[:phoenix, :endpoint, :start]` - dispatched by `Plug.Telemetry` in your
+      endpoint at the beginning of every request.
+      * Measurement: `%{time: System.monotonic_time}`
+      * Metadata: `%{conn: Plug.Conn.t}`
+
+    * `[:phoenix, :endpoint, :stop]` - dispatched by `Plug.Telemetry` in your
+      endpoint whenever the response is sent
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{conn: Plug.Conn.t}`
+
+    * `[:phoenix, :router_dispatch, :start]` - dispatched by `Phoenix.Router`
+      before dispatching to a matched route
+      * Measurement: `%{time: System.monotonic_time}`
+      * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom]}`
+
+    * `[:phoenix, :router_dispatch, :stop]` - dispatched by `Phoenix.Router`
+      after successfully dispatching to a matched route
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom]}`
+
+    * `[:phoenix, :error_rendered]` - dispatched at the end of an error view being rendered
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{status: Plug.Conn.status, kind: Exception.kind, reason: term, stacktrace: Exception.stacktrace}`
+
+    * `[:phoenix, :socket_connected]` - dispatched at the end of a socket connection
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{endpoint: atom, transport: atom, params: term, connect_info: map, vsn: binary, user_socket: atom, result: :ok | :error, serializer: atom}`
+
+    * `[:phoenix, :channel_joined]` - dispatched at the end of a channel join
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{params: term, socket: Phoenix.Socket.t}`
+
+    * `[:phoenix, :channel_handled_in]` - dispatched at the end of a channel handle in
+      * Measurement: `%{duration: native_time}`
+      * Metadata: `%{event: binary, params: term, socket: Phoenix.Socket.t}`
+
   """
 
   @type topic :: String.t
@@ -979,31 +893,7 @@ defmodule Phoenix.Endpoint do
     end
   end
 
-  @doc """
-  Instruments the given function using the instrumentation provided by
-  the given endpoint.
-
-  To specify the endpoint that will provide instrumentation, the first argument
-  can be:
-
-    * a module name - the endpoint itself
-    * a `Plug.Conn` struct - this macro will look for the endpoint module in the
-      `:private` field of the connection; if it's not there, `fun` will be
-      executed with no instrumentation
-    * a `Phoenix.Socket` struct - this macro will look for the endpoint module in the
-      `:endpoint` field of the socket; if it's not there, `fun` will be
-      executed with no instrumentation
-
-  Usually, users should prefer to instrument events using the `c:instrument/3`
-  macro defined in every Phoenix endpoint. This macro should only be used for
-  cases when the endpoint is dynamic and not known at compile time.
-
-  ## Examples
-
-      endpoint = MyApp.Endpoint
-      Phoenix.Endpoint.instrument endpoint, :render_view, fn -> ... end
-
-  """
+  @doc false
   defmacro instrument(endpoint_or_conn_or_socket, event, runtime \\ Macro.escape(%{}), fun) do
     compile = Phoenix.Endpoint.Instrument.strip_caller(__CALLER__) |> Macro.escape()
 

lib/phoenix/endpoint/instrument.ex

@@ -95,7 +95,7 @@ defmodule Phoenix.Endpoint.Instrument do
       raise ":instrumenters must be a list of instrumenter modules"
     end
 
-    events_to_instrumenters([Phoenix.Logger | instrumenters])
+    events_to_instrumenters(instrumenters)
   end
 
   # Strips a `Macro.Env` struct, leaving only interesting compile-time metadata.

lib/phoenix/endpoint/render_errors.ex

@@ -66,17 +66,20 @@ defmodule Phoenix.Endpoint.RenderErrors do
   end
 
   defp instrument_render_and_send(conn, kind, reason, stack, opts) do
-    level = Keyword.get(opts, :log_level, :debug)
+    level = Keyword.get(opts, :log, :debug)
     status = status(kind, reason)
     conn = error_conn(conn, kind, reason)
-    metadata = %{status: status, conn: conn, kind: kind, reason: reason, stacktrace: stack, log_level: level}
+    start = System.monotonic_time()
+    metadata = %{status: status, kind: kind, reason: reason, stacktrace: stack, log: level}
 
-    conn =
-      Phoenix.Endpoint.instrument(conn, :phoenix_error_render, metadata, fn ->
-        render(conn, status, kind, reason, stack, opts)
-      end)
-
-    send_resp(conn)
+    try do
+      conn
+      |> render(status, kind, reason, stack, opts)
+      |> send_resp()
+    after
+      duration = System.monotonic_time() - start
+      :telemetry.execute([:phoenix, :error_rendered], %{duration: duration}, metadata)
+    end
   end
 
   defp error_conn(_conn, :error, %NoRouteError{conn: conn}), do: conn