Investigating the Performance of a Problematic Rails API Endpoint
Tags: rails, ruby
Published: 2019-08-31 12:42:48

It recently came to my attention that one of our API endpoints was hogging a lot of resources and taking over 3 seconds to complete per request. I was able to cut average memory usage from 85mb to 7mb and average request duration from 3000ms to 150ms. I'm going to detail that process in this post. 

![latency graph before / after deployment](https://thepracticaldev.s3.amazonaws.com/i/s696d3znldxme6fcb241.png)

Let's get started by installing the tools we're going to use.

# Set up bullet
[bullet](https://github.com/flyerhzm/bullet) is a gem that helps you identify and correct N+1 queries.

We'll add this to our Gemfile:

```ruby
group :development do
  gem 'bullet'
end
```

And this to our `config/application.rb`:

```ruby
  config.after_initialize do
    Bullet.enable = true
    Bullet.rails_logger = true
  end
```


# Set up rack-mini-profiler

[rack-mini-profiler](https://github.com/MiniProfiler/rack-mini-profiler) is a middleware that provides database and memory profiling. Let's get that set up so we can get a closer look into what's causing our issues.

We need to add `rack-mini-profiler` and `memory_profiler` to our Gemfile **below the database gem**, and run `bundle` to install it.

```ruby
gem 'pg'
gem 'rack-mini-profiler'
gem 'memory_profiler'
```



Next, we'll add this to `config/initializers/mini_profiler.rb`:

```ruby
Rack::MiniProfiler.config.authorization_mode = :allow_all
```

When rack-mini-profiler is enabled, it saves the profiler output from previous requests and injects a badge into the next HTML page that is loaded. But we're in an API only app, so in order to see the badge, we're going to have to serve an HTML page.

Note: If you're planning on checking this code into your repo, you'll want to add some sort of [authorization around `authorize_request`](https://github.com/MiniProfiler/rack-mini-profiler#access-control-in-non-development-environments). 

Here's my `PerformanceTestsController`:

```ruby
class PerformanceTestsController < ActionController::Base
  before_action do
    Rack::MiniProfiler.authorize_request
  end

  def index
  end
end
```

`app/views/performance_tests/index.html`:

```
<body></body>
```

`config/routes.rb`:

```ruby
  get '/performance_tests', to: 'performance_tests#index'
```

Once you have that set up, if you open `/performance_tests` in your browser, you should be seeing this badge in the top left.

![Alt Text](https://thepracticaldev.s3.amazonaws.com/i/9aygp42wje3h2whm7w3g.png)

# Recreate the environment
When you're investigating a production performance problem, you want the environment you test in to be as similar to the production environment as possible. In Rails' development mode, class caching is disabled, so the time it takes to complete requests can vary wildly. I ran these tests in production mode on my local machine with a similar dataset to the one found in the prod db.

# Isolate

We use Ember as our front end framework, which can make several calls to the API on page load. I wanted to isolate the problematic API call so I could repeat it as quickly as possible as many times as necessary. The endpoint requires an authentication header, so I just used Chrome's Copy as cURL function to grab everything I needed in one command.

![Copy as cURL](https://thepracticaldev.s3.amazonaws.com/i/t58p4g7uf14rs2qsq0y2.png)

# Benchmark

Now that we have our environment and tools set up, it's time to get our hands dirty and try to figure out what's actually going on. The endpoint in question is `UsersController#index`:

```ruby
def index
  users = User.joins(:roles).where(roles: { title: params[:roles] })          
 
  respond_with users, include: %w[roles groups]
end
```

Before we start making changes, the first thing we're going to want to do is to get a benchmark control with the code in its current state. That way we can ensure the changes we're going to make are actually improvements.

rack-mini-profiler has [several options](https://github.com/MiniProfiler/rack-mini-profiler#flamegraphs) available to pass in through the `pp=` query parameter, but the two we're going to be using are `pp=profile-memory` and `pp=enable`.

The first request always seems to have higher resource usage than subsequent requests, so I always fire the request twice and take the benchmarks from the second request.

Here we go, let's get our memory control:


```
# All Users (`/users?pp=profile-memory`)
Total allocated: 60047355 bytes (744989 objects)
Total retained:  1356020 bytes (8851 objects)

```

In addition to memory usage, we're going to want to check the rack-mini-profiler badge that displays info on response timings and SQL queries. We do this by using the `pp=enable` query parameter then opening `/performance_tests` as described in the rack-mini-profiler setup section above.



```
# All Users (`/users?pp=enable`)
Total Duration: 7795ms
SQL Duration: 373ms
SQL Queries: 1139

```

😱

This is bad! Let's fix it.

# Eliminating N+1 queries

The amount of SQL queries being executed per request suggests that we've got some N+1 issues going on, so let's take a look at that first. We'll make one change and then run the benchmarks again.

Let's change the `joins(:roles)` to `includes(:roles, :groups)` so our roles and groups will be eager loaded.

```ruby
def index
  users = User.includes(:roles, :groups).where(roles: { title: params[:roles] })
 
  respond_with users, include: %w[roles groups]
end
``` 

Here are the benchmarks with `includes`:

```
Total allocated: 436705757 bytes (4119179 objects)
Total retained:  4646110 bytes (33480 objects)

Total Duration: 7209ms
SQL Duration: 355ms
SQL Queries: 1130
```

Eager loading all of those roles actually caused the memory usage to increase 7x! The duration and queries decreased a bit, but this is obviously not the fix we were hoping for.

Let's use the rack-mini-profiler HTML badge to see the queries that are being executed.

![rack-mini-profiler](https://thepracticaldev.s3.amazonaws.com/i/3aracu0rx0m71mabf2pz.png)

When I expanded the `1130 sql` link, I saw a lot of entries similar to this:

```
app/serializers/user_serializer.rb:72:in `employee_id'
app/controllers/v1/users_controller.rb:53:in `index'
app/controllers/application_controller.rb:48:in `set_current_attrs'
SELECT  "employees".* FROM "employees" WHERE "employees"."user_id" = $1 LIMIT $2; 
``` 

At this point, I think the issue lies mainly within the serializer, so let's take a look at what's going on in there.

```ruby
class UserSerializer < ActiveModel::Serializer
  attributes :id,
             :email,
             :first_name,
             :last_name,
             :last_login_at,
             :employee_id

  has_one :employee
  has_many :assignments
  has_many :direct_roles
  has_many :roles, through: :assignments
  has_many :group_assignments
  has_many :groups, through: :group_assignments

  def employee_id
    object.employee&.id
  end
end
```

Now we're on to something! Every time a `User` object is serialized, we're issuing queries for each of the associations listed here. We can try to eager load each of these associations with `includes`, but what if we don't need these associations for the `index` action at all?

Real quick, let's check out the `show` action next to `index` in `UsersController`.

```ruby
  def index
    users = User.includes(:roles, :groups).where(roles: { title: params[:roles] })

    respond_with users, include: %w[roles groups]
  end

  def show
    respond_with @user, include: %i[roles roles_tags assignments groups group_assignments groups.roles]
  end

```

`show` is serialized via the same `UserSerializer` class. It's starting to look like those associations were added to the serializer so they would be included on the `show` endpoint.

For now, I'm only making optimizations to `index`, so `show` and any other actions using `UserSerializer` need to be unaffected. I think the path forward is to create an `index`-specific serializer with a sparse fieldset -- we'll include only the data we need in the response.

```ruby
# app/controllers/users_controller.rb
def index
  users = User.includes(:roles, :groups).where(roles: { title: params[:roles] })

  respond_with users, include: [:roles, :groups], each_serializer: Users::Index::UserSerializer
end

# app/serializers/users/index/user_serializer.rb
class Users::Index::UserSerializer < ActiveModel::Serializer
  attributes :id,
             :email,
             :first_name,
             :last_name,
             :last_login_at,
             :employee_id

  has_many :roles, through: :assignments
  has_many :groups, through: :group_assignments

  def employee_id
    object.employee&.id
  end
end
```

I removed all associations except the ones we want to side load, `roles` and `groups`. Let's check our numbers.

```
Total allocated: 242932074 bytes (2392253 objects)
Total retained:  2511484 bytes (18008 objects)

Total Duration: 3650ms
SQL Duration: 202ms
SQL Queries: 571
```

Our first big improvement! At this point, I checked where this endpoint was being called in our frontend apps and verified that we didn't need the associations that were removed.

But, 571 queries. Let's check the Bullet output to the Rails log to see if it's identified any N+1 queries.

```
USE eager loading detected
  User => [:employee]
  Add to your finder: :includes => [:employee]
Call stack
  /Users/mculp/sf/cs/app/serializers/users/index/user_serializer.rb:66:in `employee_id'

USE eager loading detected
  User => [:group_assignments]
  Add to your finder: :includes => [:group_assignments]
Call stack
  /Users/mculp/sf/cs/app/models/user.rb:229:in `roles'

USE eager loading detected
  User => [:assignments]
  Add to your finder: :includes => [:assignments]
Call stack
  /Users/mculp/sf/cs/app/controllers/v1/users_controller.rb:49:in `index'
```

Yep! Let's eager load `employee`, `group_assignments`, and `assignments`.

```ruby
  def index
    users = User
              .includes(:roles, :groups, :employee, :group_assignments, :assignments)
              .where(roles: { title: params[:roles] })

    respond_with users, each_serializer: Users::Index::UserSerializer, include: [:roles, :groups]
  end
```

Numbers:

```
Total allocated: 80137296 bytes (825840 objects)
Total retained:  761444 bytes (5371 objects)

Total Duration: 1580ms
SQL Duration: 58ms
SQL Queries: 124
```

Another big improvement. Bullet is no longer screaming at us in the Rails log.

After checking rack-mini-profiler, I see that we still have an N+1:

```
app/models/user.rb:476:in `last_login_at'
app/controllers/v1/users_controller.rb:49:in `index'
app/controllers/application_controller.rb:48:in `set_current_attrs'
SELECT  "authentication_tokens".* FROM "authentication_tokens" WHERE "authentication_tokens"."user_id" = $1 AND "authentication_tokens"."on_behalf" = $2 ORDER BY "authentication_tokens"."id" DESC LIMIT $3;
```

Here's the code for `last_login_at`:

```ruby
  def last_login_at
    token = authentication_tokens.where(on_behalf: false).last
    token&.last_used_at
  end
```

This one is trickier to fix. We can't simply eager load `authentication_tokens` because this method is issuing a query each time it's called.

However, what we can do is create a new scoped association and eager load it.

```ruby
  # app/models/user.rb
  has_one :last_login_authentication_token,
    -> { where(on_behalf: false) },
    class_name: 'AuthenticationToken'

  def last_login_at
    last_login_authentication_token&.last_used_at
  end
```

```ruby
  # app/controllers/users_controller.rb
  def index
    eager_load_associations = [
      :roles, :groups, :employee, :group_assignments,
      :assignments, :last_login_authentication_token
    ]

    users = User.includes(eager_load_associations).where(roles: { title: params[:roles] })

    respond_with users, each_serializer: Users::Index::UserSerializer, include: [:roles, :groups]
  end

```

This should take care of our last N+1 issue. Let's make sure:


```
Total allocated: 69663419 bytes (872929 objects)
Total retained:  302956 bytes (1818 objects)

Total Duration: 1250ms
SQL Duration: 26ms
SQL Queries: 12
```

It's looking good from a SQL standpoint! The rest of the time is being spent instantiating and serializing objects.

Let's take a look at what we can do to make some improvements on that front.

# Further Optimizations

### fast_jsonapi

[`fast_jsonapi`](https://github.com/Netflix/fast_jsonapi) is a gem by the engineering team at Netflix that promises 25x faster serialization than `ActiveModel::Serializers`.

> We want to ensure that with every change on this library, serialization time is at least 25 times faster than Active Model Serializers on up to current benchmark of 1000 records.

That sounds too good to be true, but it can't hurt to try it!

```ruby
  # app/controllers/users_controller.rb
  def index
    eager_load_associations = [
      :roles, :groups, :employee, :group_assignments,
      :assignments, :last_login_authentication_token
    ]

    users = User.includes(eager_load_associations).where(roles: { title: params[:roles] })

    respond_with users, 
      each_serializer: Fast::Users::Index::UserSerializer,
      include: [:roles, :groups]
  end
```

```ruby
# app/serializers/fast/users/index/user_serializer.rb
class Fast::Users::Index::UserSerializer
  include FastJsonapi::ObjectSerializer

  attributes :id,
             :email,
             :first_name,
             :last_name,
             :employee_id,
             :last_login_at

  has_many :roles, through: :assignments, serializer: Fast::Users::Index::RoleSerializer
  has_many :groups, through: :group_assignments, serializer: Fast::Users::Index::GroupSerializer

  attribute :employee_id do |object|
    object.employee&.id
  end
end
```

```ruby
# app/serializers/fast/users/index/role_serializer.rb
class Fast::Users::Index::RoleSerializer
  include FastJsonapi::ObjectSerializer

  attributes :id, :title, :description
end
```

```ruby
# app/serializers/fast/users/index/group_serializer.rb
class Fast::Users::Index::GroupSerializer
  include FastJsonapi::ObjectSerializer

  attributes :title, :description, :archived
end
```

Numbers:

```
Total allocated: 54130985 bytes (698850 objects)
Total retained:  189166 bytes (935 objects)

Total Duration: 707ms
SQL Duration: 21ms
SQL Queries: 6
```

Well, it's not 25x, but that's still a pretty impressive improvement. We're gonna roll with it.

### Caching

`fast_jsonapi` also has built in object caching, which uses Rails' `cache_key` under the hood to do cache invalidation. I think it'd work well for our use case here, so let's try it.

We're using Redis as the cache store, which was set up in `config/environments/production.rb`:

```ruby
  if ENV['REDIS_URL']
    config.cache_store = :redis_store, ENV['REDIS_URL'], { expires_in: 12.hours }
  end
```

Now all we have to do is add this `cache_options` line to our serializer to cache each `User` object:

```ruby
# app/serializers/fast/users/index/user_serializer.rb
class Fast::Users::Index::UserSerializer
  include FastJsonapi::ObjectSerializer

  cache_options enabled: true, cache_length: 12.hours

  attributes :id,
             :email,
             :first_name,
             :last_name,
             :employee_id,
             :last_login_at

  has_many :roles, through: :assignments, serializer: Fast::Users::Index::RoleSerializer
  has_many :groups, through: :group_assignments, serializer: Fast::Users::Index::GroupSerializer

  attribute :employee_id do |object|
    object.employee&.id
  end
end
```

Now, let's run the numbers.

```
Total allocated: 10239567 bytes (92500 objects)
Total retained:  413751 bytes (2609 objects)

Total Duration: 165ms
SQL Duration: 17ms
SQL Queries: 6
```

🥳🎉