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 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 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.
