huge difference in hot deploy times on Weblogic for 2.5.5 vs 2.0.8 [SPR-4990]

[spring-projects-issues]

Jorg Heymans opened SPR-4990 and commented

Hi,

I upgraded one of my 2.0.8 applications to Spring 2.5.5 just by replacing the old spring-2.0.8.jar with the new spring-2.5.5.jar and spring-webmvc-2.5.5.jar. As a result, the hot deploy times increased drastically. The application was otherwise unmodified , so we're definitely not using any specific 2.5.5 features (i.e. component-scanning)

Here are some timings from my local machine (win xp), the application is deployed as an unpacked WAR in Weblogic's autodeploy directory. I hotdeployed the app 5 times in sequence, without making any request to the application in between. Timings are taken from the "Root WebApplicationContext: initialization completed in X ms" message. The server was restarted and WLS jar caches were cleared in between runs.

2.0.8 (ms)
6562
6000
5969
6844
6894

2.5.5 (ms) 27203 28532 32141 34345 32562

There is an almost 500% increase in deploy time. Also, I noticed that the 2.5.5 deployment time seems to increase with the number of times deployed (it went as high as 38s).

http://forum.springframework.org/showthread.php?p=188252 seems to indicate something similar, but he's using component-scanning.

If there is anything I can do to troubleshoot this or provide more information let me know.

Thanks, Jorg Heymans

---

Affects: 2.5.5

Attachments:

• output.log (291.91 kB)
• outputGC.log (110.27 kB)
• outputGC2.log (462.37 kB)
• weblogic9.2MP2-spring2.0.8.z01 (9.00 MB)
• weblogic9.2MP2-spring2.0.8.z02 (9.00 MB)
• weblogic9.2MP2-spring2.0.8.zip (77.47 kB)
• weblogic9.2MP2-spring2.5.5.z01 (9.00 MB)
• weblogic9.2MP2-spring2.5.5.zip (8.93 MB)

1 votes, 4 watchers

[spring-projects-issues]

Jorg Heymans commented

"The server was restarted and WLS jar caches were cleared in between runs."

----> clarification: i did not restart the server for each hotdeploy ofcourse, only once after switching from 2.0.8 to 2.5.5

[spring-projects-issues]

Jorg Heymans commented

I have a yourkit cpu trace log available for both versions. I won't attach them here because of their size, but if they can be of help let me know and I'll post them somewhere. Doing a comparison of the 2 snapshot logs reveals some interesting information in terms of what methods are adding the additional time during hot deploy. I don't know enough about the Spring core though to interpret the results meaningfully.

[spring-projects-issues]

Juergen Hoeller commented

Hi Jorg,

I'd definitely like to have a look at those logs. Let me know about your preferred way to make them available. You could simply send me an email if you want...

Juergen

[spring-projects-issues]

David.Turing commented

First: Could open the deployment Debug Log on WebLogic Server? You can enable the flags MasterDeployer, SlaveDeployer, DeploymentTaskRuntime, DeployerRuntime, ApplicationContainer. Please note that these debug flags need to be enabled as parameters in the start script to the weblogic.Debug as it does not work in the ServerDebug Mbean. You need to add the following to your JAVA_OPTIONS in your start script to enable the weblogic.MasterDeployer, for example: -Dweblogic.Debug=weblogic.MasterDeployer If you want to enable more flags they can be comma separated like: -Dweblogic.Debug=weblogic.MasterDeployer,weblogic.SlaveDeployer Make sure the StdoutDebugEnabled is set to "true". You could verify this in config.xml. Debug to stdout may be enabled via the console or via the command-line using: -Dweblogic.StdoutDebugEnabled=true

Second: You can use pslist and get thread details of the java process on Windows. pslist is available from: http://www.microsoft.com/technet/sysinternals/utilities/pslist.mspx

