AppEngine extremely slow

[Marcin]

Hi, 

I am experiencing extremely long response times for a couple of hours now. I am using GAE/J. 

I can provide app id via email.

My app has billing enabled and is using SSL VIP.

This affects both requests with API calls and static resources like images:

Static image:

ms=2655 cpu_ms=0

Controller with API calls displaying dashboard:

ms=8430 cpu_ms=131

For a list of activities 131 cpu_ms seems like a good result, but why does the whole request last for 8.5secs?

Other odd things that I have noticed:

- My resident / reserved instance is missing - I have only dynamic ones, there was always a permanent instance with green shield icon.

- After disabling and reenabling the application I always get

/_ah/warmup 500 87610ms 0kb - 90 seconds to start an instance? I'm not using Spring, it usually took about 7 secs to spin a new one.

com.google.apphosting.api.DeadlineExceededException: This request (18f5b04d255c672c) started at 2013/02/08 00:28:56.487 UTC and was still executing at 2013/02/08 00:29:56.229 UTC.
	at java.util.zip.ZipFile.read(Native Method)
	at java.util.zip.ZipFile.access$1200(ZipFile.java:57)
	at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:476)
	at java.util.zip.ZipFile$1.fill(ZipFile.java:259)
	at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:158)
	at java.io.DataInputStream.readFully(DataInputStream.java:195)
	at java.util.jar.JarFile.hasClassPathAttribute(JarFile.java:482)
	at java.util.jar.JavaUtilJarAccessImpl.jarFileHasClassPathAttribute(JavaUtilJarAccessImpl.java:33)
	at sun.misc.URLClassPath$JarLoader.getClassPath(URLClassPath.java:1176)
	at sun.misc.URLClassPath.getLoader(URLClassPath.java:374)
	at sun.misc.URLClassPath.findResource(URLClassPath.java:201)
	at java.net.URLClassLoader$2.run(URLClassLoader.java:379)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findResource(URLClassLoader.java:376)
	at com.google.apphosting.runtime.security.UserClassLoader.findResource(UserClassLoader.java:723)
	at java.lang.ClassLoader.getResource(ClassLoader.java:977)
	at org.mortbay.resource.Resource.newSystemResource(Resource.java:203)
	at org.mortbay.jetty.webapp.WebXmlConfiguration.configureDefaults(WebXmlConfiguration.java:159)
	at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1230)
	at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517)
	at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467)
	at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:219)
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:194)
	at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:134)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:447)
	at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:454)
	at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:461)
	at com.google.tracing.TraceContext.runInContext(TraceContext.java:703)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:338)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:330)
	at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:458)
	at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
	at java.lang.Thread.run(Thread.java:679)

Uncaught exception from servlet
javax.servlet.UnavailableException: Initialization failed.
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:228)
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:194)
	at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:134)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:447)
	at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:454)
	at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:461)
	at com.google.tracing.TraceContext.runInContext(TraceContext.java:703)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:338)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:330)
	at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:458)
	at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
	at java.lang.Thread.run(Thread.java:679)

We are starting to consider moving out of App Engine. This issue and the thing that our users tend to hit cold instances every n requests makes it not suitable for our need

Marcin

[John V Denley]

I am having the same problem this morning, none of my users can log in...

http://www.diarybooker.com/Login/admin
javax.servlet.ServletException: com.google.apphosting.api.DeadlineExceededException: This request (4a04ab7d507513bc) started at 2013/02/08 13:01:01.116 UTC and was still executing at 2013/02/08 13:02:00.857 UTC.
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:268)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:326)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
	at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:923)
	at com.google.apphosting.runtime.jetty.RpcRequestParser.parseAvailable(RpcRequestParser.java:76)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
	at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:146)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:447)
	at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:454)
	at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:461)
	at com.google.tracing.TraceContext.runInContext(TraceContext.java:703)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:338)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:330)
	at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:458)
	at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
	at java.lang.Thread.run(Thread.java:679)

[John V Denley]

Also Just noticed this which REALLY doesn't seem right!!

