Include event and handler name as tags with handle_in metrics

[clandry94]

Change description

Adds the event name that is present from the channel_handled_in telemetry payload as a tag for the duration metric.

I also noticed that :handler was included in the tags field, but wasn't actually set under tag_values. Maybe this was a bug? I added it as a tag value as well.

There's a lot of value including this tag with duration metrics. Right now, if a specific event handler function is slow, there's no way to identify that with without the event dimension. With it added, it's now possible to group by events and monitor for slow handlers.

Example usage

Nothing really required from the user's side to set this up, they'll just need to update their PromEx version. channel_handled_in_duration_milliseconds metrics will now include the event and handler tags. Example output:

phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="10"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="100"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="500"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="1000"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="5000"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="10000"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket",le="+Inf"} 1
phoenix_channel_handled_in_duration_milliseconds_sum{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket"} 0.721542
phoenix_channel_handled_in_duration_milliseconds_count{endpoint="Server.Endpoint",event="select_elements",handler="Elixir.Server.UserSocket"} 1

Checklist

• I have added unit tests to cover my changes.
• I have added documentation to cover my changes.
• My changes have passed unit tests and have been tested E2E in an example project.

[clandry94]

I noticed the phoenix tests only check for event counts and not the tag values, so this is a bit hard to test without editing a decent chunk of code. I could add additional test coverage there for this whole module in a follow-up PR if that would be preferred!

[akoutmos]

Overall this looks good to me. The only part that gives me pause is the event since it is a binary and has the potential to be an unbounded value. I think it would be best if this module accepts an option to normalize event values. The default implementation would be a passthrough:

fn event -> 
  event
end

But then the user could override this to do something like so:

fn 
  "join" -> "join"
  "leave" -> "leave"
  _ -> "unknown"
end

Thoughts?

[clandry94]

Hey @akoutmos good idea and I can implement it like you've described. Just might be a little slow due to the holiday season!

[akoutmos]

No worries at all my friend! Happy holidays!

[clandry94]

I've updated the PR with support for a normalizer function. I also added some new tests- one to test for handled_in metrics generally which I noticed were missing and another to test that configuring the normalize_event_names option works as expected.

[clandry94]

To verify this works in a Phoenix app, I've pushed up this branch to one of Felt's preview instances. Here's some of the metrics emitted-

# HELP phoenix_channel_handled_in_duration_milliseconds The time it takes for the application to respond to channel messages.
# TYPE phoenix_channel_handled_in_duration_milliseconds histogram
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="10"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="100"} 1
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="500"} 2
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="1000"} 2
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="5000"} 2
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="10000"} 2
phoenix_channel_handled_in_duration_milliseconds_bucket{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket",le="+Inf"} 2
phoenix_channel_handled_in_duration_milliseconds_sum{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket"} 186.01561399999997
phoenix_channel_handled_in_duration_milliseconds_count{endpoint="FeltServerWeb.Endpoint",event="add_elements",handler="Elixir.FeltServerWeb.UserSocket"} 2

Looks like things are working as expected!

[clandry94]

Hey @akoutmos, now that the holidays are over just wanted to poke for another review on this PR.

[coveralls]

Coverage: 79.135% (+0.1%) from 79.022% when pulling b25cc9a on clandry94:channel-names into 22664c1 on akoutmos:master.

[akoutmos]

It looks like there are some test failures. Could you address those?

[clandry94]

@akoutmos the tests should be fixed now. They were failing in different test files because I've added 2 additional test events for channel_handled_in and those tests depended on counts of metrics appearing.

[akoutmos]

LGTM!

[akoutmos]

Thanks for the contribution!!