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.