1. Run pslist -d \ and redirect the output to a file.
2. Do this for several iterations so you can see a pattern. You should see the "User Time" and "Kernel Time" increasing.
3. Take thread dumps of the WLS server over several iterations.
4. Take the Thread ID # from Step 1 that seems to be increasing, change the decimal value to a hex value (You can use the Calc function in Windows).
5. Examine the thread dump for the "nid=0x<Your Hex Value from Step 3>" until you find the offending thread.

David.Turing BEA WebLogic Support

[spring-projects-issues]

Jorg Heymans commented

@Juergen: trace logs attached as splitted zip files, hope that's ok.

@David:

• i enabled the debug settings as you said, but the WLS console does not show any particularly useful information. Also, i'm only getting \ level info. Can I lower this to obtain more logging?
• for the pslist stuff: I don't really understand step 5 , what tool should I use to examine the thread dump ? i can get the thread info with pslist but it doesn't tell me much. Anything particular i should look out for ?

Thanks Jorg

[spring-projects-issues]

David.Turing commented

Dear Jorg As you are using win xp, your could press CTRL+BREAK(every 5 seconds) to generate the Thread Dump on DOS Windows directly, the same effect as above 5 steps. I need to figure out what's going on between Hot Deploy.

[spring-projects-issues]

Jorg Heymans commented

thread dumps during container startup and a subsequent hotdeploy.

[spring-projects-issues]

David.Turing commented

Jorg, from the thread dump, i see J2EE-Deployment-task-poller has been go into sleep, this could be a problem. "J2EE-Deployment-task-poller" daemon prio=6 tid=0x34be3330 nid=0xe38 waiting on condition [0x358cf000..0x358cfc68] at java.lang.Thread.sleep(Native Method) at weblogic.deploy.api.spi.deploy.internal.ServerConnectionImpl$TaskPoller.run(ServerConnectionImpl.java:1034)

You need to open the VerboseGC on JVM. I need to analysis the GC Time between REDEPLOY, and you could tell me your JVM Options, such as PermSize.

[spring-projects-issues]

Jorg Heymans commented

David,

Sorry for the delay.

From my WLS startup script:

set JAVA_OPTIONS=-Dweblogic.StdoutDebugEnabled=true -Dweblogic.Debug=weblogic.MasterDeployer,weblogic.application,weblogic.J2EEApplication,weblogic.SlaveDeployer,weblogic.DeploymentTaskRuntime,weblogic.DeployerRuntime,weblogic.ApplicationContainer Xverify:none -Xdebug -Xrunjdwp:server=y,transport=dt_socket,address=8899,suspend=n -XX:MaxPermSize=256m -verbose:gc

I have attached the output of the server startup followed by a hotdeploy. No requests were made to the application.

HTH Jorg

[spring-projects-issues]

Jorg Heymans commented

