Troubleshooting - rails env has inconsistent load time

rails
performance

#1

Caveat: I tried for a minimal reproducible error case that exercised the rails env. A more complex use case is at the bottom and affects rspec.

- run: bin/rails r "puts 'foo'" takes a highly variable amount of time on CircleCI 2.0.

Local laptop result: 16s-21s consistently, including cold cache.

15 container results (3 builds @ 5 containers each):
22s
22s
24s
48s
50s
52s
53s
54s
54s
55s
56s
56s
57s
57s

No ruby/rails commands had been run in the container prior to this point. Gems were restored from cache and DB was restored from cache and loaded with pg_restore.

Note that I consider the 22s containers to be perfectly expected. The 50s+ containers are my worry (3xlocal!). We run a variety of builds across multiple containers and that potential 30 seconds added on to each rails related command we run gets onerous when it’s a per container cost.

=====

Related (probably) issue is that rspec taking a very long time for loading files:

From Circle logs:
Finished in 1 minute 31.1 seconds (files took **1 minute 47.31** seconds to load)

From local with same build command/set of files (spring disabled - no preloaders involved):
Finished in 1 minute 48.98 seconds (files took **16.06** seconds to load)

Note to Circle employees - happy to provide a link to private builds if it’d help.


#2

I did some deeper diving on this and would be curious for another opinion on some of my findings.

I verified that the slowdown is under config/environment.rb specifically where it loads
require File.expand_path('../application', __FILE__)

The boilerplate Bundler.require(*Rails.groups) line was responsible for the lion’s share (~40 seconds) of the load time, just to really drill in the point that this is an issue with being slow to load gems.

To get more granular data, I overrode require and collected timing data on loading application. I’ve grabbed the top 15 files that differed the most in load times:

image

As you can see, the difference is spread across many different gems at different layers of the stack, each one being slowed by a decent amount.

Why would gems be loading slower in one container vs. another? This is a run of the same job across 5 containers. Each runs the exact same load, no smart splitting going on while isolating this analysis.

Edit: just to be explicit, I am fully aware that higher level requires will aggregate the runtime of lower level requires and double count. I’m being very cautious in comparing apples to apples between runs.


#3

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.