Total number of instances	Average QPS*	Average Latency*	Average Memory
0 total	Unknown	Unknown ms	Unknown MBytes

On Friday, 8 February 2013 01:04:45 UTC, Marcin wrote:

[John V Denley]

I just adjusted my instance setting so the number of idle instances was 3-24 and the pending latency was 0-500ms 

and suddenly everything seemed to kick into action...

I changed my settings back to auto-auto and auto-auto its not working again....

more tests...

[John V Denley]

Sorry for all the updates, hopefully someone will find it useful though!!

Latency is through the roof! - what is causing this?! can I fix it?...

Total number of instances	Average QPS*	Average Latency*	Average Memory

7 total (3 Resident)

0.002

33671.0 ms

68.9 MBytes

Instances 

QPS*	Latency*	Requests	Errors	Age	Memory	Logs	Availability	Shutdown
0.000	0.0 ms	3	0	0:04:20	67.0 MBytes	View Logs	Resident
0.000	0.0 ms	12	0	0:04:20	67.8 MBytes	View Logs	Resident
0.017	33671.0 ms	1	0	0:01:28	52.0 MBytes	View Logs	Resident
0.000	0.0 ms	2	0	0:02:23	55.3 MBytes	View Logs	Dynamic
0.000	0.0 ms	14	0	0:04:10	68.5 MBytes	View Logs	Dynamic
0.000	0.0 ms	2	0	0:02:01	67.4 MBytes	View Logs	Dynamic
0.000	0.0 ms	29	0	0:07:19	104.1 MBytes	View Logs	Dynamic

[Marcin]

Hi, thanks for the updates,

it looked similar for me yestarday, fortunately it is OK now, or maybe I should say - for now.

It is a little fishy for me, there obviously was a problem, but none of the system status tools did show that something bad is happening...

The other thing is that I cannot understand one thing, and you seem to have the same issue:

You have 3 resident instances, why new dynamic ones are created? Why don't the resident instances take the requests?

Looking at the table attached by you:

Sum of requests - dynamic instances: 47

Sum of requests - resident instances: 15

It's the same for me, even if I add 5 resident instances, only one of them is serving the requests, 4 are idle and new dynamic instances are created to serve those requests that should go to additional resident ones.

This is odd and makes reserving instances pointless.

Marcin

[John V Denley]

Still having trouble this morning... looking back historically too I notice my "errors per second" also started going nuts about 24 hours ago... what have you changed Google?!

--
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-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Visit this group at http://groups.google.com/group/google-appengine?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Sudip Mukherjee]

Hi
Same here. My application (paid with identifier : vectortracking) is also having the same issue since 09/02 onwards. And surprisingly if i redeploy it then the errors are gone for atleast 24 hours.

Regards
Sudip

On Sunday, February 10, 2013 10:30:50 PM UTC+5:30, scarlatine wrote:

Hi,
I encounter the same trouble since Friday (application identifier: commanderepas), when GAE try to create a new instance I have a "DeadlineExceededException" in the log. It says that the request is still executing after 60 seconds, but usually (when GAE is in good shape), this request take less than ten seconds. A few requests have succeeded Saturday at the end of the morning (in France), but on the afternoon the DeadlineExceededException was back. What can I do?
Thanks...

P.S.: I have had same trouble during a weed-end at the end of December, but on Monday everything was running well again.

[doright]

yes, I'm experiencing an un-usable app this morning 'mybikeshopmanager' on GAE/J

lots of 'deadline exceeded exception' for even the simplest task.

but as John reports, you wouldn't know from looking at the SystemStatus.

Please give us some feedback Google.

[John V Denley]

This issue has been raised with google:

http://code.google.com/p/googleappengine/issues/detail?id=8806&q=latency&sort=-opened&colspec=ID%20Type%20Component%20Status%20Stars%20Summary%20Language%20Priority%20Owner%20Log%20Opened

please add in your own comments and +1's :D

On Friday, 8 February 2013 01:04:45 UTC, Marcin wrote: