Start time #4
Comments
|
how did you deploy? This looks like an issue you'll get when using mvn clean install I bet the issue goes away if you use mvn clean appengine:update . true? ra On Tue, Apr 9, 2013 at 2:14 PM, Samuel Liard [email protected]:
inc: http://ars-machina.raphaelbauer.com |
|
Yes I run : mvn clean install gae:deploy -Pdeployment But I have the same error with "mvn clean gae:deploy -Pdeployment" and appengine:update don't work (No plugin found for prefix 'appengine') not declare in pom.xml Edit : |
|
On Tue, Apr 9, 2013 at 2:24 PM, Samuel Liard [email protected]:
Hmm. That is strange. I got several applications up and runing on App Can you post all logs? Best, Raphael |
|
You have all logs :) And for other application what is the average load time ? 2013-04-09 14:29:19.139 / 200 12248ms 0kb Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_3) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.43 Safari/537.31 I 2013-04-09 14:29:15.266 I 2013-04-09 14:29:15.537 I 2013-04-09 14:29:16.320 I 2013-04-09 14:29:19.139 |
|
One difference with demo. I add logback : To correct error : But error is still here even without logback : |
|
On Tue, Apr 9, 2013 at 2:32 PM, Samuel Liard [email protected]:
I tried again, but cannot reproduce your issue. I just deployed my app via: and it works fine... this is the appengine module i am using: Maybe you can deploy to a new app version and restart the app. And maybe The startup time of Ninja is limited (I guess) mostly by Guice. And guice Best, Raphael |
|
Worth looking at dagger as well? http://square.github.io/dagger/ |
|
On Tue, Apr 9, 2013 at 5:07 PM, ludoch [email protected] wrote:
Thanks for the zipped project - I'll have a look the next days :) Best, Raphael |
|
On Tue, Apr 9, 2013 at 8:01 PM, Raphael André Bauer
Hi Samuel, I had a look and unfortunately cannot reproduce your issue. I simply imported your project into eclipse, changed my app id and called: you can see your running app here: Best, Raphael |
|
My empty app works, it's not the problem :) And in GAE log we have Info logs with exception : And maybe it's the reason of 13s starting time... Samuel 2013/4/10 Raphael A. Bauer [email protected]:
|
|
Known guice log entry. Very annoying but has no impact: |
|
On Wed, Apr 10, 2013 at 4:09 PM, Samuel Liard [email protected]:
No. That is just an info message saying that guice uses a non thread based And for sure not the reason for 13s startup time :) You have of course take into account that initial loading requests can be Best, Raphael |
|
Startup time is a big problem with GAE due to a bug with idle instance. My experience : Hope that ludoch work on it :) So we have to work to have the minimum startup time. In other case some client have 13s of loading page :( |
|
On Wed, Apr 10, 2013 at 4:34 PM, Samuel Liard [email protected]:
You have to benchmark that against the "minimal" spring and ninja Another "trick" you can do is: Schedule a task that touches one of your Hope that helps, ra |
|
Sample GAE app with 1 servlet takes between 2 and 3 secondes to start. Maybe the faster framework is Slim3 : Look at this article, maybe we can find solution to speed up ninja : And I try your trick with schedule task, it's doesn't work. Idle instance is the solution (without bug...) |
|
Remember that the default setting for an instance is F1: 660Mhz, 128MB memory, 1 core. Dagger has some potential there. I will push for more work at the guice/servlet level to see what could be pre calculated at the GAE SDK level and just used at the frontend level. |
|
Interesting discussion. Startup times on GAE are really important. It's a pity Google/GAE does not provide a optimized framework like they provided for Python with Webapp. Hope to see Google/GAE reach out to framework developers to bring a decent/optimized web framework to GAE one day. Just like @ludoch is mentioning talking to the Guice devs. |
|
@REYEZ as you have deployed ninjaframework apps to GAE, what are the startup times you are seeing? |
|
@marceloverdijk all true. Under the hood Ninja uses Guice what is in general (gut feeling and common sense - no benchmarking) faster than a full fledged spring application. But: The GAE startup still takes time. In my experience the startup speed is also a lot depending on the size of the war file you are uploading. I guess the war has to be unzipped when starting up and that can take a while on a "slow" machine. But - the appengine sdk alone has 40MB... Apart from that check out that thread from @stickfigure - he is very enthusiastic about the startup times - not. https://groups.google.com/forum/?fromgroups#!topic/google-appengine/Nz4Yt8V6PB0 Bottom line: Startup speed can be a problem. Ninja is reasonably "fast" and way fast enough for all apps we built. So for us it is no problem at all... |
|
For my current apps startup times are also not important. They are mainly 'private' apps used by just a couple of users. So 1 instance is enough and I just keep it warm with a cron job. But for a scalable application I would not choose for GAE/J at the moment because of startup times. I also experimented with Python on GAE and there I did not suffer these startup times. |
|
It really seems we can't do much about it. If you are really dependent on startup times either don't use java - or don't use gae :( |
|
@REYEZ indeed take it or leave it :-( |
|
After 4 month of development, we have always a big problem with starting time. The worst is that warmup request don't help. I chose Ninja because I thought that spring was too heavy. But with Spring warmup request load all element and first request is very fast after... no solution to reduce request time ?? |
|
Hey Sam, the message your are seeing regarding "NinjaAppengineEnvironmentNull" is just a note. There is no initialization going on. I am not really sure what to say here. Our startup times are around 15s. What is not great, but our instances are up all the time and as such it is ok for us. So initially we pay 15s (I just benchmarked it again), but then everything is really fast and quick. But I have to admit that 15s startup is really bad. 40s sounds really long. How big is the ".war" you are trying to deploy? What version of Ninja and GAE are you using? If the startup time is "between" 25s and 40s this might be an issue on GAE' servers - but I am just guessing. Other interesting (and possibly disappointing) reads are: I hope that helps a bit... Best, Raphael |
|
You might also want to checkout https://developers.google.com/appengine/docs/adminconsole/performancesettings#Setting_the_Pending_Latency I just played around with some settings and brought down our initial startup time to around 8 secs.. Cheers, Raphael |
|
And another quick update. I just tried with the default settings and a new project based on the ninja-appengine-blog-archetype archetype. The initial loading request (after an update on a F4 instance / automatic latency settings) is around 8 secs. All subsequent requests are ultrafast. Even if the application is not hit by any request for a while. To me it seems that after an update a lot of stuff happens, that really kills performance at the first request to a new version of your app... @ludoch might now more... |
|
At the beginning of the project, the starting time was around 10s and now it's 25s (average). I have a pb with GAE starting time and AOP since long time. I already talked about that in a bar with @ludoch the last time I meet him in SF :) But I think we have also a pb with ninja. Why warmup request don't start all conf ? With warmup : Without warmup (when a request start a new instance) : Can we do something to load all in warmup ? |
|
Hey Sam,
I'd therefore check if there is a difference for you if you start the Guice injector in mode production:
Let us know if that helps... Thanks and cheers, Raphael |
|
It starts to be better ! I found my problem with Production Stage. I just add one line on I don't use ninja for asset management. Still 4,5s for the first request after warmup, but much better than 17s ! Next step is to minimize Injection usage. I will write Poor Old Thx for your help Raphael ! Samuel PS : last log : 2013-08-28 22:20:03.785 /index.do 200 210ms 21kb 2013-08-28 22:19:47.987 /index.do 200 4564ms 21kb 2013-08-28 22:19:36.010 /ah/warmup 200 12226ms 0kb 2013/8/28 Raphael A. Bauer [email protected]:
|
Hi,
Just tried to deploy an application on GAE and the load time is very slow. 9s
I have an Exception, that can explain start time ?
thx
Full trace :
2013-04-09 14:05:28.277 / 200 9225ms 0kb Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_3) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.43 Safari/537.31
5.48.232.156 - - [09/Apr/2013:05:05:28 -0700] "GET / HTTP/1.1" 200 224 - "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_3) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.43 Safari/537.31" "1.testbetw.appspot.com" ms=9225 cpu_ms=5070 cpm_usd=0.000025 loading_request=1 instance=00c61b117c9b676bc5d77a7517e47f1f8d159b03
I 2013-04-09 14:05:23.185
com.google.inject.internal.util.$FinalizableReferenceQueue$SystemLoader loadFinalizer: Not allowed to access system class loader.
I 2013-04-09 14:05:23.192
com.google.inject.internal.util.$FinalizableReferenceQueue : 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-c3a2e572f96e3caa(Request.java)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:43)
at com.google.inject.internal.util.$FinalizableReferenceQueue.(FinalizableReferenceQueue.java:124)
at com.google.inject.internal.util.$MapMaker$QueueHolder.(MapMaker.java:787)
at com.google.inject.internal.util.$MapMaker$WeakEntry.(MapMaker.java:946)
at com.google.inject.internal.util.$MapMaker$Strength$1.newEntry(MapMaker.java:312)
at com.google.inject.internal.util.$MapMaker$StrategyImpl.newEntry(MapMaker.java:498)
at com.google.inject.internal.util.$MapMaker$StrategyImpl.newEntry(MapMaker.java:419)
at com.google.inject.internal.util.$CustomConcurrentHashMap$ComputingImpl.get(CustomConcurrentHashMap.java:2029)
at com.google.inject.internal.Annotations$AnnotationChecker.hasAnnotations(Annotations.java:116)
at com.google.inject.internal.Annotations.isBindingAnnotation(Annotations.java:180)
at com.google.inject.internal.Annotations.findBindingAnnotation(Annotations.java:161)
at com.google.inject.internal.Annotations.getKey(Annotations.java:147)
at com.google.inject.spi.InjectionPoint.(InjectionPoint.java:92)
at com.google.inject.spi.InjectionPoint$InjectableField.toInjectionPoint(InjectionPoint.java:438)
at com.google.inject.spi.InjectionPoint.getInjectionPoints(InjectionPoint.java:723)
at com.google.inject.spi.InjectionPoint.forInstanceMethodsAndFields(InjectionPoint.java:356)
at com.google.inject.spi.InjectionPoint.forInstanceMethodsAndFields(InjectionPoint.java:375)
at com.google.inject.internal.BindingBuilder.toInstance(BindingBuilder.java:82)
at ninja.scheduler.SchedulerSupport$1.configure(SchedulerSupport.java:81)
at com.google.inject.AbstractModule.configure(AbstractModule.java:59)
at com.google.inject.spi.Elements$RecordingBinder.install(Elements.java:223)
at com.google.inject.spi.Elements.getElements(Elements.java:101)
at com.google.inject.internal.InjectorShell$Builder.build(InjectorShell.java:133)
at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:103)
at com.google.inject.Guice.createInjector(Guice.java:95)
at com.google.inject.Guice.createInjector(Guice.java:72)
at ninja.servlet.NinjaBootstap.initInjector(NinjaBootstap.java:141)
at ninja.servlet.NinjaBootstap.boot(NinjaBootstap.java:69)
at ninja.servlet.NinjaServletListener.getInjector(NinjaServletListener.java:52)
at com.google.inject.servlet.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:45)
at ninja.servlet.NinjaServletListener.contextInitialized(NinjaServletListener.java:40)
at org.mortbay.jetty.handler.ContextHandler.startContext(ContextHandler.java:548)
at org.mortbay.jetty.servlet.Context.startContext(Context.java:136)
at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1250)
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.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:480)
at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:487)
at com.google.tracing.TraceContext.runInContext(TraceContext.java:774)
at com.google.tracing.TraceContext$DoInTraceContext.runInContext(TraceContext.java:751)
at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:342)
at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:334)
at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:484)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.security.AccessControlException: access denied (java.lang.RuntimePermission modifyThreadGroup)
at java.security.AccessControlContext.checkPermission(AccessControlContext.java:355)
at java.security.AccessController.checkPermission(AccessController.java:567)
at java.lang.SecurityManager.checkPermission(SecurityManager.java:549)
at java.lang.ThreadGroup.checkAccess(ThreadGroup.java:315)
at java.lang.Thread.init(Thread.java:353)
at java.lang.Thread.(Thread.java:479)
at com.google.inject.internal.util.$Finalizer.(Finalizer.java:92)
at com.google.inject.internal.util.$Finalizer.startFinalizer(Finalizer.java:81)
... 48 more
I 2013-04-09 14:05:25.883
[s~testbetw/1.366550021591110251].: _______ .___ _______ . _____
\ \ | |\ \ | | / _ \
/ | | |/ | \ | |/ /\ \
/ | \ / | /| / |
__| /****|__ /________| /
web/framework / /
I 2013-04-09 14:05:25.883
[s~testbetw/1.366550021591110251].:
I 2013-04-09 14:05:26.162
[s~testbetw/1.366550021591110251].: 12:05:26.101 [Request C854F190] INFO ninja.lifecycle.LifecycleServiceImpl - Starting Ninja application...
I 2013-04-09 14:05:26.567
[s~testbetw/1.366550021591110251].: 12:05:26.567 [Request C854F190] INFO ninja.lifecycle.LifecycleServiceImpl - Ninja application started in 471ms
I 2013-04-09 14:05:28.277
This request caused a new process to be started for your application, and thus caused your application code to be loaded for the first time. This request may thus take longer and use more CPU than a typical request for your application.
The text was updated successfully, but these errors were encountered: