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