JSON api: plug+cowboy inconsistent request handling

Questions / Help
, ,
1

I am new to elixir and did a slack bot(https://github.com/ahsandar/ultronex) few months ago and now added a simple JSON api (https://github.com/ahsandar/ultronex/tree/master/lib/ultronex/server) to it to check stats. The api has basically 5 paths

  • /heartbeat
  • /track
  • /stats
    */ favicon
  • _ (match all to 404)

The slowest of all these endpoint seem to be heartbeat while both track and stats have to fetch values from ets for their JSON response while heartbeat responds with a static JSON. It would be understandable for the _ match to be the slowest because of looking for a matching path before the request is dispatched to it.

I can see the avg time for heartbeat is over 1.7ms while stats and track are below 0.7ms. These are NewRelic numbers. Even in the logs I see the heartbeat to be 5X slower compared to other endpoints. It might seem weird to be questioning times as low as 1 ms but the performance variation is of interest as it adds unpredictability.

Can’t upload images as a new member to show the numbers.

Any help in understanding why this would be happening or did I get something misconfigured as I plan to take elixir and phoenix for my next project but this is a bit boggling why such varied performance. Any help or guidance over why this happens and how to fix this would be nice

The source code can be found on these links

1 Like
2

Here you can see most of the time is spent in heartbeat. I have refactored the code a bit to make it like pipeline (pardon me if i used the term incorrectly) where as now only the endpoints that need authenticatin are protected. So heartbeat is open and doesn’t have to go through an extra layer of processing yet being the slowest.

13%20AM
13%20AM805×348 45.2 KB

3

Refactoring each path in to its own plug.Router with using forward to pass on the request seems to have made the results more realistic. I think this works for plug+cowboy best. Open to comments over how it can be improved further and whats a better approach or convention.

38%20AM

10%20AM
10%20AM812×265 33.7 KB

4

Could you post the code showing how you did it? It is an interesting find.

5

original setup -> https://github.com/ahsandar/ultronex/blob/eb75c1d536affa351d982861bb4ebb9686a11203/lib/ultronex/server/router.ex

defmodule Ultronex.Server.Router do
  use Plug.Router
  use Plug.Debugger
  use NewRelic.Transaction

  require Logger

  alias Ultronex.Server.Heartbeat, as: Heartbeat
  alias Ultronex.Server.Track, as: Track
  alias Ultronex.Server.Stats, as: Stats
  alias Ultronex.Server.Error, as: Error

  plug(Plug.Logger, log: :debug)

  plug(Plug.Static, at: "/", from: :ultronex, only_matching: ["favicon"])

  plug(BasicAuth, use_config: {:ultronex, :basic_auth_config})

  plug(:match)

  plug(:dispatch)

  get "/heartbeat" do
    conn |> response_encoder(200, Poison.encode!(Heartbeat.rythm()))
  end

  get "/track" do
    conn |> response_encoder(200, Poison.encode!(Track.fwd()))
  end

  get "/stats" do
    conn |> response_encoder(200, Poison.encode!(Stats.total()))
  end

  match _ do
    conn |> response_encoder(404, Poison.encode!(Error.status_404()))
  end

  def response_encoder(conn, status, json) do
    conn
    |> put_resp_content_type("application/json")
    |> send_resp(status, json)
  end
end

current setup -> https://github.com/ahsandar/ultronex/blob/master/lib/ultronex/server/router.ex

defmodule Ultronex.Server.Router do
  use Plug.Router

  if Mix.env() == :dev do
    use Plug.Debugger
  end

  use Plug.ErrorHandler
  use NewRelic.Transaction

  require Logger

  alias Ultronex.Server.Controller.Error, as: Error

  @template_dir "app/view"

  plug(Plug.Logger, log: :debug)

  plug(Plug.Static, at: "/", from: :ultronex, only_matching: ["favicon", "stylesheets"])

  plug(:match)

  plug(:dispatch)

  forward("/ultronex/heartbeat", to: Ultronex.Server.Controller.Heartbeat)
  forward("/ultronex/track", to: Ultronex.Server.Controller.Track)
  forward("/ultronex/stats", to: Ultronex.Server.Controller.Stats)
  forward("/ultronex/slack", to: Ultronex.Server.Controller.Slack)

  match _ do
    conn |> render(404, "404.html", var: Error.status_404())
  end

  def response_encoder(conn, status, json) do
    conn
    |> put_resp_content_type("application/json")
    |> send_resp(status, json)
  end

  def render(conn, status, template, assigns \\ []) do
    body =
      @template_dir
      |> Path.join(template)
      |> String.replace_suffix(".html", ".html.eex")
      |> EEx.eval_file(assigns)

    send_resp(conn, status, body)
  end
end
6

Isn’t it expected that more time is spent in heartbeat since it is called very often even though each call is faster.

7

In terms of % yes heartbeat should likely be highest compared to other endpoints but not in response time as it does the least amount of work. The refactoring results are indicative of that understanding I have.