I certainly will add some logging time stamps around the dispatch but will that help with cases like this where the request gets terminated before any code executes ( I have had 5 of these in the last 12 hours).
2011-03-01 09:49:07.343 /reggie/dispatch 500 10040ms 0cpu_ms 0kb Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/534.13 (KHTML, like Gecko) Chrome/9.0.597.98 Safari/534.13,gzip(gfe) 199.244.171.158 - brigaffney [01/Mar/2011:09:49:07 -0800] "POST / reggie/dispatch HTTP/1.1" 500 0 - "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/534.13 (KHTML, like Gecko) Chrome/9.0.597.98 Safari/534.13,gzip(gfe)" - ms=10041 cpu_ms=0 api_cpu_ms=0 cpm_usd=0.000135 exit_code=203 W 2011-03-01 09:49:07.334 A serious problem was encountered with the process that handled this request, causing it to exit. This is likely to cause a new process to be used for the next request to your application. If you see this message frequently, you should contact the App Engine team. (Error code 203) On Mar 1, 10:11 am, Robert Kluin <[email protected]> wrote: > Have you tried sticking a few logging calls with a timestamp in your > code to reconcile the difference against appstats and identify the > trouble spot in the code? > > Robert > > > > > > > > On Tue, Mar 1, 2011 at 13:06, Cian Montgomery <[email protected]> > wrote: > > > I have not been able to find a log entry with a pending_ms entry in > > it. > > > After I check capabilities, > > - construct and Objectify Object > > > - check if the user is logged in. ( false in this case ) > > - use objectify to retrieve application configuration -> this should > > be the memcache call. > > > Cian. > > > On Mar 1, 9:43 am, Robert Kluin <[email protected]> wrote: > >> Do you ever see large pending_ms values in your logs? > > >> What does your code do between the capability checks and the memcache call? > > >> Robert > > >> On Tue, Mar 1, 2011 at 12:32, Cian Montgomery <[email protected]> > >> wrote: > >> > Looking at my logs this morning for the nights activity I find a > >> > couple of troubling cases, like this: > > >> > AppEngine Log: 2011-03-01 08:45:38.679 /reggie/dispatch 200 5879ms > >> > 3150cpu_ms 0kb Mozilla/4.0 > >> > Appstats: 2011-03-01 16:45:37.204 POST /reggie/dispatch real=1255ms > >> > cpu=0ms api=0ms overhead=8ms > >> > @905ms capability_service.IsEnabled real=4ms api=0ms > >> > @935ms capability_service.IsEnabled real=8ms api=0ms > >> > @943ms capability_service.IsEnabled real=5ms api=0ms > >> > @948ms capability_service.IsEnabled real=4ms api=0ms > >> > @1187ms memcache.Get real=7ms api=0ms > > >> > AppEngine Log: 2011-03-01 08:13:36.788 /reggie/dispatch 200 18016ms > >> > 3103cpu_ms 0kb Mozilla/4.0 > >> > Appstats: 2011-03-01 16:13:34.758 200 POST /reggie/dispatch > >> > real=1816ms cpu=0ms api=0ms overhead=6m > >> > @1455ms capability_service.IsEnabled real=4ms api=0ms > >> > @1484ms capability_service.IsEnabled real=4ms api=0ms > >> > @1488ms capability_service.IsEnabled real=3ms api=0ms > >> > @1491ms capability_service.IsEnabled real=4ms api=0ms > >> > @1727ms memcache.Get real=7ms api=0ms > > >> > In both cases app stats under reports the latency reported by the > >> > Appengine logs and my code in the call does not get called for a long > >> > time after the apstats logging starts (905ms in one case and 1400ms ) > >> > in the other. > > >> > Are the machines hosting the apps overloaded? Are there other settings > >> > I can turn on to get more insights to these delays? > > >> > Thanks, > > >> > Cian. > > >> > On Feb 28, 10:50 pm, Cian Montgomery <[email protected]> > >> > wrote: > >> >> Thanks for your response. I installed and have been inspecting my > >> >> application with appstats. I have noticed a comple of things, 1 the > >> >> latency times and log times of appstats do not match what is reported > >> >> in the log. consider the following 5 calls, Particularly the 3rd call > >> >> where the difference is over 400ms. (log comparison is made more > >> >> difficult by time stamps not matching and the times of the log entries > >> >> being in different time zones.) > > >> >> 2011-02-28 22:10:55.336 /reggie/dispatch 200 45ms 116cpu_ms 0kb > >> >> Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_6; en-US) AppleWebKit/ > >> >> 534.13 (KHTML, like Gecko) Chrome/9.0.597.102 Safari/534.13,gzip(gfe) > >> >> 2011-02-28 22:07:27.537 /reggie/dispatch 200 64ms 154cpu_ms > >> >> 60api_cpu_ms 0kb Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) > >> >> AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.82 Safari/ > >> >> 534.16,gzip(gfe) > >> >> 2011-02-28 22:07:08.333 /reggie/dispatch 200 473ms 177cpu_ms > >> >> 60api_cpu_ms 0kb Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) > >> >> AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.82 Safari/ > >> >> 534.16,gzip(gfe) > >> >> 2011-02-28 22:06:55.387 /reggie/dispatch 200 60ms 107cpu_ms > >> >> 60api_cpu_ms 0kb Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) > >> >> AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.82 Safari/ > >> >> 534.16,gzip(gfe) > >> >> 2011-02-28 22:06:54.179 /reggie/dispatch 200 52ms 130cpu_ms > >> >> 60api_cpu_ms 0kb Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) > >> >> AppleWebKit/534.16 (KHTML, like Gecko) Chrome/10.0.648.82 Safari/ > >> >> 534.16,gzip(gfe) > > >> >> (12)2011-03-01 06:10:55.308 "POST /reggie/dispatch" 200 real=20ms > >> >> cpu=0ms api=0ms overhead=0ms (6 RPCs) > >> >> (13) 2011-03-01 06:07:27.487 "POST /reggie/dispatch" 200 real=40ms > >> >> cpu=0ms api=0ms overhead=0ms (8 RPCs) > >> >> (14) 2011-03-01 06:07:08.264 "POST /reggie/dispatch" 200 real=55ms > >> >> cpu=0ms api=0ms overhead=0ms (8 RPCs) > >> >> (15) 2011-03-01 06:06:55.337 "POST /reggie/dispatch" 200 real=43ms > >> >> cpu=0ms api=0ms overhead=0ms (8 RPCs) > >> >> (16) 2011-03-01 06:06:54.140 "POST /reggie/dispatch" 200 real=32ms > >> >> cpu=0ms api=0ms overhead=0ms (8 RPCs) > > >> >> - checking for each capability enable costs 2-4ms best case. It would > >> >> be nice to be able to check all caps in 1 rpc. > >> >> - latency to the datastore is highly erratic, on subsiquent user > >> >> requests for the same data from the data store show the following > >> >> resutls: real=7ms api=85ms, real=305ms api=85ms. Is is normal to 40x > >> >> variance in executing the same query to the datastore? > > >> >> Is there a way to put my own events in the appstats? I am using a > >> >> dispatch pattern in the server, so it is difficult to devine what > >> >> which handler I am looking at in the stats? > > >> >> Thanks, > > >> >> Cian > > >> >> On Feb 28, 12:42 am, Robert Kluin <[email protected]> wrote: > > >> >> > Hi Cian, > >> >> > Have you used Appstats to investigate? Perhaps there is some type > >> >> > of cleanup process, maybe by a session library, happening? > > >> >> > Robert > > >> >> > On Fri, Feb 25, 2011 at 17:00, Cian Montgomery > > >> >> > <[email protected]> wrote: > >> >> > > My app (appid: mr-october, always on) is experiencing lots of > >> >> > > problems > >> >> > > with latency problems over the last couple of days. > > >> >> > > For a bunch of the calls to the same action dispatch handler over > >> >> > > the > >> >> > > last there hours. > >> >> > > 2011-02-25 12:36:09.581 /reggie/dispatch 200 4829ms 4763cpu_ms > >> >> > > 236api_cpu_ms > >> >> > > 2011-02-25 12:35:31.683 /reggie/dispatch 200 159ms 405cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 12:35:16.764 /reggie/dispatch 200 354ms 615cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 12:20:37.208 /reggie/dispatch 200 232ms 452cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 12:19:28.348 /reggie/dispatch 200 6380ms 4600cpu_ms > >> >> > > 190api_cpu_ms > >> >> > > 2011-02-25 10:47:19.700 /reggie/dispatch 200 171ms 452cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 10:47:15.865 /reggie/dispatch 200 141ms 405cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 10:47:15.731 /reggie/dispatch 200 385ms 475cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 10:37:15.031 /reggie/dispatch 200 177ms 522cpu_ms > >> >> > > 125api_cpu_ms > >> >> > > 2011-02-25 10:36:48.890 /reggie/dispatch 200 3550ms 732cpu_ms > >> >> > > 125api_cpu_ms > > >> >> > > Which is honestly much better then the past couple of days where saw > >> >> > > some times over 30000ms. > > >> >> > > Or these where appengine did not even get to my log statement so I > >> >> > > have no idea what the request was: > >> >> > > 2011-02-23 09:36:35.922 /reggie/dispatch 500 141862ms 1395cpu_ms > >> >> > > 65api_cpu_ms > >> >> > > 2011-02-23 09:00:21.024 /reggie/dispatch 500 102858ms 793cpu_ms > > >> >> > > I can reproduce this behavor just by hitting the same query from the > >> >> > > client, reliably 1 out of about every 20 exections of this action is > >> >> > > over 5 seconds of latency. > > >> >> > > What can be done to address these latency issues? > > >> >> > > Thanks, > > >> >> > > Cian. > > >> >> > > -- > >> >> > > You received this message because you are subscribed to the Google > >> >> > > Groups "Google App Engine" 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 > >> >> > > athttp://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 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 > >> > athttp://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 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 > > athttp://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 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?hl=en.
