Instrumentation

This page lists the events a hibiki_rails channel publishes, and shows how to time actions and renders with them. Read it when you want to know how long an action takes, which render is slow, or how long a visitor waited. The events arrived in 0.18.0.

Rails already times a channel action, in perform_action.action_cable. In a hibiki channel that event covers very little. The channel hands each action to the graph thread, the one worker thread that owns a subscription’s signals and effects (Channel lifecycle explains it), and Rails stops its clock when the hand-off returns. The action, the effects it re-runs, and the renders those effects send all happen afterward. The events below are published from the graph thread, around the work itself.

The events

All five go through ActiveSupport::Notifications, the same mechanism Rails uses for its own events. They are always on and need no configuration, and the gem subscribes to none of them.

The payload keys:

• channel is the channel’s class name, and action the name of the action method.
• wait is the time the action spent queued for the graph thread, in milliseconds. It grows when earlier actions on the same subscription are slow.
• renders is the number of broadcast renders the action caused.
• target is the DOM id the render replaces. method is :replace, :morph, or :refresh, and a refresh has no target.

Subscribing

Subscribe in an initializer, as you would to any Rails event:

# config/initializers/hibiki_metrics.rb
ActiveSupport::Notifications.subscribe("action.hibiki_rails") do |event|
  payload = event.payload
  Rails.logger.info(
    "#{payload[:channel]}##{payload[:action]} " \
    "#{event.duration.round(1)}ms, waited #{payload[:wait].round(1)}ms, " \
    "#{payload[:renders]} renders"
  )
end

A subscriber runs on the graph thread. While it runs, that visitor’s next action waits. Keep a subscriber to cheap work in memory, such as adding to a counter, and do the slow part (a database write, a call to a metrics service) elsewhere, on a timer or in a job.

With no subscriber, an event costs an action one to two microseconds.

What is and is not published

• An action the channel does not have publishes nothing. The action name comes from the browser, so a subscriber that stores names is only ever given the names of your own action methods.
• A raising action still publishes. Its payload carries the exception under :exception and :exception_object, as any Rails event does.
• A render with no action has no action event. A model’s after_commit ping or a debounced refresh re-runs an effect outside any action. Its render event is published as usual.
• transmit_value and transmit_url have no event of their own. Action Cable’s transmit.action_cable covers them.
• No event carries a byte count. Action Cable’s broadcast.action_cable fires inside the render event, on the same thread, and its payload holds the message. A subscriber that wants the size of each render can read it there.

Counting subscriptions

Hibiki::Rails.registry knows the live subscriptions in the process:

Hibiki::Rails.registry.size   # => 12
Hibiki::Rails.registry.tally  # => { "SongsChannel" => 9, "CounterChannel" => 3 }

Read these for a count. Adding up subscribe and unsubscribe events drifts in development, where a code reload can drop a socket without the unsubscribe running.

Trips: how long a visitor waited

The server cannot time what a visitor felt. The acknowledgement that ends an action and the HTML it rendered travel separately, and only the browser sees both arrive. The JS client can time each round trip, a trip, and report it:

// app/javascript/application.js
import { HibikiController } from "hibiki-rails"

HibikiController.reportTrips = true

Reporting is off until you set this. Set it once, on the class, and every island on the page reports.

An island then sends its recent trips along with its next action, and the channel publishes one trip.hibiki_rails event for each:

• ack is the milliseconds from the action being sent to the server’s acknowledgement arriving.
• paint is the milliseconds from the action being sent to its first render arriving, or nil when the action rendered nothing. An island that only uses broadcast_refresh always reports nil, because a refresh fetches the page instead of carrying HTML.

A trip event has no duration of its own; the two figures are its content.

What reporting leaves out:

• The last trip on a page is never sent, since no action follows it.
• A trip the server dropped, or one that stalled, is not reported.
• An island sends at most its last five trips with one action.

Treat trip figures as reported, not measured. They come from the visitor’s browser, and anyone can send false ones. The channel accepts at most five per action, only for its own action names, and clamps each figure to between 0 and 60 000 ms. It cannot check them beyond that.

Trips ride on a third reserved payload key, hbt. Like hbk, the channel removes it before your action method runs (Driving an island describes the payload).