Recently when investigating our application metrics we’ve noticed that one of our API endpoints is surprisingly and unexplainably slow. At first, we brushed it off as this particular endpoint returns one of the biggest JSON objects in our system but after comparing it with similar ones the difference became even more apparent so we decided to stop by and investigate.
The first thing we did is fire up rack-mini-profiler to check what is happening in that API call. The flamegraph quickly pointed us to one particular method that seemed to be extremely slow for its simple role. The method in question looked innocent enough:
def time_intervals(start_time, end_time, step)
(start_time.to_i..end_time.to_i).step(step.minutes).map { |t|
Time.zone.at(t).strftime('%H:%M')
}
end
but after running it in Rails console it turns out it takes a whopping 400ms (!) just do generate a simple array of strings! Can you already spot the problem?
Digging a bit further revealed the reason: this code did not work like the person implementing it expected. The step variable, in this case, is an integer and when calling step.minutes what we’re getting back is not also an Integer (like one could think) but rather an instance of ActiveSupport::Duration. Considering that we turned both start and end time to integers, this means that the loop on every iteration was adding a massive amount of seconds to a duration instance:
> (start_time.to_i..end_time.to_i).step(30.minutes).to_a => [1622023200, 30 minutes and 1622023200 seconds, 30 minutes and 1622025000 seconds, 30 minutes and 1622026800 seconds, 30 minutes and 1622028600 seconds, 30 minutes and 1622030400 seconds, 30 minutes and 1622032200 seconds, 30 minutes and 1622034000 seconds, 30 minutes and 1622035800 seconds, 30 minutes and 1622037600 seconds, 30 minutes and 1622039400 seconds, 30 minutes and 1622041200 seconds, 30 minutes and 1622043000 seconds, 30 minutes and 1622044800 seconds, 30 minutes and 1622046600 seconds, 30 minutes and 1622048400 seconds]
This in turn is slow because the class in question does a bunch of calculations internally and returns a new instance every time you use + on it.
Considering that in this particular place we do not care about all the features of ActiveSupport::Duration (since the original intent was to use integers in the first place), the fix is very simple:
def time_intervals(start_time, end_time, step)
(start_time.to_i..end_time.to_i).step(step.minutes.to_i).map { |t|
Time.zone.at(t).strftime('%H:%M')
}
end
This very simple thing has sped up this code over 17000x (!)
> www.de.docker.test(main)> Benchmark.ms { (start_time.to_i..end_time.to_i).step(30.minutes).map { |t| t } }
=> 575.404899995192
> www.de.docker.test(main)> Benchmark.ms { (start_time.to_i..end_time.to_i).step(30.minutes.to_i).map { |t| t } }
=> 0.03330000618007034
while keeping the same results we wanted:
> (start_time.to_i..end_time.to_i).step(30.minutes).map { |t| Time.zone.at(t).strftime('%H:%M') }
=> ["12:00", "12:30", "13:00", "13:30", "14:00", "14:30", "15:00", "15:30", "16:00", "16:30", "17:00", "17:30", "18:00", "18:30", "19:00", "19:30"]
> (start_time.to_i..end_time.to_i).step(30.minutes.to_i).map { |t| Time.zone.at(t).strftime('%H:%M') }
=> ["12:00", "12:30", "13:00", "13:30", "14:00", "14:30", "15:00", "15:30", "16:00", "16:30", "17:00", "17:30", "18:00", "18:30", "19:00", "19:30"]
The lesson learned here is that you should take a careful look at your metrics and always second guess the outliers. Sometimes code that seems like it may have good reasons to be slow is only slow because of a simple mistake and fixing that mistake may benefit your application a lot in the long run.
And of course – don’t forget to benchmark, benchmark, benchmark 😉
