What can cause high variability of Untraced Time in App Engine requests?

Question

I just ran a load test against my app. I noticed some very large variability in latency for two identical requests: 3 s vs. 30 s. When I dug into the traces I found the following:

|                      | Traced (ms) | Untraced (ms) |
|----------------------+-------------+---------------|
| High-latency Request |         193 |         29948 |
| Low-latency Request  |         305 |          2934 |

Here are screen shots for the traces:

Low overall latency

High overall latency

I cannot make sense of a 10-to-1 difference in runtime performance.

I only see these high-latency requests under load. Could something in my code account for this variability (assuming the same path through the code was followed for both requests)?

Answer 1

In my experience, those extraordinarily high latencies are caused by a fresh instance starting up. There was a discussion in the AppEngine Google Group which is about similar issues: https://groups.google.com/d/msg/google-appengine/MBveo1KSTyY/mkYdyCmfAgAJ

Two things you can do:

1. reduce time it takes an instance to start by reducing overall size of your application (code, libraries, assets) and heavy use of lazy initialization. Using a higher instance class might help too (stronger instances boot up faster)
2. tweak your scaling options: always have one (or two) idle instances hanging around so there is no need to wait for an instance to boot during traffic peaks

Hope that helps. In my case, using a higher instance class helped a lot already!