Slow startup

[Willie Loyd Tandingan <ta...@gmail.com>]

Hello,

We are running on Apache Isis 1.11.0 and our persistable classes have
already gone in the range of 40~ split across multiple JARs while still
using hsqldb for development. I noticed that startup time in IDEA has
reached over 70 seconds and most of time is spent in initializing
DataNucleus. VisualVM CPU profiling at startup yielded the following
results (screenshot at [1]):

================================
Hot Spots - Method Self Time [%] Self Time Total Time Invocations
org.apache.isis.core.runtime.system.IsisSystem.init() 0.10048878
59.673 ms 56810.706
ms 1
org.apache.isis.core.runtime.system.persistence.PersistenceSessionFactory.init()
0.0000067359633 0.004 ms 23296.049 ms 1
org.apache.isis.core.runtime.system.persistence.PersistenceSessionFactory.createDataNucleusApplicationComponents(org.apache.isis.core.commons.config.IsisConfiguration)
0.014691136 8.724 ms 23296.045 ms 1
org.apache.isis.core.runtime.system.persistence.DataNucleusApplicationComponents.<init>(org.apache.isis.core.commons.config.IsisConfiguration,
java.util.Map, java.util.Set) 0.00003873179 0.023 ms 23244.987 ms 1
org.apache.isis.core.runtime.system.persistence.DataNucleusApplicationComponents.initialize()
0.000026943853 0.016 ms 23244.964 ms 1
org.apache.isis.core.runtime.system.persistence.DataNucleusApplicationComponents.createPmfAndSchemaIfRequired(java.util.Set,
java.util.Map) 0.000774636 0.46 ms 22503.88 ms 1
org.apache.isis.core.runtime.system.persistence.DataNucleusApplicationComponents.createSchema(javax.jdo.PersistenceManagerFactory,
java.util.Set, java.util.Map) 0.00007746358 0.046 ms 18327.657 ms 1
org.datanucleus.store.rdbms.RDBMSStoreManager.createSchemaForClasses(java.util.Set,
java.util.Properties) 0.038295634 22.741 ms 18320.481 ms 1
org.datanucleus.store.rdbms.AbstractSchemaTransaction.execute(org.datanucleus.ClassLoaderResolver)
0.000181871 0.108 ms 18264.045 ms 1
org.datanucleus.store.rdbms.RDBMSStoreManager$ClassAdder.run(org.datanucleus.ClassLoaderResolver)
0.000321642 0.191 ms 18263.19 ms 1
org.datanucleus.store.rdbms.RDBMSStoreManager$ClassAdder.addClassTables(String[],
org.datanucleus.ClassLoaderResolver) 0.000599501 0.356 ms 17435.615 ms 1
org.datanucleus.api.jdo.metadata.JDOMetaDataManager.getMetaDataForClassInternal(Class,
org.datanucleus.ClassLoaderResolver) 0.01417415 8.417 ms 17429.163 ms 453
org.datanucleus.metadata.MetaDataManagerImpl.getMetaDataForClass(Class,
org.datanucleus.ClassLoaderResolver) 0.013027353 7.736 ms 17326.69 ms 9087
org.datanucleus.metadata.MetaDataManagerImpl.getReferencedClasses(String[],
org.datanucleus.ClassLoaderResolver) 0.000328378 0.195 ms 17325.453 ms 1
org.datanucleus.ClassLoaderResolverImpl.getResources(String, ClassLoader)
14.340284 8515.655 ms 16876.542 ms 2346
org.datanucleus.api.jdo.metadata.JDOMetaDataManager.loadXMLMetaDataForClass(Class,
org.datanucleus.ClassLoaderResolver, String, String,
org.datanucleus.metadata.MetadataFileType, boolean) 0.024424603 14.504
ms 16872.089
ms 146
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.internalLoadSpecification(Class)
0.022504853 13.364 ms 13151.5 ms 96513
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.loadSpecificationForSubstitutedClass(Class)
0.054052737 32.098 ms 13055.562 ms 96513
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.introspectIfRequired(org.apache.isis.core.metamodel.spec.ObjectSpecification)
0.001650311 0.98 ms 12849.15 ms 470
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.introspect(org.apache.isis.core.metamodel.specloader.specimpl.ObjectSpecificationAbstract)
0.002126881 1.263 ms 12848.861 ms 470
org.apache.isis.core.metamodel.specloader.specimpl.dflt.ObjectSpecificationDefault.introspectTypeHierarchyAndMembers()
0.010546834 6.263 ms 12797.89 ms 469
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.init(org.apache.isis.core.metamodel.runtimecontext.RuntimeContext)
0.000018523899 0.011 ms 12607.389 ms 1
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.initialize(org.apache.isis.core.metamodel.runtimecontext.RuntimeContext)
0.000119563 0.071 ms 12605.973 ms 1
org.apache.isis.core.metamodel.specloader.ObjectReflectorDefault.loadSpecificationsForServices()
0.001987109 1.18 ms 12500.942 ms 1
org.apache.isis.applib.fixturescripts.FixtureScript.run(String)
0.000107775 0.064
ms 12444.698 ms 4
org.datanucleus.metadata.MetaDataManagerImpl.loadAnnotationsForClass(Class,
org.datanucleus.ClassLoaderResolver, boolean, boolean) 0.013047561
7.748 ms 12436.37
ms 98
org.apache.isis.applib.fixturescripts.FixtureScript$ExecutionContext.access$200(org.apache.isis.applib.fixturescripts.FixtureScript.ExecutionContext,
org.apache.isis.applib.fixturescripts.FixtureScript) 0.000011787935
0.007 ms 12433.691
ms 4
org.apache.isis.applib.fixturescripts.FixtureScript$ExecutionContext.executeChildIfNotAlready(org.apache.isis.applib.fixturescripts.FixtureScript)
0.04790617 28.448 ms 12433.683 ms 30
org.apache.isis.applib.fixturescripts.FixtureScript$ExecutionContext.executeChild(org.apache.isis.applib.fixturescripts.FixtureScript,
org.apache.isis.applib.fixturescripts.FixtureScript) 0.00004209977
0.025 ms 12404.436
ms 26
org.apache.isis.applib.fixturescripts.FixtureScript$ExecutionContext.executeChildT(org.apache.isis.applib.fixturescripts.FixtureScript,
org.apache.isis.applib.fixturescripts.FixtureScript) 0.00002357587
0.014 ms 12404.413
ms 26
org.apache.isis.applib.fixturescripts.FixtureScript$ExecutionContext.executeChildT(org.apache.isis.applib.fixturescripts.FixtureScript,
String, org.apache.isis.applib.fixturescripts.FixtureScript) 0.000304802 0.181
ms 12404.398 ms 26
org.datanucleus.metadata.MetaDataManagerImpl.populateFileMetaData(org.datanucleus.metadata.FileMetaData,
org.datanucleus.ClassLoaderResolver, ClassLoader) 0.000373846 0.222 ms
11962.332
ms 48
org.datanucleus.metadata.MetaDataManagerImpl.populateAbstractClassMetaData(org.datanucleus.metadata.AbstractClassMetaData,
org.datanucleus.ClassLoaderResolver, ClassLoader) 0.07717225 45.827 ms
11962.091
ms 96
org.apache.isis.core.runtime.system.IsisSystem.initializeServices()
0.024079384 14.299 ms 10671.565 ms 1
org.apache.isis.core.metamodel.specloader.specimpl.dflt.ObjectSpecificationDefault.createActions(java.util.Properties)
0.001310145 0.778 ms 10638.253 ms 406

===============================
Intel Core i5-4570 CPU @ 3.20GHz
16GB DDR3 1800MHz
7200 RPM HDD
================================


Has anyone encountered similar startup time with too many persistable
classes?


Thanks,
Willie

[1] http://imgur.com/QL812e3