What is really strange is that appstats shows that everything is going fine on GAE side though logs shows a very high latency for the same request, check below:
AppStats : <https://lh4.googleusercontent.com/-rKhcWOGN0ms/ULU50mlgXxI/AAAAAAAAwnk/GDrCcqy3gVA/s1600/AppStats+-+VinoCities+Dev+-+Google+Chrome.jpg> Same request in the logs : 1. 2012-11-27 23:03:18.921 /?d=d 200 7591ms 23kb Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.91 Safari/537.11 2. I2012-11-27 23:03:18.720 com.mably.cms.web.PageCacheServlet doGet: At program start we have : 15761400 bytes 3. I2012-11-27 23:03:18.721 com.mably.cms.theme.web.CookieDeviceResolver initRenderDevice: Device = {browser:chrome,type:DESKTOP,bot:false} 4. I2012-11-27 23:03:18.721 com.mably.cms.web.PageCacheServlet doGet: Page is cacheable : home|d|en 5. I2012-11-27 23:03:18.721 com.mably.cms.web.PageCacheUtils getPageCacheFullId: Added to ThreadLocal : fr.filhot.net|default|home|d|en 6. I2012-11-27 23:03:18.748 com.mably.cms.web.HomeServlet verifyPageCache: com.mably.cms.cache.SerializableCacheObject@19bf7d0[object=com.mably.cms.cache.PageCacheData@aaa392,tag 7. I2012-11-27 23:03:18.777 com.mably.cms.web.PageCacheServlet$PageCacheChecker check: In cache, verify OK :fr.filhot.net|default|home|d|en 8. I2012-11-27 23:03:18.778 com.mably.cms.web.PageCacheServlet doGet: After running the program, we have : 14724712 bytes 7591ms instead of 58ms , huge difference no ? I can reproduce the same behavior from home and from work, so it's not related to my internet connection. Why do we have such high latency for this trivial request ? A 7 seconds wait and your users are gone. Any help will be greatly appreciated. François On Tuesday, November 27, 2012 12:31:33 PM UTC+1, Francois Masurel wrote: > > Example of two identical requests doing a simple MemCache fetch with quite > different excecution times 385ms vs 4502ms : > > 1. > > 2012-11-27 12:19:25.809 * > /chateau-de-mouchac-183001.dhtml?m=publications&l=fr&d=d* 200 *385ms*14kb > Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.11 (KHTML, like > Gecko) Chrome/23.0.1271.91 Safari/537.11 > I 2012-11-27 12:19:25.511 com.mably.cms.web.PageCacheServlet doGet: At > program start we have : 20535256 bytes > I 2012-11-27 12:19:25.512 com.mably.cms.theme.web.CookieDeviceResolver > initRenderDevice: Device = {browser:chrome,type:DESKTOP,bot:false} > I 2012-11-27 12:19:25.512 com.mably.cms.web.PageCacheServlet doGet: Page > is cacheable : view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publications|fr|d > I 2012-11-27 12:19:25.512 com.mably.cms.web.PageCacheUtils > getPageCacheFullId: Added to ThreadLocal : mouchac.vinocities.com > |default|view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publicati > I 2012-11-27 12:19:25.520 > com.mably.cms.web.PageCacheServlet$PageCacheChecker check: In cache, verify > OK :mouchac.vinocities.com|default|view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publi > I 2012-11-27 12:19:25.520 com.mably.cms.web.PageCacheServlet doGet: After > running the program, we have : 20071256 bytes > > 2012-11-27 > 12:19:09.395*/chateau-de-mouchac-183001.dhtml?m=publications&l=fr&d=d > * 200 *4502ms* 14kb Mozilla/5.0 (Windows NT 6.1; WOW64) > AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.91 Safari/537.11 > I 2012-11-27 12:19:09.325 com.mably.cms.web.PageCacheServlet doGet: At > program start we have : 23017432 bytes > I 2012-11-27 12:19:09.326 com.mably.cms.theme.web.CookieDeviceResolver > initRenderDevice: Device = {browser:chrome,type:DESKTOP,bot:false} > I 2012-11-27 12:19:09.326 com.mably.cms.web.PageCacheServlet doGet: Page > is cacheable : view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publications|fr|d > I 2012-11-27 12:19:09.327 com.mably.cms.web.PageCacheUtils > getPageCacheFullId: Added to ThreadLocal : mouchac.vinocities.com > |default|view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publicati > I 2012-11-27 12:19:09.338 > com.mably.cms.web.PageCacheServlet$PageCacheChecker check: In cache, verify > OK :mouchac.vinocities.com|default|view|aghzfnZuY3RzMXIJCxIBZBjZlQsM|publi > I 2012-11-27 12:19:09.339 com.mably.cms.web.PageCacheServlet doGet: After > running the program, we have : 22546336 bytes > > > What am I supposed to say to my customers ? > > > > On Tuesday, November 27, 2012 12:11:45 PM UTC+1, Francois Masurel wrote: >> >> Could it also be related to really bad Get latency lately ? >> >> Let's compare today's Java dynamic get latency with April 25 numbers : >> >> Today<http://code.google.com/status/appengine/detail/serving-java/2012/11/27#ae-trust-detail-helloworld-get-java-latency>: >> >> >> >> <https://lh4.googleusercontent.com/-PzOlG7y3TRM/ULSealyN6EI/AAAAAAAAwnM/yiy4jqL72hk/s1600/PrtScr+capture.jpg> >> 04/25/2012<http://code.google.com/status/appengine/detail/serving-java/2012/04/25#ae-trust-detail-helloworld-get-java-latency>: >> >> >> <https://lh5.googleusercontent.com/-lJ3ySBW_ky0/ULSeooDuWkI/AAAAAAAAwnU/NMHkvcNWgqM/s1600/PrtScr+capture_2.jpg> >> In my case, some requests running most of the time in less than 200ms can >> take as much as 7s without any instance loading going on. >> >> When will things start to stabilize a bit so we can run real businesses >> on GAE ? >> >> Am I the only one encountering such problems ? I sometimes feels like >> being on a desert island here :-) >> >> François >> >> >> >> >> On Saturday, November 17, 2012 4:21:28 PM UTC+1, Francois Masurel wrote: >>> >>> I've notice lots of user facing loading requests since a few hours >>> (days?). >>> >>> Just check the screenshot below. Two new instances have been started to >>> serve only 13 (12 + 1) requests though another instance was already running >>> and available and obviously was not overloaded as it had only served 105 >>> requests during the last hour : >>> >>> >>> <https://lh4.googleusercontent.com/-UxI0M8fnvw0/UKep9Wkb_VI/AAAAAAAAwN0/wxKaPhZvXlI/s1600/Instances+-+VinoCities+-+Google+Chrome.jpg> >>> >>> My application instance settings are all set to automatic and pending >>> latency set to 10s : >>> >>> >>> <https://lh4.googleusercontent.com/-TxgVTyTvqJM/UKeqaNNQvBI/AAAAAAAAwN8/fKUP3ftluk8/s1600/Application+Settings+-+VinoCities+-+Google+Chrome.jpg> >>> >>> Did something change on GAE side recently ? >>> >>> These user facing loading requests are really killing my business as my >>> users are getting really upset about it. >>> >>> Thanx for your help. >>> >>> François >>> >>> App Id = vncts1 >>> >> -- You received this message because you are subscribed to the Google Groups "Google App Engine" group. To view this discussion on the web visit https://groups.google.com/d/msg/google-appengine/-/wMcwpiSbuxQJ. To post to this group, send email to google-appengine@googlegroups.com. To unsubscribe from this group, send email to google-appengine+unsubscr...@googlegroups.com. For more options, visit this group at http://groups.google.com/group/google-appengine?hl=en.
