-
1. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
sfcoy Mar 27, 2012 7:50 AM (in response to ablet)Some of the deltas in the log file timestamps smell like garbage collection.
17:35:00,812 WARN [org.hibernate.mapping.RootClass] (MSC service thread 1-3) HHH000038: ...
17:35:17,875 WARN [org.hibernate.mapping.RootClass] (MSC service thread 1-3) HHH000039: ...Thats a 17 second pause. Are you sure that you have enough memory allocated?
I would think that 80 modules would need a substantial slab of memory.
-
2. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
smarlow Mar 27, 2012 9:55 AM (in response to ablet)If its not a memory issue, I think a few different possible ways of investigating could be:
1. Enable TRACE logging for org.hibernate, org.jboss.jpa, org.jboss.as.jpa and do further analysis of the log timestamps (as Stephen did above).
2. Sprinkle the code with more print statements to see where the most time is spent.
3. Profile the code in a Java profiler.
4. Something else that others might suggest...
Depending on how much time and effort you can put into this, we can discuss the best path. I think (1) is the easiest/quickest to try next.
I hope Stephen is right, increasing memory and then investigating what is in memory, would be a good win.
-
3. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 27, 2012 11:34 PM (in response to ablet)Yup, seems its related to the Memory Issue and GC, I got this error this time i run the JBOSS:
09:35:07,155 INFO [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (MSC service thread 1-3) HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jta.CMTTransactionFactory
09:35:07,155 INFO [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (MSC service thread 1-3) HHH000397: Using ASTQueryTranslatorFactory
09:36:51,421 INFO [org.jboss.jpa] (MSC service thread 1-1) JBAS011402: Starting Persistence Unit Service 'icba10.ear/icba10-kern-overriding-ejb.jar#entityManager'
09:36:51,421 INFO [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-1) HHH000204: Processing PersistenceUnitInfo [
name: entityManager
...]
09:39:11,436 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC00001: Failed to start service jboss.persistenceunit."icba10.ear/icba10-kern-overriding-ejb.jar#entityManager": org.jboss.msc.service.StartException in service jboss.persistenceunit."icba10.ear/icba10-kern-overriding-ejb.jar#entityManager": Failed to start service
at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1780) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_29]
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
at java.beans.Introspector.decapitalize(Introspector.java:264) [:1.6.0_29]
at org.hibernate.annotations.common.reflection.java.JavaXProperty.getName(JavaXProperty.java:56)
at org.hibernate.cfg.PropertyInferredData.getPropertyName(PropertyInferredData.java:104)
at org.hibernate.cfg.AnnotationBinder.fillComponent(AnnotationBinder.java:2332)
at org.hibernate.cfg.AnnotationBinder.mapAsIdClass(AnnotationBinder.java:862)
at org.hibernate.cfg.AnnotationBinder.bindClass(AnnotationBinder.java:669)
at org.hibernate.cfg.Configuration$MetadataSourceQueue.processAnnotatedClassesQueue(Configuration.java:3406)
at org.hibernate.cfg.Configuration$MetadataSourceQueue.processMetadata(Configuration.java:3360)
at org.hibernate.cfg.Configuration.secondPassCompile(Configuration.java:1334)
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1724)
at org.hibernate.ejb.EntityManagerFactoryImpl.<init>(EntityManagerFactoryImpl.java:76)
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:905)
at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:890)
at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:73)
at org.jboss.as.jpa.service.PersistenceUnitServiceImpl.createContainerEntityManagerFactory(PersistenceUnitServiceImpl.java:149)
at org.jboss.as.jpa.service.PersistenceUnitServiceImpl.start(PersistenceUnitServiceImpl.java:79)
at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1824) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1759) [jboss-msc-1.0.1.GA.jar:1.0.1.GA]
... 3 more09:39:11,436 INFO [org.jboss.jpa] (MSC service thread 1-1) JBAS011402: Starting Persistence Unit Service 'icba10.ear/icba10-cbs-routing-ejb.jar#entityManager'
09:39:11,452 INFO [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-1) HHH000204: Processing PersistenceUnitInfo [I run the JBoss with this JVM memory allocation Parameter:
"JAVA_OPTS=-Xms512M -Xmx1024M -XX:MaxPermSize=256M"
On my PC still there is around 1GB memory left untouched then why i am getting such error?
-
4. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 28, 2012 5:44 AM (in response to ablet)I tried to run JBoss with follwoing JVM parameters in order to do further Garbage Collection analysis:
JAVA_OPTS=-Xms512M -Xmx1024M -XX:MaxPermSize=256M -Xloggc:gclogs.txt -XX:+PrintGCDetails"
Then, I could see the time is mainly taking up by the process of "Unloading class":
12:10:46,827 WARN [org.hibernate.dialect.Oracle9Dialect] (MSC service thread 1-2) HHH000063:
12:10:46,843 INFO [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (M
12:10:46,843 INFO [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (MSC service th
[Unloading class sun.reflect.GeneratedConstructorAccessor6]
[Unloading class sun.reflect.GeneratedConstructorAccessor20]
[Unloading class sun.reflect.GeneratedConstructorAccessor24]
[Unloading class sun.reflect.GeneratedConstructorAccessor7]
[Unloading class sun.reflect.GeneratedConstructorAccessor23]
[Unloading class sun.reflect.GeneratedConstructorAccessor25]
[Unloading class sun.reflect.GeneratedConstructorAccessor27]
[Unloading class sun.reflect.GeneratedConstructorAccessor26]
[Unloading class sun.reflect.GeneratedConstructorAccessor88]
[Unloading class sun.reflect.GeneratedMethodAccessor6]
[Unloading class sun.reflect.GeneratedConstructorAccessor47]
[Unloading class sun.reflect.GeneratedConstructorAccessor16]
[Unloading class sun.reflect.GeneratedConstructorAccessor40]
[Unloading class sun.reflect.GeneratedMethodAccessor14]
....
12:12:50,709 INFO [org.jboss.jpa] (MSC service thread 1-4) JBAS011402: Starting Persistence
12:12:50,709 INFO [org.hibernate.ejb.Ejb3Configuration] (MSC service thread 1-4) HHH000204:I also have GC log generated with the help of parameters (-Xloggc:gclogs.txt -XX:+PrintGCDetails) which is attached here.
-
gclogs.txt.zip 8.9 KB
-
-
5. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
sfcoy Mar 28, 2012 2:33 AM (in response to ablet)What happens if you double the memory?
I suspect that the "[Unloading class ..." messages are side effect of garbage collection btw.
-
6. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 28, 2012 5:41 AM (in response to sfcoy)I have 3,5 GB Memory on my pc, and when the JBOSS is run still 1GB is left untouched. However, i am looking for another system here around wth higher memory to test the deployment.
Anyway, I like you know that I deploy and run the same application on the same system with JBoss 4.3.
Thanks for your help.
-
7. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ctomc Mar 28, 2012 5:52 AM (in response to ablet)what if you add/change settings for PermGen
to:
-XX:PermSize=256M -XX:MaxPermSize=512M
--
tomaz
-
8. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 28, 2012 6:19 AM (in response to ctomc)I tested it with: -XX:MaxPermSize=512M
The result is the same: Slow and Error is: Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
-
9. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
sfcoy Mar 28, 2012 6:38 AM (in response to ablet)The gclog indicated that permgen space was not an issue.
How many ejb's in each module?
-
10. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ctomc Mar 28, 2012 8:17 AM (in response to ablet)did you try with also with -XX:PermSize=256M
this will prevent full gc before expanding PermGen to limits defined by MaxPermSize
-
11. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
smarlow Mar 28, 2012 10:30 AM (in response to ablet)If you guys get stuck, perhaps it would help to look at what is in memory by capturing a heap dump (or a few dump files), that could be looked at with the Eclipse Memory Analyzer tool. I would capture the heap dump when you know that deployment is thrashing on memory (or at least you think it is).
1. Get the list of java processes with command "jps -l"
look for the output line containing jboss-modules.jar (e.g. ProcessID jboss-as-7.1.2.Final-SNAPSHOT/jboss-modules.jar)
2. Generate the heap dump(s)
jmap -dump:live,format=b,file=heapdump.hprof ProcessID
3. Run MAT tool on the heap dump and see what the memory hog(s) are. You probably cannot upload the heapdump files because they could contain your app data. But you could attach some screen shots.
Scott
-
12. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 29, 2012 4:31 AM (in response to sfcoy)Stephan, at the current stage of the application, numbers of ejbs inside modules varies from 1 to around 15 EJBs. Depends on the type of the modules. and most of the ejbs have less than 5 ejbs.
Tomaz, yes, i tried running JBoss with -XX:PermSize=256M, same problem there but there is slight diffierence on error message:
Caused by: java.lang.OutOfMemoryError: Java heap space
Scott, I have not experience on capturing heap dump, i try to do what you said and share with you what i got.
It's great of you guys helping us here. I really appreciate it.
-
13. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
ablet Mar 29, 2012 4:39 AM (in response to ablet)I played with this parameter several times, and following is the best out come i got.
set "JAVA_OPTS=-Xms512M -Xmx1384M -XX:PermSize=128M -XX:MaxPermSize=128M
application got deployed successfully whithin 7mints .. still Lower than Jboss 4.3.
-
14. Re: Startup Goes Very Slow with Scanning Entity Classes from Different Jars
sfcoy Mar 29, 2012 6:52 AM (in response to ablet)I think you may need to consider almalgamating some of your EJB modules.
This is the effect that you would have had in JBoss 4.3 and it's "big ball of mud" classloader.
How many different persistence units are there?
I think each EJB module will be loading it's own copy...