Performance profiling on Google App Engine

My GAE application for table tennis players does not perform very well. Although some parts are exceptionally fast, getting the results of a players team matches, is quite slow. I can understand it’s slower than searching for a player, but over ten times as slow? No. Sorry. I don’t understand.

Profiling, first attempt

It’s time to find out what’s going on. So let’s turn profiling on! There’s a FAQ entry on how to do that. After adding the code and running it on the development server, I was a bit puzzled. The majority of the time is spent on eval() functions. Digging through the output a bit, made me realize profiling should not be executed on the development server.

    1873187 function calls (1871823 primitive calls) in 10.741 CPU seconds

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    15174    0.763    0.000    2.506    0.000 datastore_types.py:175(from_path)
     7587    0.675    0.000    4.605    0.001 {eval}
    15174    0.610    0.000    1.386    0.000 datastore_types.py:422(__repr__)
     7609    0.530    0.000    1.308    0.000 datastore_types.py:442(__cmp__)

It looks like querying the datastore is done by creating expressions using repr() and subsequent calls to eval() to check the query conditions…

Profiling, 2nd attempt

Running the same code on Google App Engine reveals totally different usage stats:

    64751 function calls (63972 primitive calls) in 0.957 CPU seconds

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       37    0.625    0.016    0.674    0.017 {google3.apphosting.runtime._apphosting_runtime___python__apiproxy.Wait}
        2    0.018    0.009    0.018    0.009 {method 'read' of 'file' objects}
       37    0.017    0.000    0.028    0.001 apiproxy.py:119(_MakeCallImpl)

As you can see above, time is mostly (65%) spent on a call to apiproxy.Wait. So, what is Google waiting for? I can guess, of course: datastore I/O. So, let’s find out if that is the case…

DB Profiling

For database profiling, I turned to an article: Using hooks in GAE. Using a “pre-call” hook, I log all datastore_v3 calls:

def patch_appengine():
    def hook(service, call, request, response):
        logging.info('%s %s - %s' % (service, call, str(request)))
        stack = traceback.format_stack()
        logging.debug('%s %s - %s' % (service, call, "n".join(stack)))
      
    apiproxy_stub_map.apiproxy.GetPreCallHooks().Append('db_log', hook, 'datastore_v3')

It turns out that 36 out of the 37 apiproxy.Wait are accounted for in the log. These are, as we expected, datastore calls. But there is an interesting thing going on, looking a part of the log:

3:39 30.425 Get - key .. {type: "Team" name: "Shot 1"}
3:39 30.506 Get - key .. {type: "Team" name: "Bijmaat 3"}
3:39 30.540 Get - key .. {type: "Team" name: "Almeerspin 2"}
3:39 30.580 Get - key .. {type: "Team" name: "Shot 1"}
3:39 30.614 Get - key .. {type: "Team" name: "Maarssen 1"}
3:39 30.651 Get - key .. {type: "Team" name: "Shot 1"}
3:39 30.678 Get - key .. {type: "Team" name: "Shot 1"}
3:39 30.702 Get - key .. {type: "Team" name: "SVO 2"}
3:39 30.732 Get - key .. {type: "Team" name: "Shot 1"}
3:39 30.755 Get - key .. {type: "Team" name: "Laren 1"}

Now, let’s get a little bit of background: I am profiling the part of my app that is showing the matches of my team (“Shot 1″). Every match references two teams using db.ReferenceProperty(Team). The log output above is the result of showing the first 5 matches.

As you can see above, my team is retrieved from the datastore for every single match, using an expensive (16 ms on average) remote procedure call!

Optimizing this is something I will work on in my next post.

Advertisement