Thanks Kyle, Your blog was very insightful. I am not sure why your JVM spins up so fast and mine takes upwards of 5000ms. I have several .jar files of my own and probably instantiate 3 or 4 dozen classes in order to serve my home page.
My JSPs are all precompiled. There is only MemCache access (1) and then the deserialization of about 40K's worth of data. I have the same notion as you mention in that my JSP's can be marked cacheable in which case the results get served next time. (The system automatically detects dependent Entity classes and blows away the cached JSP page if a dependent Entity is changed). One more thing, your log had a very interesting number on it, the JVM id. How are you getting this? Thanks, Steve On Mar 20, 7:34 pm, Spines <[email protected]> wrote: > Hi Steve, > I read your link. What I am referring to does include JVM startup. > Those are the times I get right after a redeploy. > > Here are some more lines from my logs, included with my info logs that > I omitted last time: > 03-20 04:07PM 41.084 /donothing 200 891ms 796cpu_ms 0kb Mozilla/5.0, > AC.Log info: JVMID: -4270362285924610791 - ReqNum: 0 > 03-20 04:11PM 22.290 /donothing 200 1240ms 777cpu_ms 0kb Mozilla/5.0, > AC.Log info: JVMID: -5678405964618118370 - ReqNum: 0 > 03-20 04:12PM 06.574 /donothing 200 81ms 58cpu_ms 0kb Mozilla/5.0, > AC.Log info: JVMID: -5678405964618118370 - ReqNum: 1 > 03-20 04:14PM 31.684 /donothing 200 1105ms 835cpu_ms 0kb Mozilla/5.0, > AC.Log info: JVMID: -5439702848547505668 - ReqNum: 0 > 03-20 04:14PM 52.309 /donothing 200 71ms 58cpu_ms 0kb Mozilla/5.0, > AC.Log info: JVMID: -5439702848547505668 - ReqNum: 1 > > Here are the corresponding times for my browser to receive a response > (captured with firebug): > 1.11s > 1.38s > 188ms > 1.22s > 172ms > > In the logs, the lines that say "ReqNum: 0" were cold starts that > happened because I redeployed my app. One of them even took less than > a second :). > > I have spent many months learning how to optimize my cold start time. > I took my original app that took 15 seconds for a cold start, and have > brought it down quite a bit :). > > I wrote a guide on my blog for cold start optimization if you are > interested. Here is the link > -http://www.answercow.com/2010/03/google-app-engine-cold-start-guide-f... > . > > On Mar 20, 1:24 pm, Steve Pritchard <[email protected]> wrote: > > > Hi, > > As I explained > > inhttp://groups.google.com/group/google-appengine-java/browse_thread/th... > > > I have the notion of cold/warm/hot. > > It calculates and records the service time when the top left-most GEM > > is pressed.. Hovering over the gem after it returns will show the > > stats. > > > A cold start only happens after a redeploy. > > > A warm start seems to add about 5000ms to my 'network' time which is > > normally 400ms or so. My turnaround in the server goes from almost 0 > > to about 2000ms, mostly doing a single cache-read from MemCache plus > > the ensuing de-serialization. > > > The 5000ms has to be JVM etc start up. Only the google folks can deal > > with that one. Theoretically getting rid of the unneeded .jar files > > can only help. > > > In my hot mode there is no JVM start-up and I am able to service the > > request in about 400ms. > > > Your cold-start (which is my warm start equivalent) of 2867ms is not > > including the JVM startup so I suspect at your browser the time is > > longer. > > > Hope this helps. > > Steve > > > On Mar 20, 11:42 am, Spines <[email protected]> wrote: > > > > Hey Steve, > > > Yea, the elapsed time is usually higher than CPU usage, but I think > > > maybe because I was doing my testing late last night I lucked into > > > really low elapsed time too. I checked my cold start time this > > > morning, and elapsed time was 2867ms with 1010cpu_ms. > > > > Here are some lines from my logs: > > > 03-20 08:30AM 05.838 /donothing 200 2867ms 1010cpu_ms 0kb Mozilla/5.0 > > > 03-20 12:15AM 00.832 /donothing 200 2155ms 913cpu_ms 0kb Mozilla/5.0 > > > 03-19 11:02PM 28.449 /donothing 200 1119ms 1166cpu_ms 0kb Mozilla/5.0 > > > > The elapsed time seems to vary greatly, whereas cpu time seems to be a > > > decent metric to see if an optimization of mine actually had an > > > effect. The page I request for testing is a servlet which returns > > > nothing. Note that if you are requesting a JSP it will increase your > > > cold start times by at least a few hundred milliseconds. For some > > > reason the first access to even the most simple JSP (like <%= 5+2 %> > > > will take quite a while. > > > > I'd really love to get my elapsed time down to around the same amount > > > as my CPU time. Does anyone have any insights as to what exactly App > > > Engine is doing during that time? > > > > On Mar 20, 7:30 am, Steve Pritchard <[email protected]> wrote: > > > > > Update to previous post. > > > > I am measuring elapsed time (what I really care about), not CPU secs. > > > > I could not figure out how a cold start was so fast (1200ms). > > > > Steve > > > > > On Mar 20, 10:26 am, Steve Pritchard <[email protected]> wrote: > > > > > > Thanks for the tip. I am in the same boat in that I do not use JDO > > > > > etc. I also do not need GWT stuff. So I deleted: > > > > > > datanucleus-appengine-1.0.5.final.jar > > > > > datanucleus-core-1.1.5.jar > > > > > datanucleus-jpa-1.1.5.jar > > > > > geronimo-jpa_3.0_spec-1.1.1.jar > > > > > geronimo-jta_1.1_spec-1.1.1.jar > > > > > gwt-servlet.jar > > > > > jdo2-api-2.3-eb.jar > > > > > > from my 1.3.1 war\lib and it keeps running. My 'warm' start (using > > > > > MemCache) is around 3200ms. Previously I recall it fluctuated around > > > > > 4000ms. > > > > > Steve > > > > > > On Mar 20, 2:09 am, Spines <[email protected]> wrote: > > > > > > > Well, I figured it out, I just deleted all of the jars I didn't need > > > > > > from my ./build directory. I deleted all of the JDO, JPA, and > > > > > > datanucleus jars. The result of doing this was I got my first cold > > > > > > start that happened under 1200ms :). Previously the CPU time used > > > > > > by > > > > > > a cold start was pretty consistently around 1500ms, and after > > > > > > deleting > > > > > > those jars it is now around 1150ms :). -- You received this message because you are subscribed to the Google Groups "Google App Engine for Java" group. To post to this group, send email to [email protected]. To unsubscribe from this group, send email to [email protected]. For more options, visit this group at http://groups.google.com/group/google-appengine-java?hl=en.
