tithonium: (Default)
Per Denise's request...

So, I have this Service. One of the endpoints loads basically /all the data/ in the database, constructs a big json object, and send it over the wire.
As of Thursday morning, it was taking 179 seconds to generate that json on my laptop.
As of Thursday evening, it was taking between 4 and 5 seconds.

In /theory/, if you just /look/ at the code, and look at how things were being loaded, you might think it should have been that fast to start with. I was doing everything right, right? Here's what we were doing (massively simplified and slightly redacted)...

class Plan
  scope :with_components, ->{
                              includes(
                                :calendars,
                                :calculators,
                                {
                                  schedules: :tiers,
                                  statements: [
                                    :approvals,
                                    :releases,
                                  ],
                                },
                              )
                            }
end

class ReportController
  def index                          
    plans = Plan.not_deleted.with_components.order(:id)
    render json: PlanReportDecorator.decorate_list(plans).as_json
  end
end


Simple enough. Load all the plans, include all the associations that we're going to use to generate the json, and generate the json. Boom.

Thing is, when you actually generate the json, inside those decorators (and there are several levels of decorators here, but only two matter), it was loading more data from the database. And it would do that, loading counts or sums or individual records, about a dozen queries each, for every statement (dozens), for every plan (hundreds).

All those individual queries, taking fractions of a second each, add up quickly.

But WHY is it making all these queries? We eager-loaded EVERYTHING WE NEED.


Ok, so. Yes, we did. And ActiveRecord is really pretty clever as far as it goes, but sometimes it doesn't go far enough.

Let's take a specific example. Statements can be approved? or not. They are approved if there exists an Approval that has not been revoked. Simple enough accessor:

def approved?
  approvals.not_unapproved.any?
end


And since we eager-loaded the approvals for all statements, this should be crazy fast, right?

Nope. Because we're accessing the not_unapproved scope on our approvals association, it makes a new db query. In theory, when the scope is known to be a simple where(), there's no /real/ reason that AR couldn't translate that into a .select{} on the loaded data, but it doesn't. So, new query. How do we fix that? If we /have/ all the approvals, don't load them again. Just look at what we have. If we do NOT have them, then do this scoped query, as it's the fastest option.

def approved?
  if @approved.nil?
    @approved = approvals.loaded? ? !!approvals.find(&:not_unapproved?) : approvals.not_unapproved.exists?
  end
  @approved
end


Memoize the result in @approved. If we haven't done so, it'll be nil. We can't use ||=, because that will still run when the value is false, we only want to set it when it's undetermined. Check if we have the association loaded. If so, use .find/.detect, using an accessor on the Approvals that implements the same logic as the scope. If we don't have them loaded, use the scoped query, and use .exists? instead of .any?, because it might possibly be ever so faintly faster. (on pg, it's SELECT 1 AS one FROM instead of SELECT count(*) FROM)

Changing things like that cut my load time from three minutes to about 50 seconds. The remainder was calculated sums on other associated records, displaying payment totals and such. It was causing three database queries per statement. Rather than loading those models each time, I added a json column to the database and stored the computed values at the time the statement is processed, and wrote a little caching wrapper I can tie to any method on the model to turn it into a write-once accessor.

def self.cached_detail_methods ; @cached_detail_methods ||= [] ; end
def self.cache_detail(*methods)
  methods = methods.flatten.map(&:to_s)
  methods.each do |method|
    class_eval <<-"EOF"
      def #{method}_with_detail_cache
        return self.detail_cache[#{method.inspect}] if self.detail_cache.has_key? #{method.inspect}
        self.detail_cache[#{method.inspect}] = #{method}_without_detail_cache
      end
    EOF
    alias_method_chain method, :detail_cache
  end
  @cached_detail_methods ||= []
  @cached_detail_methods |= methods
end



Then added a before_save callback that will clear and repopulate the cache anytime we modify the statement (generally when it's being reprocessed).

And that change got rid of the last 45 seconds. At this point, there are less than a dozen database queries, all at the very start, and the json generation itself takes hardly any time at all.

OMFG

Aug. 8th, 2007 10:49 pm
tithonium: (Giant Octopus)
I'm using Hobo for taskomat. Even running in production mode, loading my entire task list has been.. horrifyingly slow. Looking at the logs, I noticed, among other things, that it seemed to be loading the user record at least once for /every single task/. Ok, that's weird. The only place I find that it loads the user, it's caching it. So.. wtf?

Digging through the code, I find that, whenever I display an editor field, it checks to see if the current user can edit that field. the check to see if you can edit, eventually, deep down, /duplicates the object and tries to change the field on the duplicate/. Ok, that makes a certain amount of sense, sure. If you try to set the value and it throws an error, obviously you aren't allowed to edit.

Except.. it duplicates all the relationships that the object has... with other objects... like.. the user, that every single task is owned by. And because of the type of relationship, it loads the value. From the database. Every time.

I wrote my own editor functions. Which don't check edit permissions, since if you can see the entry, I already know you own it and can edit.

Before, under the best of circumstances - all classes loaded and cached, all dryml loaded, compiled, and cached, fastcgi mode - it took 45 seconds or more to load my task list.

Now, newly restarted, nothing loaded, nothing cached... 7 seconds. After caching... 3.

I may go back and rip out my dependancies on hobo, either copy back in the useful bits or roll my own, and see if I can get that down below 1s.



Yes, yes, hobo is pre-release, alpha, in development, yeah yeah. That doesn't mean I can't be dismayed at such poor design. <edit> called can_edit? before calling <editor>, which calls can_edit? before calling the type editor, some of which call can_edit? before doing anything. At least that stream only causes /one/ unnecessary db hit.

Profile

tithonium: (Default)
tithonium

February 2019

S M T W T F S
     12
3456789
10111213141516
17181920212223
2425262728  

Syndicate

RSS Atom

Expand Cut Tags

No cut tags