same logfile, but with a few additional hotdeploys. It seems to progressively spend more time doing GC (even a few full GC's are triggered).

Jorg

[spring-projects-issues]

David.Turing commented

Can you reproduce this case to me? Send your war to me please, I need to do some research on it: mail: dhuang(at)bea.com

[spring-projects-issues]

Jorg Heymans commented

Hi,

Any news on this ? I'm happy to supply any additional information or test out new builds etc just let me know. Unfortunately this is preventing us from porting our framework to Spring 2.5.x as it's the slowdown in deployment is really unproductive when developing on WLS 9.2

Thanks Jorg

[spring-projects-issues]

Jon Osborn commented

A couple of comments from me as we use WL 9.2 MP3 w/no issue. Can you try this with jrockit instead of sun? Also, I see you are using MP2. MP3 has many bug fixes including a fairly large memory leak. Since MP2 is not production worthy, can you retry with MP3?

Jon

[spring-projects-issues]

Jorg Heymans commented

Jon, thanks for your comment.

I tested on 92mp3 and the behaviour with increasing deployment time using 2.5.5 has gone away, perhaps this can be attributed to the fixed memory leak you mentioned.

However it still takes a solid 22 seconds to deploy the app using 2.5.5, compared to 8.5s for Spring 2.0.8.

Switching JDK for JROCKIT did not have a noticeable effect when using 2.0.8 , but increased deployment time to 38 seconds for 2.5.5.

---

David, did you manage to have a look with the analysis of the war i sent you ?

[spring-projects-issues]

Jorg Heymans commented

Also, Jon, do you have a documented reference from BEA to the fixed memory leak somewhere ? Does it only occur during deploy/undeploy cycles or does it affect the runtime as well ?

[spring-projects-issues]

Juergen Hoeller commented

I'm still unclear on where Spring 2.5.5 actually behaves differently from 2.0.8... Even if the actual issue here seems to be caused by WLS, Spring obviously does something in a different fashion in 2.5.5; otherwise there wouldn't be such an enormous difference caused in terms of WLS runtime behavior! If you could give me any hints on what Spring 2.5.5 triggers differently there, I'd research the Spring side.

Juergen

[spring-projects-issues]

David.Turing commented

Sorry, I get the comment too late. @Jorg Heymans, I think this is a WebLogic Issue, I can't upzip your the Zip Archive: weblogic9.2MP2-spring2.5.5.zip Can you send your war(2.5.5 and 2.0.8) to me directly. I will try to reproduce it.

[spring-projects-issues]

Jorg Heymans commented

... back from holidays sorry for the delay.

@David i will isolate another smaller testcase that shows the slow behaviour and send it to you directly, either this week or the next.

[spring-projects-issues]

Juergen Hoeller commented

I'm closing this from Spring's side for the time being, assuming that it will be addressed in WebLogic. To be reopened if we find anything that Spring could do better here.

Juergen

[spring-projects-issues]

Jorg Heymans commented

I agree Juergen.

I've sent another testcase to David he is investigating ATM. I'll keep posting any further findings or conclusions in this ticket.

[spring-projects-issues]

Ming Kwok commented

Hi,

I've encountered the same problem. The following is my finding and hope this will help to resolve the issue.

1) 2.0.3 used 400M peak during deployment where 2.5.3 used 800 peak during the deployment. In second case, many full GC take place and causing a huge application pause time.

• The following flag used and reduced the pause time down to within 1 sec. set MEM_ARGS=-Xgc:gencon -Xms:1g -Xmx:1g -Xns:256m 2) The profiling tool indicates that an arrayCopy method has taken 30% of the time for doing Manifest file reading for classloading of jar file. This is only observed in 2.5.3.

• I've found that the new Spring 2.5.3 library contains a suspicious Manifest.MF file which contains some chunky long strings. Replacing the content with the following seems resolved the long delay issue. Manifest-Version: 1.0 Ant-Version: Apache Ant 1.6.5 Created-By: 1.5.0_10-b03 (Sun Microsystems Inc.) Implementation-Title: Spring Framework Implementation-Version: 2.5.3 Spring-Version: 2.5.3 Premain-Class: org.springframework.instrument.InstrumentationSavingAgent

-Ming

[spring-projects-issues]

Julien Dubois commented

Thanks Ming!

This is exactly what happened to me at a client site : it looks like Weblogic 10 has problems with big MANIFEST.MF files, which causes it to be really slow at startup time. Removing the MANIFEST.MF files has solved the problem.

[spring-projects-issues]

Ming Kwok commented

Hi,

May I know what would be the impact of removing content of the MANIFEST.MF file from development perspective. Would it cause the application not working?

FYI, I've submitted a change request to Oracle BEA for this issue.

-Ming

[spring-projects-issues]

Jorg Heymans commented

I guess the only thing would be that the Spring jar would no longer be "OSGI" compliant, otherwise i don't see an impact.

[spring-projects-issues]

Julien Dubois commented

No impact at all in my opinion : Weblogic is not an OSGi container (it might "do" OSGi internally, but it does not provide this capabilty to the applications deployed on it, unlike dm Server for instance). So as Jorg says, the only thing is that your Spring JARs won't be OSGi compliant, but as Weblogic cannot use it anyway, there is no impact.

And I agree this is indeed a Weblogic bug - which is not specific to Spring at all, as more and more people are providing OSGi-compliant JARs nowadays.