Instrumenting Phoenix
The heart of a Phoenix application is the endpoint module. It is the entry point for web requests and it encapsulates the supervision tree of our web application. In our app, it is called DemoWeb.Endpoint. This module also contains a function named instrument/3, which we can use to instrument any event inside our web stack:
| | require DemoWeb.Endpoint |
| | DemoWeb.Endpoint.instrument(:long_operation_in_controller, |
| | %{metadata: "foobar"}, fn -> |
| | # code to be instrumented |
| | end) |
Phoenix itself instruments a handful of events, listed here:
-
phoenix_controller_call measures how long the controller takes to process your request.
-
phoenix_controller_render measures the time the controller takes to render your view.
-
phoenix_channel_join records each time a user joins a channel.
-
phoenix_channel_receive records each message received by a client on a channel.
To consume those events published by your own application or by Phoenix, you’ll probably want to instrument them through a specific Elixir module. This module should export functions with the same name as the events themselves. Phoenix will call each function twice per event, once when the event starts, and again when it finishes.
For example, to instrument the phoenix_controller_call event, we would define a module with two functions:
| | defmodule DemoWeb.PhoenixInspector do |
| | def phoenix_controller_call(:start, compile_metadata, runtime_metadata) do |
| | IO.inspect {:start, compile_metadata, runtime_metadata} |
| | :ok |
| | end |
| | |
| | def phoenix_controller_call(:stop, time_in_native_unit, _result_of_start) do |
| | IO.inspect {:stop, time_in_native_unit} |
| | end |
| | end |
Note the result of the :start callback is given to the :stop callback with the time elapsed between events in native units. Just as you did with the Ecto events, convert them to known units using System.convert_time_unit/3.
Create the module above in lib/demo_web/phoenix_inspector.ex. Then, tell Phoenix to use it in config/config.exs:
| | config :demo, DemoWeb.Endpoint, |
| | instrumenters: [DemoWeb.PhoenixInspector] |
Start the server once again and you should see our instrumenter kicking in and printing the controller information:
| | {:start, |
| | %{ |
| | application: :demo, |
| | file: "demo/lib/demo_web/controllers/page_controller.ex", |
| | function: "call/2", |
| | line: 2, |
| | module: DemoWeb.PageController |
| | }, |
| | %{ |
| | conn: %Plug.Conn{...}, |
| | log_level: :debug |
| | } |
| | } |
| | {:stop, 335169} |
You can see the start event includes compile time information such as the application name, source file, function name, and so on. The stop event includes the time the action effectively took.
Phoenix instrumenters provide a mechanism to instrument and hook into existing events, allowing you to push this data to anywhere you would like, including external systems. Similar to Ecto, if you are picking up an existing tool, it is most likely those hooks are already in place.
At ElixirConf EU 2017, Chris McCord announced metrics and monitoring would be the next focus of the Phoenix team. This means the process of getting information out of Ecto and Phoenix will likely become much more streamlined. Still, understanding the measurements and their impact on the system is essential, so what you have learned here will still serve you well, even if the plumbing in the future is not quite the same.
Even though we have focused on Ecto and Phoenix, the process for other libraries will be quite similar. If they provide their own metrics and instrumentation hooks, then you should look into integrating with them and pushing the data to your own systems. If they do not, then your best bet is to measure important function calls and track any important process that may be part of the third-party library. If you are not sure which processes are part of those libraries, you can use Observer to explore the different supervision trees in your system.
Now that we have hooked up our metrics, it is time to assess if our system will behave how we expect it to.