I do some performance stuff, but that will save me only 200-300ms. Other that that, no special code is in the servlets.
Following are debug logs that take 4038ms and 235ms for the same request. Please find the code that happens between "LoginFilter Begin" and "before chain.doFilter()". In the below log, the log between "7" and "7a" is taking about 1.5 secs. It is just one query that happens there. Most of the calls are taking longer time in the first request. http://snipt.org/AgjF0 1. 2013-09-15 07:32:34.625 /toolsMgr/activityLog?tenantId= DemoCompany:veersoft1.t...@gmail.com&branchId=5270096&timePeriodId=16001 200 4038ms 22kb Mozilla/5.0 (Windows NT 6.1; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0 2. I2013-09-15 07:32:30.619 com.veersoft.filter.ResetUserMessagesAndErrorsFilter doFilter: begin 3. I2013-09-15 07:32:30.619 com.veersoft.filter.LoginFilter doFilter: LoginFilter Begin 4. I2013-09-15 07:32:30.625 com.veersoft.filter.LoginFilter doFilter: 1 5. I2013-09-15 07:32:30.643 com.veersoft.filter.LoginFilter doFilter: 2 6. I2013-09-15 07:32:31.036 com.veersoft.filter.LoginFilter doFilter: 3 7. I2013-09-15 07:32:31.036 com.veersoft.filter.LoginFilter doFilter: 4 8. I2013-09-15 07:32:31.039 com.veersoft.filter.LoginFilter doFilter: 5 9. I2013-09-15 07:32:31.116 com.veersoft.filter.LoginFilter doFilter: 6 10. I2013-09-15 07:32:31.117 com.veersoft.filter.LoginFilter doFilter: 7 11. I2013-09-15 07:32:31.117 com.veersoft.filter.LoginFilter doFilter: 7a 12. I2013-09-15 07:32:32.732 com.veersoft.filter.LoginFilter doFilter: 8 13. I2013-09-15 07:32:32.732 com.veersoft.filter.LoginFilter doFilter: 9 14. I2013-09-15 07:32:32.732 com.veersoft.filter.LoginFilter doFilter: 10 15. I2013-09-15 07:32:32.732 com.veersoft.filter.LoginFilter doFilter: before chain.doFilter() 16. I2013-09-15 07:32:32.733 com.veersoft.common.servlet.ValidateTenantServlet doGet: LoginInterceptor: user logged in = accguru1.t...@gmail.com 17. I2013-09-15 07:32:32.733 com.veersoft.common.servlet.ValidateTenantServlet validateTenant: Validating tenant DemoCompany:veersoft1.test@gmail.comfor user accguru1.test@gmail. 18. I2013-09-15 07:32:32.841 com.veersoft.common.servlet.ValidateTenantServlet validateTenant: tenant size list = 0 19. I2013-09-15 07:32:32.841 com.veersoft.common.servlet.ValidateTenantAndBranchServlet validateBranch: branchId validated value is : 5270096 20. I2013-09-15 07:32:33.519 com.veersoft.common.servlet.MainMenuMgrBaseServlet doGet: The memcahce key in main Servlet for headerAndMenu accguru1.test@gmail.comDemoCompany-veerso 21. I2013-09-15 07:32:33.800 com.veersoft.common.servlet.MainMenuMgrBaseServlet cacheHeaderAndMenusForMenuLink: Getting the prepared header and menu cache 22. I2013-09-15 07:32:34.616 com.veersoft.filter.LoginFilter doFilter: /toolsMgr/activityLog: 3997ms 23. I2013-09-15 07:32:34.616 com.veersoft.filter.ResetUserMessagesAndErrorsFilter doFilter: end 1. 2013-09-15 07:26:12.898 /toolsMgr/activityLog?tenantId= DemoCompany:veersoft1.t...@gmail.com&branchId=5270096&timePeriodId=16001 200 235ms 22kb Mozilla/5.0 (Windows NT 6.1; WOW64; rv:23.0) Gecko/20100101 Firefox/23.0 2. I2013-09-15 07:26:12.683 com.veersoft.filter.ResetUserMessagesAndErrorsFilter doFilter: begin 3. I2013-09-15 07:26:12.683 com.veersoft.filter.LoginFilter doFilter: LoginFilter Begin 4. I2013-09-15 07:26:12.683 com.veersoft.filter.LoginFilter doFilter: 1 5. I2013-09-15 07:26:12.684 com.veersoft.filter.LoginFilter doFilter: 2 6. I2013-09-15 07:26:12.687 com.veersoft.filter.LoginFilter doFilter: 3 7. I2013-09-15 07:26:12.687 com.veersoft.filter.LoginFilter doFilter: 4 8. I2013-09-15 07:26:12.688 com.veersoft.filter.LoginFilter doFilter: 5 9. I2013-09-15 07:26:12.695 com.veersoft.filter.LoginFilter doFilter: 6 10. I2013-09-15 07:26:12.696 com.veersoft.filter.LoginFilter doFilter: 7 11. I2013-09-15 07:26:12.696 com.veersoft.filter.LoginFilter doFilter: 7a 12. I2013-09-15 07:26:12.708 com.veersoft.filter.LoginFilter doFilter: 8 13. I2013-09-15 07:26:12.708 com.veersoft.filter.LoginFilter doFilter: 9 14. I2013-09-15 07:26:12.708 com.veersoft.filter.LoginFilter doFilter: 10 15. I2013-09-15 07:26:12.708 com.veersoft.filter.LoginFilter doFilter: before chain.doFilter() 16. I2013-09-15 07:26:12.709 com.veersoft.common.servlet.ValidateTenantServlet doGet: LoginInterceptor: user logged in = accguru1.t...@gmail.com 17. I2013-09-15 07:26:12.709 com.veersoft.common.servlet.ValidateTenantServlet validateTenant: Validating tenant DemoCompany:veersoft1.test@gmail.comfor user accguru1.test@gmail. 18. I2013-09-15 07:26:12.720 com.veersoft.common.servlet.ValidateTenantServlet validateTenant: tenant size list = 0 19. I2013-09-15 07:26:12.720 com.veersoft.common.servlet.ValidateTenantAndBranchServlet validateBranch: branchId validated value is : 5270096 20. I2013-09-15 07:26:12.814 com.veersoft.common.servlet.MainMenuMgrBaseServlet doGet: The memcahce key in main Servlet for headerAndMenu accguru1.test@gmail.comDemoCompany-veerso 21. I2013-09-15 07:26:12.889 com.veersoft.common.servlet.MainMenuMgrBaseServlet cacheHeaderAndMenusForMenuLink: Getting the prepared header and menu cache 22. I2013-09-15 07:26:12.895 com.veersoft.filter.LoginFilter doFilter: /toolsMgr/activityLog: 212ms 23. I2013-09-15 07:26:12.895 com.veersoft.filter.ResetUserMessagesAndErrorsFilter doFilter: end -Aswath On Sat, Sep 14, 2013 at 2:04 PM, timh <zutes...@gmail.com> wrote: > > > On Saturday, September 14, 2013 2:57:35 PM UTC+8, aswath wrote: >> >> If a request a served by an instance that is alive for sometime, then it >> is fine. >> However, sometimes the request is directed to a new instance. Any first >> request for a new instance is adding a considerable delay. >> >> > This implies you have some control over the performance. As I said > earlier either it's something that is expensive to initialise and is not > occurring as part of the warmup request > or you are caching something expensive as a result of the first request > serviced by the instance. > > I would strongly recommend you us appstats and logging, and determine > where in your request processing the time is consumed on this initial > request - maybe you can get whatever it does performed as part of a warmup > request. > > T > > > >> -Aswath >> >> >> On Sat, Sep 14, 2013 at 10:50 AM, timh <zute...@gmail.com> wrote: >> >>> I would check that this is always the case. Also check what 3rd and 4th >>> request is like - make sure it's the same instance. >>> >>> If so it would then suggest that additional initialisation is being >>> performed that is expensive or that caching of some data (memcache for >>> instance) has a significant performance impact (improvement) for 2nd and >>> subsequent requests. >>> >>> You should use appstats to profile what this request is doing. >>> >>> T >>> >>> >>> On Saturday, September 14, 2013 1:05:49 PM UTC+8, aswath wrote: >>> >>>> I am attaching the new logs. >>>> >>>> I was examining the logs. It did not say, it started a new instance. >>>> But, there was a instance startup before that log >>>> /_ah/warmup 200 15380ms 0kb >>>> >>>> I noticed that the request that is taking longer was served by the >>>> newly started instance. >>>> >>>> >>>> -Aswath >>>> >>>> >>>> >>>> On Sat, Sep 14, 2013 at 9:48 AM, timh <zute...@gmail.com> wrote: >>>> >>>>> You truncated the log for the 4159ms request. Did it say it started a >>>>> new instance ? >>>>> >>>>> T >>>>> >>>>> >>>>> On Saturday, September 14, 2013 11:15:37 AM UTC+8, aswath wrote: >>>>>> >>>>>> Hello, >>>>>> I am finding a huge time difference for serving the same request. >>>>>> Attached is the logs that shows the serving time for the same request. >>>>>> The same request was accessed with in 1 min interval from the same >>>>>> browser. There is no business logic change that happens between the >>>>>> first >>>>>> 1st request and the 2nd request. >>>>>> >>>>>> For the first request the serving the time is 4159ms, and for the >>>>>> second request it is 832ms. Why is this huge time difference? >>>>>> >>>>>> -Aswath >>>>>> >>>>>> >>>> >> -- You received this message because you are subscribed to the Google Groups "Google App Engine" group. To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine+unsubscr...@googlegroups.com. To post to this group, send email to google-appengine@googlegroups.com. Visit this group at http://groups.google.com/group/google-appengine. For more options, visit https://groups.google.com/groups/opt_out.
