Hi, today I noticed sporadic requests in our Google AppEngine application failing with either a HardDeadlineExceededError or a DeadlineExceededException. This seemed odd since all we did was deploy GWT clientside changes.
Luckily the debugging output for our application is enabled and I found these messages from Guice: D 2011-08-03 11:47:25.179 com.google.inject.internal.util.$Stopwatch resetAndLog: Module execution: 2096ms D 2011-08-03 11:47:25.182 com.google.inject.internal.util.$Stopwatch resetAndLog: Interceptors creation: 3ms D 2011-08-03 11:47:25.190 com.google.inject.internal.util.$Stopwatch resetAndLog: TypeListeners creation: 8ms D 2011-08-03 11:47:25.267 com.google.inject.internal.util.$Stopwatch resetAndLog: Scopes creation: 77ms D 2011-08-03 11:47:25.268 com.google.inject.internal.util.$Stopwatch resetAndLog: Converters creation: 1ms D 2011-08-03 11:47:25.317 com.google.inject.internal.util.$Stopwatch resetAndLog: Binding creation: 49ms D 2011-08-03 11:47:25.319 com.google.inject.internal.util.$Stopwatch resetAndLog: Private environment creation: 2ms D 2011-08-03 11:47:25.319 com.google.inject.internal.util.$Stopwatch resetAndLog: Injector construction: 0ms D 2011-08-03 11:47:25.464 com.google.inject.internal.BytecodeGen newFastClass: Loading class com.google.inject.servlet.ManagedFilterPipeline FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:25.929 com.google.inject.internal.BytecodeGen newFastClass: Loading class com.google.inject.servlet.ManagedServletPipeline FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:25.941 com.google.inject.internal.util.$Stopwatch resetAndLog: Binding initialization: 622ms D 2011-08-03 11:47:25.942 com.google.inject.internal.util.$Stopwatch resetAndLog: Binding indexing: 1ms D 2011-08-03 11:47:25.943 com.google.inject.internal.util.$Stopwatch resetAndLog: Collecting injection requests: 1ms D 2011-08-03 11:47:25.947 com.google.inject.internal.util.$Stopwatch resetAndLog: Binding validation: 4ms D 2011-08-03 11:47:25.951 com.google.inject.internal.BytecodeGen newFastClass: Loading class com.google.inject.servlet.GuiceFilter FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:26.370 com.google.inject.internal.BytecodeGen newFastClass: Loading class nl.presenter.goofur.server.util.SessionRegister FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:26.381 com.google.inject.internal.BytecodeGen newFastClass: Loading class nl.presenter.goofur.server.namespace.NamespaceCenter FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:26.479 com.google.inject.internal.BytecodeGen newFastClass: Loading class nl.presenter.goofur.server.acl.ServerAcl FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:26.646 com.google.inject.internal.BytecodeGen newFastClass: Loading class nl.presenter.goofur.server.util.DAO FastClass with com.google.apphosting.runtime.security.UserClassLoader@1de4376 D 2011-08-03 11:47:26.663 com.google.inject.internal.util.$Stopwatch resetAndLog: Static validation: 716ms D 2011-08-03 11:47:26.664 com.google.inject.internal.util.$Stopwatch resetAndLog: Instance member validation: 1ms D 2011-08-03 11:47:26.666 com.google.inject.internal.util.$Stopwatch resetAndLog: Provider verification: 2ms D 2011-08-03 11:47:49.137 com.google.inject.internal.util.$Stopwatch resetAndLog: Static member injection: 22471ms D 2011-08-03 11:47:49.138 com.google.inject.internal.util.$Stopwatch resetAndLog: Instance injection: 1ms D 2011-08-03 11:47:49.141 com.google.inject.internal.util.$Stopwatch resetAndLog: Preloading singletons: 3ms Notice the extremely long times recorded for Module Execution, Static Validation and Static Injection. I have no idea where these times are coming from, since our GuiceServletModule only statically injects four classes, each with just a single reference to the NamespaceManager in GAE. Another funny thing is that the AppEngine log is reporting a request time of 30+ seconds, but only around 6 seconds cpu-time. This seems to indicate that most of the delay is actually CPU wait time... Does anyone have any idea what is going on here, or better yet, what I can do to try and fix this? Any help is appreciated! -- You received this message because you are subscribed to the Google Groups "google-guice" 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-guice?hl=en.
