Explain my AppStats graph for a db.get

Question

I did a db.get([356 keys]) and it took 8 seconds. Here is an excerpt of the AppStats graph for this operation: http://vvcap.net/db/iXvU5LtfG6tp04-kjqvp.htp

Is 8 seconds normal for 356 keys? And why is the CPU time be bigger than the API CPU time? If anything I would expect the API CPU time to be bigger, since entities are fetched in parallel.

All 356 keys are for this model:

class Molecule(db.Model):
    meaning = db.StringProperty()
    short_desc = db.StringProperty()
    official = db.BooleanProperty(default=False)
    phrasing = db.ReferenceProperty()
    atoms = db.ListProperty(db.Key) # ~3 list elements on average
    keywords = db.ListProperty(db.Key) # ~20 list elements on average
    phrasings = db.ListProperty(db.Key) # ~1 list element on average
    add_dt = db.DateTimeProperty()
    modify_dt = db.DateTimeProperty()
    delete_dt = db.DateTimeProperty()
    _ucase_meaning = db.StringProperty()

Answer 1

6-8 seconds is certainly high, but the models you're fetching are fairly complex. The reason for the long time is due to the number and size of the entities you're fetching - most of the CPU time not accounted for by API time is the time spent waiting for the request to complete (eg, blocked on IO from one or more of the tabletservers).

There are several approaches you can take to speed things up:

1. Fetch fewer entities.
2. Split your model into two parts, the 'full' model and the 'summary'. Only fetch the summary entities whenever possible.
3. Memcache the result of the fetch.
4. Memcache the output that you generate with the fetched data.