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.
