google-app-enginegoogle-cloud-datastoreappstats

Does this exception imply that appstats are locking up my appengine app?


My app has been purring along for a month with only the occasional deadline exceeded exception. This morning, in a space of five minutes, I had 150 deadline exceeded exceptions. Now it's back to normal. I understand that this can just happen, and isn't necessarily going to be resolved by anything that I do in my code, but every single exception has appstats in the stack trace (at least the 20 I looked at most carefully). On one hand, this implicates appstats - on the other hand, I guess appstats is probably in every single stack trace that ever runs. I'm trying to determine if appstats was the problem.

I'm not an expert with filters - can anyone tell me if a stack trace like the one below implies that the code was waiting in appstats for a long time? It seems like it does mean that, but I thought maybe filters are chained together in such a way that confuses the stack trace. Also, even if it was waiting in appstats - it seems like the problem might be datastore unavailability (no problems evident on the global appengine status page).

I put asterisks at the beginning of the obvious appstats calls for quick scanning.

javax.servlet.ServletContext log: Exception while dispatching incoming RPC call
com.google.gwt.user.server.rpc.UnexpectedException: Service method 'public abstract com.activegrade.shared.dto.ResultDTO com.activegrade.client.serviceinterfaces.CourseOperationService.getCourseList(com.activegrade.shared.dto.AuthInfo)' threw an unexpected exception: com.google.apphosting.api.DeadlineExceededException: This request (1ff876185c635baf) started at 2010/11/30 14:35:47.278 UTC and was still executing at 2010/11/30 14:36:16.261 UTC.
    at com.google.gwt.user.server.rpc.RPC.encodeResponseForFailure(RPC.java:378)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:581)
    at com.google.gwt.user.server.rpc.RemoteServiceServlet.processCall(RemoteServiceServlet.java:207)
    at com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:243)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:713)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:806)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
  **at com.google.appengine.tools.appstats.AppstatsFilter.doFilter(AppstatsFilter.java:140)**
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:97)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.runtime.jetty.SaveSessionFilter.doFilter(SaveSessionFilter.java:35)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
    at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:238)
    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:135)
    at com.google.apphosting.runtime.JavaRuntime.handleRequest(JavaRuntime.java:261)
    at com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:8486)
    at com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:8484)
    at com.google.net.rpc.impl.BlockingApplicationHandler.handleRequest(BlockingApplicationHandler.java:24)
    at com.google.net.rpc.impl.RpcUtil.runRpcInApplication(RpcUtil.java:418)
    at com.google.net.rpc.impl.Server$RpcTask.runInContext(Server.java:572)
    at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:448)
    at com.google.tracing.TraceContext.runInContext(TraceContext.java:688)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:326)
    at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:318)
    at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:446)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:636)
Caused by: com.google.apphosting.api.DeadlineExceededException: This request (1ff876185c635baf) started at 2010/11/30 14:35:47.278 UTC and was still executing at 2010/11/30 14:36:16.261 UTC.
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
  **at com.google.appengine.tools.appstats.RecordingFuture.get(RecordingFuture.java:99)
  **at com.google.appengine.tools.appstats.RecordingFuture$ExtendedFuture.get(RecordingFuture.java:44)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:42)
    at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:42)
    at com.google.appengine.api.datastore.FutureHelper.getInternal(FutureHelper.java:71)
    at com.google.appengine.api.datastore.FutureHelper.quietGet(FutureHelper.java:32)
    at com.google.appengine.api.datastore.QueryResultsSourceImpl.loadMoreEntities(QueryResultsSourceImpl.java:69)
    at com.google.appengine.api.datastore.QueryResultsSourceImpl.loadMoreEntities(QueryResultsSourceImpl.java:56)
    at com.google.appengine.api.datastore.QueryResultIteratorImpl.ensureLoaded(QueryResultIteratorImpl.java:156)
    at com.google.appengine.api.datastore.QueryResultIteratorImpl.hasNext(QueryResultIteratorImpl.java:65)
    at org.datanucleus.store.appengine.DatastoreElementContainerStoreSpecialization.getChildren(DatastoreElementContainerStoreSpecialization.java:105)
    at org.datanucleus.store.appengine.DatastoreFKListStore.listIterator(DatastoreFKListStore.java:48)
    at org.datanucleus.store.mapped.scostore.AbstractListStore.listIterator(AbstractListStore.java:84)
    at org.datanucleus.store.mapped.scostore.AbstractListStore.iterator(AbstractListStore.java:74)
    at org.datanucleus.sco.backed.List.loadFromStore(List.java:241)
    at org.datanucleus.sco.backed.List.initialise(List.java:190)
    at org.datanucleus.sco.SCOUtils.newSCOInstance(SCOUtils.java:183)
    at org.datanucleus.store.mapped.mapping.AbstractContainerMapping.replaceFieldWithWrapper(AbstractContainerMapping.java:426)
    at org.datanucleus.store.mapped.mapping.AbstractContainerMapping.postFetch(AbstractContainerMapping.java:444)
    at org.datanucleus.store.appengine.DatastorePersistenceHandler.runPostFetchMappingCallbacks(DatastorePersistenceHandler.java:510)
    at org.datanucleus.store.appengine.DatastorePersistenceHandler.fetchObject(DatastorePersistenceHandler.java:489)
    at org.datanucleus.store.appengine.query.DatastoreQuery.entityToPojo(DatastoreQuery.java:565)
    at org.datanucleus.store.appengine.DatastoreRelationFieldManager.lookupOneToOneChild(DatastoreRelationFieldManager.java:320)
    at org.datanucleus.store.appengine.DatastoreRelationFieldManager.fetchRelationField(DatastoreRelationFieldManager.java:274)
    at org.datanucleus.store.appengine.DatastoreFieldManager.fetchObjectField(DatastoreFieldManager.java:289)
    at org.datanucleus.state.AbstractStateManager.replacingObjectField(AbstractStateManager.java:1197)
    at com.activegrade.server.dao.Course.jdoReplaceField(Course.java)
    at com.activegrade.server.dao.Course.jdoReplaceFields(Course.java)
    at org.datanucleus.state.JDOStateManagerImpl.replaceFields(JDOStateManagerImpl.java:2772)
    at org.datanucleus.state.JDOStateManagerImpl.replaceFields(JDOStateManagerImpl.java:2791)
    at org.datanucleus.store.appengine.DatastorePersistenceHandler.fetchObject(DatastorePersistenceHandler.java:480)
    at org.datanucleus.store.appengine.query.DatastoreQuery.entityToPojo(DatastoreQuery.java:565)
    at org.datanucleus.store.appengine.query.DatastoreQuery.entityToPojo(DatastoreQuery.java:520)
    at org.datanucleus.store.appengine.query.DatastoreQuery.access$300(DatastoreQuery.java:110)
    at org.datanucleus.store.appengine.query.DatastoreQuery$6.apply(DatastoreQuery.java:638)
    at org.datanucleus.store.appengine.query.DatastoreQuery$6.apply(DatastoreQuery.java:630)
    at org.datanucleus.store.appengine.query.LazyResult.resolveNext(LazyResul

Solution

  • Appstats inserts instrumentation into the App Engine stack, in order to time all the RPC calls your app makes. Since DeadlineExceeded errors are thrown by the RPC, Appstats will always be in the stack. The call in question wasn't made by appstats - it was simply recording it.