The 400ms was measured from the time that the code entered my servlet's get method. I can't be sure anymore since I've rewritten the code since then to use Objectify, but I'm guessing that it did not include the first PMF construction call.
If constructing the PMF is what was costing a bunch of time, then I'm guessing that the warmup request was not constructing one, but that it was getting constructed at static init time relative to the actual request. I'll keep an eye on this once I'm ready to deploy again (the rewrite to Objectify came with a bunch of other changes I need to finish before I'm ready for real testing again). For the moment, though, it seems like the problems I was having were due to a misunderstanding of how GAE instance warmups happen, and not due to a problem with the instance scheduler itself. - Kris On Saturday, September 1, 2012 3:57:07 PM UTC-7, Jeff Schnitzer wrote: > > Yeah, baffling. JDO startup costs come with the construction of the > PersistenceManagerFactory, so that should be "in your code". > > That 400ms - is that measured from a filter at the outermost layer? > > An interesting thing to try is to set up a handler for the warmup > request which issues an actual query to the datastore. Any query. > > Jeff > > On Fri, Aug 31, 2012 at 9:25 PM, Kristopher Giesing > <kris.g...@gmail.com <javascript:>> wrote: > > 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-a...@googlegroups.com<javascript:>. > > > To unsubscribe from this group, send email to > > google-appengi...@googlegroups.com <javascript:>. > > For more options, visit this group at > > http://groups.google.com/group/google-appengine?hl=en. > -- 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/-/WawFZE2RJw0J. 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.
