The JVM Id is just a random number I assign to the JVM at startup time. I just call new Random().nextLong().
http://code.google.com/appengine/kb/java.html#How_To_Detect_Loading_Requests explains how to know when a JVM is starting up. On Mar 20, 6:22 pm, Steve Pritchard <[email protected]> wrote: > 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.
