Unexpectedly poor performance

[liamwhite]

I came here from Coherence as I am a novice in Elixir, new to Phoenix, and I was looking for a more-or-less prebuilt authentication solution for my app -- preferably one that would essentially behave like Devise in Rails. My test app has nothing configured on it except for Postgres and is running in a Vagrant VM.

The homepage of my app is blank and renders in about 0.2 milliseconds. In addition, previous authentication solutions I attempted to roll into my app (admittedly badly, using Guardian) only performed marginally worse in this respect (about 0.8 milliseconds to request /sessions/new and /registrations/new).

However, after adding pow as per the README directions, and setting up the user model with the extensions PowResetPassword, PowEmailConfirmation, and PowPersistentSession, I found that the time needed to render /session/new had ballooned to a quite comparatively hefty 25ms in my VM, even while running in production mode. For the record, even Devise with all plugins enabled does better than this with /sessions/new clocking in at around 8ms.

I tried profiling my app with fprof and did not find anything useful. I tried using the Mnesia cache instead of the ETS cache, which did not make a difference. I profiled the server using tcpdump and confirmed that it was not communicating with the database during the request. I also tried deleting all the view code for the pages to see if there was something in the view code that was causing the poor performance there, and that did not make a difference (as expected).

What I did find is that with this configuration,

config :myapp, :pow,
  # ...
  extensions: [PowResetPassword, PowEmailConfirmation, PowPersistentSession],
  controller_callbacks: Pow.Extension.Phoenix.ControllerCallbacks,
  # ...

the controller_callbacks used have a substantial impact on the render time. By commenting this line the render time reduced to around 8ms on average. However, this is still unexpectedly slow, and obviously this breaks those extensions.

What can I do to bring this on par with the performance of a hand-rolled authentication system?

[danschultzer]

Interesting. I haven't looked at all at performance so there must definitely be room for improvement. I'm pretty sure there isn't anything you can do to improve performance outside digging into Pow and refactoring whatever is slowing down the response.

I'm swamped atm, but will look at this as soon as I've some time available. Please do post any more details if you're going to dig further into it.

[liamwhite]

This method here seems to be using metaprogramming to generate a list of matching extension modules on the fly, every request, instead of caching them somehow.

Doing this instead

  defp controller_callbacks_modules(config) do
    [PowEmailConfirmation.Phoenix.ControllerCallbacks,
     PowPersistentSession.Phoenix.ControllerCallbacks]

    #Extension.Config.discover_modules(config, ["Phoenix", "ControllerCallbacks"])
  end

seems to have the same effect on performance as removing the controller_callbacks line from the config, but does not seem to break anything.

[danschultzer]

I did some light tests to verify myself and it definitely shouldn't be as slow as you experience it. The default Phoenix index controller should range around half of what the Pow session controller is. Do you have a sample repo that I can try out, or can you clarify how you test this?

Standard Phoenix setup with Pow on my machine built with distillery, with first load and two subsequent loads:

# Default phoenix index page
16:10:46.386 request_id=FZnGLdU7vPjffz8AAAGG [info] GET /
16:10:46.389 request_id=FZnGLdU7vPjffz8AAAGG [info] Sent 200 in 2ms
16:10:47.372 request_id=FZnGLg_5A_DJQrEAAAGm [info] GET /
16:10:47.372 request_id=FZnGLg_5A_DJQrEAAAGm [info] Sent 200 in 339µs
16:10:49.701 request_id=FZnGLprLnsAYqAoAAAHG [info] GET /
16:10:49.701 request_id=FZnGLprLnsAYqAoAAAHG [info] Sent 200 in 260µs

# Session controller
16:10:13.539 request_id=FZnGJi9FeODffz8AAAEB [info] Sent 200 in 2ms
16:10:14.741 request_id=FZnGJncRO6DJQrEAAAEh [info] GET /session/new
16:10:14.742 request_id=FZnGJncRO6DJQrEAAAEh [info] Sent 200 in 571µs
16:10:24.340 request_id=FZnGKLM0q7CwZyYAAAAI [info] GET /session/new
16:10:24.341 request_id=FZnGKLM0q7CwZyYAAAAI [info] Sent 200 in 516µs

I tried with both controller callbacks on and off and there was virtually no difference.

[danschultzer]

Ok, running this with just MIX_ENV=prod mix phx.server definitely produces a significant difference (10x+):

16:23:00.253 request_id=FZnG2LMLfFhQnX0AAAAE [info] GET /
16:23:00.284 request_id=FZnG2LMLfFhQnX0AAAAE [info] Sent 200 in 31ms
16:23:02.060 request_id=FZnG2R7QK3ggF7IAAABB [info] GET /
16:23:02.060 request_id=FZnG2R7QK3ggF7IAAABB [info] Sent 200 in 263µs
16:23:03.908 request_id=FZnG2Yz5LIAk9y0AAABh [info] GET /
16:23:03.908 request_id=FZnG2Yz5LIAk9y0AAABh [info] Sent 200 in 322µs

# Without controller callbacks
16:24:41.390 request_id=FZnG8D9FGihQnX0AAASk [info] GET /session/new
16:24:41.435 request_id=FZnG8D9FGihQnX0AAASk [info] Sent 200 in 45ms
16:24:43.770 request_id=FZnG8M0teKggF7IAAATE [info] GET /session/new
16:24:43.770 request_id=FZnG8M0teKggF7IAAATE [info] Sent 200 in 507µs
16:24:44.617 request_id=FZnG8P-1TuAk9y0AAATk [info] GET /session/new
16:24:44.618 request_id=FZnG8P-1TuAk9y0AAATk [info] Sent 200 in 614µs

