The task every developer fears “Hey, I sometimes get a timeout when I want to see the last gazillion days of activity in the dashboard. What gives?”

Nikon GP-1 GPS Unit Test

Nikon GP-1 GPS Unit Test (Photo credit: AndyRamdin / ND-Photo.nl)

This problem started happening for a project I work on a few months ago. Through a lucky sequence of events I was able to push the problem back a couple of months … mostly just a beefier VPS on amazon with a bit more memory.

Yesterday I finally cleaned up everything else from pivotal tracker and was left with only that one dreaded item. That … slowness thing. Have you ever tried speeding up the execution of something when 80% of the codebase isn’t yours?

Context! I need context!

Let me give you a bit of context for what’s going on:

  • the project lets customers have many users
  • users enter events when they do stuff
  • the entries can be checked in a dashboard
  • there is a date-range picker to see more than just today’s events

And that’s where it all gets ever so slightly weird. When you choose anything other than today things start becoming increasingly slow and sometimes certain browsers decide that it’s just too slow and timeout.

No, it isn’t slow enough to cause the 30 second socket timeout.

No, caching wouldn’t really benefit this activity either.

A simple benchmark

In light of what I’ve learned about unit testing being for lazy people last week, I decided to set up a unit test that is actually an integration test and most likely isn’t either of those since it’s some sort of benchmark.

But it goes in django‘s testing framework, the python module behind that is called unittest, so I’m calling it a unit test.

    def test_date_range(self):
        t1 = datetime.now()
        response = self.c.post('/accounts/dashboard/',
                               {'dateFrom': (datetime.now()-timedelta(days=356)).strftime("%m/%d/%Y")})
 
        t2 = datetime.now()
 
        self.assert_((t2-t1).seconds < 2, "Too slow")

See, simple test. All it needed was exporting the whole production database into a fixture so django loads it up every time the test is run and then cleans up after itself.

The results are abominable! To return a dashboard with 250 rows of entries, this django app takes between 5 and 8 seconds. Clearly way way too much time!

The fix?

Indexes! Yes, adding an index where appropriate should speed things up immensely. Right?

U.S. Marine Corps SSgt. R. McIntosh, an engine...

Image via Wikipedia

Nope.

Creating indexes didn’t even put a dint in that benchmark. There was more fluctuation from the effect of memory pages on mysql’s performance. And anyway … what was I thinking really, indexes helping queries with less than 1000 rows of results? Don’t be silly Swizec.

Now what?

Added a bunch of “spent time” prints in the code and realized that even though it takes less than a second to make everything ready it then takes five seconds to render the template.

Wait what! Five seconds to render the template!?

Oh right … django’s querysets are lazy. That would probably explain it. The template is where those querysets get evaluated, they ping the database and that’s the explanation I’m looking for. It must be!

Except it wasn’t. Due to the way the view is written all the querysets get iterated over before the template is rendered. And they all have that magical select_related so all the fields getting accessed inside the template can’t possibly be triggering more db queries can it?

Well … no.

The main module has a function added that returns the latest related object. This function, correctly, only gets called once per rendering for every model.

But the function returns a queryset.

That queryset is lazy and it gets evaluated every single time that related object is used, which turns out to be 30 times per displayed row. But can 30 queries explain the slowness in rendering? Or should it be even slower if my theory was in fact correct?

I don’t know, but right now I’m working on a fix to make sure that object is solidified and is not a lazy queryset before it gets pushed to the template. If it works, great … otherwise I have no idea what I’ll try next.

user.get_profile() also gets called awfully often. Wonder how that baby works …

Enhanced by Zemanta

Learned something new? 💌

Join 8,400+ people becoming better Frontend Engineers!

Here's the deal: leave your email and I'll send you an Interactive ES6 Cheatsheet 📖 right away.  After that you'll get an email once a week with my writings about React, JavaScript,  and life as an engineer.


You should follow me on twitter, here.