Hey David, 5000 ms is excessive for container startup. You say this happens before your code starts to run, but the warnings you're seeing from FinalizableReferenceQueue come from a dependency on our datastore API, which you can clearly see in your stacktrace. Some questions for you:
1) Are you absolutely sure you're not running app code which is causing this delay? Try hitting just an empty servlet or filter. 2) Can you reproduce this latency consistently? 3) What is your appid? On Tue, Sep 8, 2009 at 5:33 AM, David Given <d...@cowlark.com> wrote: > > If I make a request to my app, and (I assume) AppEngine decides it needs > to start up a new servlet instance for me, then warming up the server > can take about 5000ms. Is this normal? > > For example, the first two items in my log for a request will be: > > 09-08 12:57AM 30.917 [standard notification of incoming request] > 09-08 12:57AM 35.344 > > com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue$SystemLoader > loadFinalizer: Not allowed to access system class loader. > > Note the five second difference between the two timestamps. This all > happens before my app has even started running any code. As this only > happens the first time, it's not really a problem, but does cause nasty > red warning banners in my logs. > > Possibly related, the first time I do a database request in one of these > new servers, I'm getting the following scary backtrace. Everything > *works* --- it's just a warning. Can I safely ignore it or is this a > symptom of something wrong with my code? > > 09-08 12:57AM 35.361 > > com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue > <init>: Failed to start reference finalizer thread. Reference cleanup > will only occur when new references are created. > java.lang.reflect.InvocationTargetException > at > com.google.appengine.runtime.Request.process-5d48060cebaffe54(Request.java) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) > at java.lang.reflect.Method.invoke(Method.java:40) > at > > com.google.appengine.repackaged.com.google.common.base.FinalizableReferenceQueue.<init>(FinalizableReferenceQueue.java:124) > at > > com.google.appengine.repackaged.com.google.common.labs.misc.InterningPools$WeakInterningPool.<clinit>(InterningPools.java:104) > at > > com.google.appengine.repackaged.com.google.common.labs.misc.InterningPools.newWeakInterningPool(InterningPools.java:48) > at > > com.google.appengine.repackaged.com.google.io.protocol.ProtocolSupport.<clinit>(ProtocolSupport.java:55) > at > > com.google.apphosting.api.DatastorePb$GetRequest.freeze(DatastorePb.java:7233) > at > > com.google.apphosting.api.DatastorePb$GetRequest$1.<init>(DatastorePb.java:7177) > at > > com.google.apphosting.api.DatastorePb$GetRequest.<clinit>(DatastorePb.java:7174) > at > > com.google.appengine.api.datastore.DatastoreServiceImpl.get(DatastoreServiceImpl.java:90) > at > > com.google.appengine.api.datastore.DatastoreServiceImpl.get(DatastoreServiceImpl.java:69) > at > > com.google.appengine.api.datastore.DatastoreServiceImpl.get(DatastoreServiceImpl.java:57) > at > > com.cowlark.stellation2.server.db.GAEPersistenceInterface.atomicallyModify(GAEPersistenceInterface.java:130) > at > > com.cowlark.stellation2.server.db.GAEPersistenceInterface.lock(GAEPersistenceInterface.java:160) > at > com.cowlark.stellation2.server.db.ServerDB.lock(ServerDB.java:110) > at > com.cowlark.stellation2.server.RPCServiceImpl.ping(RPCServiceImpl.java:81) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) > at java.lang.reflect.Method.invoke(Method.java:40) > at > com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:527) > at > > com.google.gwt.user.server.rpc.RemoteServiceServlet.processCall(RemoteServiceServlet.java:166) > at > > com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) > 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:487) > at > > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093) > at > > com.google.apphosting.runtime.jetty.SaveSessionFilter.doFilter(SaveSessionFilter.java:35) > at > > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084) > at > > com.google.apphosting.utils.servlet.TransactionCleanupFilter.doFilter(TransactionCleanupFilter.java:43) > at > > org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084) > at > org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360) > at > org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) > at > org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181) > at > org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712) > at > org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405) > at > > com.google.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:237) > at > org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139) > at org.mortbay.jetty.Server.handle(Server.java:313) > at > org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506) > at > > org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:830) > at > > com.google.apphosting.runtime.jetty.RpcRequestParser.parseAvailable(RpcRequestParser.java:76) > at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381) > at > > com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:139) > at > > com.google.apphosting.runtime.JavaRuntime.handleRequest(JavaRuntime.java:235) > at > > com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:4950) > at > > com.google.apphosting.base.RuntimePb$EvaluationRuntime$6.handleBlockingRequest(RuntimePb.java:4948) > at > > com.google.net.rpc.impl.BlockingApplicationHandler.handleRequest(BlockingApplicationHandler.java:24) > at > com.google.net.rpc.impl.RpcUtil.runRpcInApplication(RpcUtil.java:359) > at com.google.net.rpc.impl.Server$2.run(Server.java:823) > at > > com.google.tracing.LocalTraceSpanRunnable.run(LocalTraceSpanRunnable.java:56) > at > > com.google.tracing.LocalTraceSpanBuilder.internalContinueSpan(LocalTraceSpanBuilder.java:516) > at com.google.net.rpc.impl.Server.startRpc(Server.java:778) > at com.google.net.rpc.impl.Server.processRequest(Server.java:351) > at > > com.google.net.rpc.impl.ServerConnection.messageReceived(ServerConnection.java:437) > at > com.google.net.rpc.impl.RpcConnection.parseMessages(RpcConnection.java:319) > at > com.google.net.rpc.impl.RpcConnection.dataReceived(RpcConnection.java:290) > at > com.google.net.async.Connection.handleReadEvent(Connection.java:428) > at > > com.google.net.async.EventDispatcher.processNetworkEvents(EventDispatcher.java:762) > at > com.google.net.async.EventDispatcher.internalLoop(EventDispatcher.java:207) > at > com.google.net.async.EventDispatcher.loop(EventDispatcher.java:101) > at > com.google.net.rpc.RpcService.runUntilServerShutdown(RpcService.java:251) > at > > com.google.apphosting.runtime.JavaRuntime$RpcRunnable.run(JavaRuntime.java:392) > at java.lang.Thread.run(Unknown Source) > Caused by: java.security.AccessControlException: access denied > (java.lang.RuntimePermission modifyThreadGroup) > at java.security.AccessControlContext.checkPermission(Unknown > Source) > at java.security.AccessController.checkPermission(Unknown Source) > at java.lang.SecurityManager.checkPermission(Unknown Source) > at java.lang.ThreadGroup.checkAccess(Unknown Source) > at java.lang.Thread.init(Unknown Source) > at java.lang.Thread.<init>(Unknown Source) > at > > com.google.appengine.repackaged.com.google.common.base.internal.Finalizer.<init>(Finalizer.java:96) > at > > com.google.appengine.repackaged.com.google.common.base.internal.Finalizer.startFinalizer(Finalizer.java:82) > ... 66 more > > > -- > ┌─── ｄｇ＠ｃｏｗｌａｒｋ．ｃｏｍ ───── http://www.cowlark.com ───── > │ > │ "They laughed at Newton. They laughed at Einstein. Of course, they > │ also laughed at Bozo the Clown." --- Carl Sagan > > > > --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Google App Engine for Java" group. To post to this group, send email to google-appengine-java@googlegroups.com To unsubscribe from this group, send email to google-appengine-java+unsubscr...@googlegroups.com For more options, visit this group at http://groups.google.com/group/google-appengine-java?hl=en -~----------~----~----~----~------~----~------~--~---