# With controller callbacks
16:22:41.724 request_id=FZnG1GKYbJ1QnX0AAADD [info] GET /session/new
16:22:41.768 request_id=FZnG1GKYbJ1QnX0AAADD [info] Sent 200 in 44ms
16:22:43.733 request_id=FZnG1NpytfIgF7IAAADj [info] GET /session/new
16:22:43.738 request_id=FZnG1NpytfIgF7IAAADj [info] Sent 200 in 4ms
16:22:45.325 request_id=FZnG1TlXjuMk9y0AAAED [info] GET /session/new
16:22:45.331 request_id=FZnG1TlXjuMk9y0AAAED [info] Sent 200 in 5ms

I'll have to dig deeper into this.

[liamwhite]

I have some custom validations in my User changeset.

  def changeset(user_or_changeset, attrs) do
    user_or_changeset
    #|> pow_changeset(attrs)
    #|> pow_extension_changeset(attrs)
    |> cast(attrs, [:name])
    #|> validate_required([:name])
    #|> validate_length(:name, max: 50)
    #|> unique_constraint(:name)
    #|> unique_constraint(:email)
  end

Doing this reduced the average time down to around 1ms. (I don't see why validations are being checked on a model when there is no model)

This was my guess based on https://github.com/danschultzer/pow/blob/b302607a7a8748bc86f16a6cd94d364a23f9aec9/lib/pow/phoenix/controllers/session_controller.ex#L18-L22

[danschultzer]

I suspect it has to do with Pow.Extension.Config.discover_modules/2: https://github.com/danschultzer/pow/blob/b302607a7a8748bc86f16a6cd94d364a23f9aec9/lib/pow/extension/config.ex#L21-L27

If the app is being ran with mix I'm pretty sure Code.ensure_compiled?/1 will be much slower since it halts until the module is loaded and compiled. Mix does some things to ensure that modules can be dynamically reloaded.

[danschultzer]

Doing this reduced the average time down to around 1ms. (I don't see why validations are being checked on a model when there is no model)

Yeah, the changeset method always runs when rendering the :new action. This is also the default in Phoenix templates. A changeset is needed for the form.

[liamwhite]

  use Pow.Extension.Ecto.Schema,
    extensions: [PowResetPassword, PowEmailConfirmation, PowPersistentSession]

  # ...

  def changeset(user_or_changeset, attrs) do
    user_or_changeset
    |> pow_changeset(attrs)
    |> pow_extension_changeset(attrs)
    |> cast(attrs, [:name])
    #|> validate_required([:name])
    #|> validate_length(:name, max: 50)
    #|> unique_constraint(:name)
    #|> unique_constraint(:email)
  end

Of this, some crude benchmarking shows that most of the time is spent in pow_extension_changeset, and the second most time is spent in pow_changeset. These methods are complicated and I have not been having much luck prying into them.

[danschultzer]

Try change the Pow.Extension.Config.discover_modules/2 method to this:

  def discover_modules(config, module_list) do
    config
    |> extensions()
    |> Enum.map(&Module.concat([&1] ++ module_list))
    |> Enum.filter(fn module ->
      case :code.is_loaded(module) do
        false -> false
        _any -> true
      end
    end)
  end

After I did that I get near identical response time as when controller callbacks are not enabled.

Do you run the app with mix? You should see pretty much no slowdown if you make a release build of your app with distillery. I think running dynamically with mix will always be slower than compiling a release.

[liamwhite]

Thanks, that seems to have fixed it.

Yes, I am running the app with mix right now, as I have not yet deployed it.

[danschultzer]

Ok, so you shouldn't see any significant slow down with a release. It should definitely be much faster than devise, and more or less the same speed as guardian.

You should be able to test this by making a release and run it locally. The reason it's so slow is the extension module lookup and running it with mix. I believe that modules can be loaded dynamically in mix so that's why it's so slow on each request since it waits for the module to be (re)loaded. That does not happen with the release version.

The Code.ensure_loaded/1 is the better way (albeit slower) to ensure the modules are ready for use, so I'm not sure if there's any way to improve response time when running the app with mix.

Edit: The only way I can think of is to record all existing modules in an ETS table, or to use a compiled list of available modules. Not sure if it's worth the effort though since I don't believe it would make a difference for release version.

[liamwhite]

After doing a distillery release I can confirm that both methods produce equivalently-performing code and the performance is more or less optimal.

00:39:28.312 [info] Running MyAppWeb.Endpoint with cowboy 2.6.3 at 0.0.0.0:4000 (http)
00:39:28.315 [info] Access MyAppWeb.Endpoint at http://localhost:4000
00:36:49.112 request_id=FZnK39-yoR8_bCkAAADx [info] GET /registration/new
00:36:49.115 request_id=FZnK39-yoR8_bCkAAADx [info] Sent 200 in 3ms
00:36:50.255 request_id=FZnK4CPTqpQ1CWgAAAEB [info] GET /registration/new
00:36:50.256 request_id=FZnK4CPTqpQ1CWgAAAEB [info] Sent 200 in 635µs
00:36:53.413 request_id=FZnK4OAKaNvPLKIAAAAC [info] GET /registration/new
00:36:53.414 request_id=FZnK4OAKaNvPLKIAAAAC [info] Sent 200 in 992µs

[danschultzer]

👍 I'm pretty sure there's still some performance improvements that can be done but doubt it would cut more than 0.1-0.2 ms of the response time 😄