Performance tuning on Google App Engine

After profiling my app (see Performance profiling on GAE), it’s time to do some actual tuning. The problem is, that GAE’s datastore is not very smart about entities already loaded in the same session or request. For this reason other ORM tools like (n)Hibernate use a Session Cache. Interacting with the datastore always goes through a session cache in Hibernate. There is only a single instance of a retrieved entity in the session cache.

Now this is quite different from the GAE datastore. As we saw in my previous post, every reference to an existing entity is

• fetched separately from the datastore, and
• leads to a new instance in memory.

Using memcache

Of course, we already have a caching mechanism in GAE: memcache. So, let’s use that and figure out if that will give the performance boost we need.

In order to prevent referenced entities to load more than once, we can subclass db.ReferenceProperty and use our own version:

class CachedReferenceProperty(db.ReferenceProperty):

  def __init__(self,
               reference_class=None,
               time=0,
               verbose_name=None,
               collection_name=None,
               **attrs):
    super(CachedReferenceProperty, self).__init__(reference_class, verbose_name, collection_name, **attrs)
    self.time = time

In the class definition above, a time parameter is added, which will be passed on to memcache. It determines the number of seconds an entity is cached.

In order to intervene with the actual database access, we need to override the __get__ method. For convenience I have duplicated the original __get__ method in our class and patched it a bit:

  def __get__(self, model_instance, model_class):
    if model_instance is None:
      return self
    if hasattr(model_instance, self.__id_attr_name()):
      reference_id = getattr(model_instance, self.__id_attr_name())
    else:
      reference_id = None
    if reference_id is not None:
      resolved = getattr(model_instance, self.__resolved_attr_name())
      if resolved is not None:
        return resolved
      else:
        reference_str = str(reference_id)
        instance = memcache.get(reference_str)
        if instance is None:
          instance = db.get(reference_id)
          memcache.set(reference_str, instance, self.time)
        else:
          logging.info("CachedReferenceProperty - found object in cache: "+str(reference_id))
        if instance is None:
          raise Error('ReferenceProperty failed to be resolved')
        setattr(model_instance, self.__resolved_attr_name(), instance)
        return instance
    else:
      return None

The changed part are lines 13 through 19 in the code above. Originally, there was only line 16 present.

Now, in order to get this code working, I had to duplicate the two methods below as well. Since I am a Python novice, I don’t understand why I had to do this, but it works… (if someone knows, please leave a comment )

  def __id_attr_name(self):
    return self._attr_name()

  def __resolved_attr_name(self):
    return "_RESOLVED"+self._attr_name()

And now the results of actually applying this caching method. I used the CachedReferenceProperty with a 5 second timeout, which should be good enough to cache the entity during the request lifetime.

    90565 function calls (88670 primitive calls) in 3.601 CPU seconds
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       61    1.858    0.030    1.921    0.031 {google3.apphosting.runtime._apphosting_runtime___python__apiproxy.Wait}
      523    0.674    0.001    0.674    0.001 {posix.stat}
       61    0.141    0.002    0.160    0.003 apiproxy.py:119(_MakeCallImpl)

Without the caching, the results are (around the same time as the previous call):

    81628 function calls (80775 primitive calls) in 2.840 CPU seconds
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       39    1.169    0.030    1.222    0.031 {google3.apphosting.runtime._apphosting_runtime___python__apiproxy.Wait}
      973    1.130    0.001    1.130    0.001 {posix.stat}
       37    0.034    0.001    1.214    0.033 traceback.py:273(extract_stack)
       39    0.027    0.001    0.039    0.001 apiproxy.py:119(_MakeCallImpl)

So, the performance is actually worse! The response time increased from 2.8 seconds to 3.6 seconds using memcache. And the number of apiproxy.Wait calls increased from 39 to 61. Which is not strange, since memcache also uses remoting… And that, of course, is also the reason that this solution is actually worse.

The lesson to be learned here, is that memcache should be used on a more granular level, caching actions that involve a lot more than just getting an entity from the datastore by key…

Using a dictionary

Since we only want to cache entities during the duration of a request, the entities could just as well be stored locally in memory. So we change our CachedReferenceProperty class:

class CachedReferenceProperty(db.ReferenceProperty):

  _cache = weakref.WeakValueDictionary({})
    
  def __get__(self, model_instance, model_class):
    ...
        instance = CachedReferenceProperty._cache.get(reference_id, None)
        if instance is None:
          instance = db.get(reference_id)
          CachedReferenceProperty._cache[reference_id] = instance
        else:
          logging.info("CachedReferenceProperty - found object in cache: "+str(reference_id))
    ...

We use a WeakValueDictionary so that we don’t actively have to clean up after our selves (that is: removing the entries from the cache dictionary after usage). Entries are removed as soon as there is no reference to the entity anymore. This will usually be at the end of the request. Here are the results of this approach:

    66706 function calls (65996 primitive calls) in 1.578 CPU seconds
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      538    0.619    0.001    0.619    0.001 {posix.stat}
       23    0.543    0.024    0.581    0.025 {google3.apphosting.runtime._apphosting_runtime___python__apiproxy.Wait}
       23    0.028    0.001    0.036    0.002 apiproxy.py:119(_MakeCallImpl)

The number of apiproxy.Wait calls decreased from 39 to 23 and, better, the response time decreased from 2.8 to 1.6 seconds!

Advertisement