Are the RPC timings in _ah/stats leaving something out?

Question

I'm trying to understand where I might be able to shave some time off a particular request in AppEngine (one millions of users will be making).

Here are my RPC timings from an appengine.com instance (not my local Dev server).

The Gannt chart shows that the 3 RPC calls in the handler took at most 25 ms each:

But there are huge gaps in between.

So I added some logging messages around each RPC, like:

logging.debug('Starting 1st RPC')
tags = ndb.get_multi(tag_keys, use_cache=True, use_memcache=True)
logging.info('Finished 1st RPC, retrieved {} entities'.format(len(tags)))

The log for the request that's graphed above is:

2015-04-03 16:33:16.870 /api/v2/foo 200 1229ms 103kb Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.118 Safari/537.36 module=default version=3
D 2015-04-03 16:33:15.650 Starting 1st RPC
I 2015-04-03 16:33:15.670 Finished 1st RPC, retrieved 3 entities
D 2015-04-03 16:33:15.671 Starting 2nd RPC
I 2015-04-03 16:33:15.953 Finished 2nd RPC, retrieved 30 entities
I 2015-04-03 16:33:15.957 ...
D 2015-04-03 16:33:15.958 Starting 3rd PRC
I 2015-04-03 16:33:16.574 Finished 3rd RPC, retrieved 190 entities
I 2015-04-03 16:33:16.652 ...
I 2015-04-03 16:33:16.761 ...
I 2015-04-03 16:33:16.843 Saved; key: __appstats__:095600, part: 90 bytes, full: 15711 bytes, overhead: 0.001 + 0.066; link: http://foo.appspot.com/_ah/stats/details?time=1

which show the RPC timings as 20 ms, 282 ms, 616 ms.

My guess is that the chart timings do not account for deserialization into the model object, or something like that?

According to Datastore Admin, the avg. entity size for the entities returned from the 2nd and 3rd calls are 5KB and 1KB, respectively.

Also, the chart shows the 3rd RPC starting ~600 ms after the first, while the logs show only ~300 ms elapsed between 1 & 3.

Should I not rely on the chart/stats for hard/real numbers?

Answer 1

My guess is that the chart timings do not account for deserialization into the model object, or something like that?

Right - they're strictly about the RPCs proper, only.

Also, the chart shows the 3rd RPC starting ~600 ms after the first, while the logs show only ~300 ms elapsed between 1 & 3.

This is perplexing -- I've seen the reverse sometimes (and mentally attributed it to the app or thread being pre-empted and the chart only considering "CPU" rather than "total elapsed" time) but never the kind of discrepancy you observe.

Should I not rely on the chart/stats for hard/real numbers?

I've recently started playing ("playing" only, as it's in beta) with Google Cloud Monitoring (from Stackdriver), per https://cloud.google.com/monitoring/get-started#monitoring_app_engine_projects , and I wonder if it might do a better job for you...