Google App Engine strange delay

Asked 29/4, 2012 at 19:1 Answered 29/4, 2012 at 22:14

I improved a lot my code and now all the API run really fast, I also added memcache and I have a great hit ratio .. But sometimes I get meaningless delays.

I attached here the most significant appstats screenshot: more than 20 seconds in total to run 90ms of RPCs; how is it possible? Where should I look to find the origin of those delays?

I am really stuck because I don't understand what's happening between the RPCs and I don't know what else I can do in order to get more informations.

Just a thought: each HTTP call is handled by the same GAE instance, right? Because my instances took a lot of time to warmup .. But I don't think it is related

BTW: I am coding in Java.

appstats statistics

Loup answered 29/4, 2012 at 19:1 Comment(0)

Usually the unaccounted for "hole" in the middle of appstats is your code executing.
Appstats records every rpc entry and exits and the areas he cannot record are your actual code running.

Do you have logs for the time in which the application was between those two calls?

Stygian answered 29/4, 2012 at 22:14 Comment(4)

thank you shay .. yes, I log a lot of things with log.fine(..), so I should just enable the level and then have a look again. – Loup 30/4, 2012 at 9:0

what I am not convinced 100% is that an HTTP call is handled by different instances. Is it possible? Because this could be another problem, due to the long time spent in warming up a new instance! – Loup 30/4, 2012 at 9:1

@MicheleOrsi you cannot jump instance during handler execution – Stygian 30/4, 2012 at 10:41

ok great! Thank you very much, at least: this is good starting point to start skipping warmup problems! ;) – Loup 30/4, 2012 at 12:7

Huge, 'unexplained' latency is almost always warmup requests gobbling up resources. Inspect your appengine logs to see how much api_ms and cpu_ms are being used on warmups.

You can avoid warmups by increasing your maximum pending latency in appengine control panel. Allowing higher latency means requests will wait longer before firing a new instance. This could make each request a little slower, but you will avoid heavyweight loading requests.

To help with warmup requests, make sure your appengine-web.xml has:

<warmup-requests-enabled>true</warmup-requests-enabled>

This will cause the appengine dispatcher to preemptively fire up new instances when the current ones are being overloaded {i.e. it starts loading before a request goes to the new instance}.

then, in the affected slow servlets, make sure you put load-on-startup in your web.xml:

<servlet>
  <servlet-name>my-servlet</servlet-name>
  <servlet-class>com.company.MyServlet</servlet-class>
  <load-on-startup>1</load-on-startup>
</servlet>

load-on-startup merely ensures that your high-priority servlets are always ready to go as soon as the warmup request finishes.

Recruitment answered 29/4, 2012 at 19:33 Comment(7)

Thank you, but I am already doing all your suggestions: warmup-requests-enabled, load-on-startup and my Pending Latency is set to 11.5s – Automatic .. – Loup 29/4, 2012 at 20:52

Can you run your test again, and watch how many instances are fired up? Check if you are getting loading requests in the logs, and how many of them. Also, are you firing all your rpcs at the same time? If your browser has more than two connections open, it will block on the pending ones, which can then cause your servlets to block. Watch the requests in firebug as well to see if you can pick out which requests are pushing you to 20s on 90ms of requests. – Recruitment 29/4, 2012 at 22:10

Also, a pending latency of 11.5s means each connection can have over 10s latency. Measure your loading requests. If one load request is 15s, and max pending latency is 11s, your first loading request will wait 10s, then take another 15s to fire up a new instance. You may want to turn pending latency down and just bite the bullet on the loading requests. – Recruitment 29/4, 2012 at 22:15

It's not warmups in this case - appstats shows that the RPCs get executed near the beginning of the request. – Tralee 30/4, 2012 at 5:46

ok @NickJohnson thank you; as Shay suggested I started to profile other part of my code, but I am a bit stuck in extending appstats for Java with recording of other events than GAE RPCs. Is it possible? – Loup 30/4, 2012 at 9:13

Thank you also to @Ajax, but I think Nick has excluded that possibility – Loup 30/4, 2012 at 9:14

If you would be so kind as to post your instance hour graph, some run logs, or some source code of this process, I'm sure between myself, Nick and all of StackOverflow, we can drop that 20s to 5s or less ;-} – Recruitment 30/4, 2012 at 14:51