tj0

Profiling Phoenix Liveview

I upgraded LiveView from 0.15.4 → 0.17.7 in March. I recently noticed that the duration has doubled from 35 to 70 ms since March which is quite confusing to me.

However, this could be caused by a few things:

upgrading from 0.15.4 → 0.17.7
a server change, however, it was moved to a beefier server
preparing for localization and adding a great deal of gettext usage

I attempted to profile in several ways, but can’t seem to instrument the right place.

incendium uses eflame which uses :erlang.trace. Using master so that it works on newer phoenix, I added the decorator in various places:
- controller - works as expected. Elixir.Phoenix.Controller:render_and_send, Elixir.Plug.Conn:send_resp
- liveview mount - only shows the function
- liveview handle_params - only shows the function
- render - does not work - gives only :eflame.stop_trace, :eflame_trace, :erts_internal_trace
- router scope - does not work
- in app/lib/app_web.ex - decorating controller or view doesn’t work.
I tried Profiler which uses :fprof under the hood and couldn’t get a useful trace either.

Anyone have ideas?

5 comments

/phoenix #troubleshooting #liveview #profiling

1 1327 5

2022-07-09 20:16:24 UTC

Most Liked

chrismccord

Creator of Phoenix

70ms is the latency time experienced by the browser, or the time on this server from your existing profiling? Does your app hit the DB? If you moved servers, the network could explain the difference, but we have too little information to say where the time is spent. It’s very unlikely to be anything LV 0.15 vs 0.17 related.

Post #2

akoutmos

Author of Build a Weather Station with Elixir and Nerves

Not sure what your setup is with your application…but you may want to set up PromEx and enable the LiveView plugin (prom_ex/lib/prom_ex/plugins/phoenix_live_view.ex at master · akoutmos/prom_ex · GitHub). You’ll get some good insight into the time spent in the mount and handle_event callbacks.

If you can deploy Prometheus and Grafana, it may be worth while rolling back (if you can) and collecting some metrics under load and then redeploying and seeing if the behavior changes (under similar load). PromEx also has an Ecto plugin and that can also be useful so you can ensure that your DB interactions are not the problem.

Post #4

Last Post!

tj0

Curious if anyone has any insight into this behaviour.

On mount:

13:06:47.025 request_id=FwA9R6sVowyxKmQAAFhC [info] [{"duration", 1111.837098}, {"event", "basic_data"}, {"status", 200}]
13:06:47.038 request_id=FwA9R6sVowyxKmQAAFhC [info] [{"duration", 1185.018558}, {"event", "handle_params"}, {"status", 200}]
13:06:47.218 request_id=FwA9R6sVowyxKmQAAFhC [info] [duration: 1377.664, status: 200, params: %{}, path: "/", method: "GET"]

Websocket connect/update (basic_data has cached elements)

13:06:47.925 [info] [{"duration", 292.594243}, {"event", "basic_data"}, {"status", 200}]
13:06:47.930 [info] [{"duration", 377.007019}, {"event", "handle_params"}, {"status", 200}]

After connection, doing a full page update via phx-click (no caching of basic_data)

13:07:17.512 [info] [{"duration", 8.274046}, {"event", "basic_data"}, {"status", 200}]
13:07:17.512 [info] [{"duration", 13.654211}, {"event", "click event"}, {"params", %{"bla"}}, {"status", 200}]

I’m not sure why the performance is so different after the websocket is connected? The initial connection is 100x slower for basic_data. For reference, basic_data is a pure function but the input to it could be cached.

Also, is in dev, not prod, so I’m not sure if that makes a difference.

I can’t explain a difference of 1000ms to 9ms easily for the same function being run with almost identical inputs (to make sure it isn’t cached).

Anyone have any ideas?

Post #6