OK. Something just became clearer to me. The requests appear to be tagged with the instance that handles the request. Based on that data, it looks like my request is in fact being handled by the resident instance, not the new dynamic instance.
The puzzle then becomes why the request still takes 8s to satisfy when the instance handling it is already warmed, and the in-application logging code (which I didn't post, but trust me on this) is never higher than about 400ms. I had been assuming that the 8s cost was the cost of the new instance spinning up, but the instance tag seems to contradict that. The answer has to be some kind of static initialization cost. Although my app is not very complex, I wonder if this is due to the class path scanning that JDO does. I have since switched to Objectify, but I am actually not very clear on whether that is sufficient to prevent JDO/JPA class path scanning; it seems like I would need to evict the JDO/JPA core code from my application on deployment, but it's far from clear to me how to do that. ... But even that may not really explain this behavior because you would think static initialization costs would be born by the warmup request. So, actually, I am baffled. Any ideas, anyone? - Kris On Friday, August 31, 2012 9:16:16 PM UTC-7, Kristopher Giesing wrote: > > This is the request that I actually issued, being handled: > > 2012-07-31 23:08:28.045 /api/game/57002?pretty=true 200 7893ms 11kb > Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_4) AppleWebKit/536.25 (KHTML, > like Gecko) Version/6.0 Safari/536.25 > 76.102.149.245 - kris [31/Jul/2012:23:08:28 -0700] "GET > /api/game/57002?pretty=true HTTP/1.1" 200 11652 - "Mozilla/5.0 (Macintosh; > Intel Mac OS X 10_7_4) AppleWebKit/536.25 (KHTML, like Gecko) Version/6.0 > Safari/536.25" "titan-game-qa.appspot.com" ms=7893 cpu_ms=3520 > api_cpu_ms=0 cpm_usd=0.099322 > instance=00c61b117c77507e2cfe78a0806d0ca80b52720e > > These are the *two* preceding warmup requests: > > ** Dynamic instance warmup ** > 2012-07-31 23:08:27.475 /_ah/warmup 200 5873ms 0kb > 0.1.0.3 - - [31/Jul/2012:23:08:27 -0700] "GET /_ah/warmup HTTP/1.1" 200 60 > - - "1.360723738856412175.titan-game-qa.appspot.com" ms=5873 cpu_ms=2475 > api_cpu_ms=0 cpm_usd=0.068778 loading_request=1 > instance=00c61b117cdaae6145945d99c16aeee7cc0f4ad8 > > ** Resident/idle instance warmup ** > 2012-07-31 23:07:42.842 /_ah/warmup 200 5045ms 0kb > 0.1.0.3 - - [31/Jul/2012:23:07:42 -0700] "GET /_ah/warmup HTTP/1.1" 200 60 > - - "1.360723738856412175.titan-game-qa.appspot.com" ms=5046 cpu_ms=2475 > api_cpu_ms=0 cpm_usd=0.068778 loading_request=1 > instance=00c61b117c77507e2cfe78a0806d0ca80b52720e > > This is my point. The problem is not that a new instance was spawned > (although I admit that I did not quite understand the desired behavior when > I first posted this data). The problem is that the request I issued is not > satisfied until AFTER the warmup request has been issued and handled by the > new instance. The request should FIRST have been handled by the already > resident instance, AND THEN the new instance should have been spawned. > > If I'm misunderstanding something, please clarify, because at the face of > it this seems to be a smoking gun. > > - Kris > -- You received this message because you are subscribed to the Google Groups "Google App Engine" group. To view this discussion on the web visit https://groups.google.com/d/msg/google-appengine/-/4FGx8YdHUIgJ. To post to this group, send email to google-appengine@googlegroups.com. To unsubscribe from this group, send email to google-appengine+unsubscr...@googlegroups.com. For more options, visit this group at http://groups.google.com/group/google-appengine?hl=en.
