| Summary: | Startup of server with EDS installed is very slow when ModeShape is initializing | ||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [JBoss] JBoss Enterprise SOA Platform 5 | Reporter: | Van Halbert <vhalbert> | ||||||||||||||||||
| Component: | EDS | Assignee: | Van Halbert <vhalbert> | ||||||||||||||||||
| Status: | CLOSED NEXTRELEASE | QA Contact: | |||||||||||||||||||
| Severity: | urgent | Docs Contact: | |||||||||||||||||||
| Priority: | urgent | ||||||||||||||||||||
| Version: | 5.2.0 ER1 | CC: | bbelovic, jpechane, rhauch, vhalbert | ||||||||||||||||||
| Target Milestone: | --- | ||||||||||||||||||||
| Target Release: | 5.2.0 GA, 5.2.0.ER5 | ||||||||||||||||||||
| Hardware: | Unspecified | ||||||||||||||||||||
| OS: | Unspecified | ||||||||||||||||||||
| URL: | http://jira.jboss.org/jira/browse/SOA-3193 | ||||||||||||||||||||
| Whiteboard: | |||||||||||||||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||||||||||||||
| Doc Text: | Story Points: | --- | |||||||||||||||||||
| Clone Of: | Environment: | ||||||||||||||||||||
| Last Closed: | 2011-10-21 11:33:32 UTC | Type: | Bug | ||||||||||||||||||
| Regression: | --- | Mount Type: | --- | ||||||||||||||||||
| Documentation: | --- | CRM: | |||||||||||||||||||
| Verified Versions: | Category: | --- | |||||||||||||||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||||||||||||
| Attachments: |
|
||||||||||||||||||||
|
Description
Van Halbert
2011-07-20 15:32:44 UTC
Link: Added: This issue depends MODE-1224 Something else I found, is that it appears the database is being setup twice. There's 2 separate times in the server.log that hibernate is configuring the modeshape tables. Attachment: Added: server.log Added a workaround. BTW, I disagree with the premise of this issue being marked as CRITICAL. The extra time is being taken by ModeShape (and Hibernate) to validate and/or update the schema to have the expected structure, due to the 'autoGenerateSchema' value of 'update'. This might be perfectly fine for testing and/or prototyping, but such a value should *NEVER* be used for production. Instead, the database should be manually configured (using DDL generated using ModeShape's utility, optimized by hand for the given database environment) and the 'autoGenerateSchema' value should be set to 'disable'. See the note at the very end of [Section 12|http://docs.jboss.org/modeshape/latest/manuals/reference/html/jdbc-storage-connector.html] (just before Section 12.1 starts) in our Reference Guide. I will continue to work MODE-1227 to reduce this time and to ensure we are not doing anything unexpected, but the configured described above should never be experienced by a real customer. Workaround Description: Added: # change the 'autoGenerateSchema' value to 'disable'; # generate the DDL for PostgreSQL (or the appropriate DBMS) using ModeShape's DDL generation tool; # manually optimize the schema for the particular installation/configuration of PostgreSQL; and # and manually set up the PostgreSQL database by running the DDL Workaround: Added: [Workaround Exists] Workaround Description: Removed: # change the 'autoGenerateSchema' value to 'disable'; # generate the DDL for PostgreSQL (or the appropriate DBMS) using ModeShape's DDL generation tool; # manually optimize the schema for the particular installation/configuration of PostgreSQL; and # and manually set up the PostgreSQL database by running the DDL Added: # generate the DDL for PostgreSQL (or the appropriate DBMS) using ModeShape's DDL generation tool; # manually optimize the schema for the particular installation/configuration of PostgreSQL; # manually set up the PostgreSQL database by running the DDL; and # change the 'autoGenerateSchema' value to 'disable'; The scripts are already present. The issue would never happen if ModeShape would use them for db initialization in the same way as for example jBPM and jUDDI do. MODE-1224 was closed after several improvements were committed and merged into the 'master' and '2.5.x' branches. See MODE-1224 for details of the changes. Note that there still will be some time during startup spent establishing a connection to the database, but this time will be noticeably longer when 'autoGenerateSchema' is set to 'update' or even 'validate' than when set to 'disable' and the database is manually configured. At this time, _the majority of the connection time is spent on_ [this line|https://github.com/ModeShape/modeshape/blob/master/extensions/modeshape-connector-store-jpa/src/main/java/org/modeshape/connector/store/jpa/JpaSource.java#L1238], _which is literally just setting up the Hibernate configuration and creating the JPA EntityManagerFactory_. Also, specifying a location on the file system for the search indexes is also very important for a shorter startup. Yes, the attached configuration does have the correct settings here, so that's good. I've closed MODE-1224 for now. If this issue (SOA-3193) is not deemed fixed or the startup times are still not sufficient, then feel free to reopen this issue. However, since the majority of startup time is spent in Hibernate, I'm not sure what else I'll be able to do on the ModeShape side. Release Notes Docs Status: Added: Not Required Writer: Added: dlesage I tried 'update' and 'disable' setting with latest SOA-P and in both cases there was 6 minute gap in server startup. Len to find out if this is same or worse than 5.1. Attachment: Added: server_hsql.log Attachment: Added: server_mysql.log Configuration changed by using the schema tool to point to mysql Attachment: Added: modeshape-config.xml I didn't see the same behavior or time, but I was using mysql. I was seeing 2.75 to 3.5 mins for startup. What I did notice, based on the description above ... 10:27:42,431 INFO [SchemaUpdate] schema update complete ... is that when I changed the modeshape-config.xml setting: mode:autoGenerateSchema="disable" the logs didn't contain the TABLEMETADATA or SCHEMAUPDATE log entries during startup. Indicating, that modeshape did disable checking/updating the schema. It appears with the configuration used above, there must have been something wrong with the configuration file. I should have mentioned that I'm running on my laptop with the default jvm settings jboss-as. Attaching configuration file with autoGenerateSchema property set to 'disable'. Attachment: Added: modeshape-config.xml.2 Is the SOA-P er4 server being run from a mounted (remote) driver? I think no, SOA-P ER4 and mysql server are both on the same drive (HDD). What's happening after the
{code}
13:30:21,758 INFO [RepositoryQueryManager] Completed rebuilding indexes for repository 'eds'
{code}
line and before the next line
{code}
13:39:43,620 INFO [ModeShapeEngine] Completed starting the "eds" repository
{code}
is that ModeShape is loading all of the CND files listed in the configuration, and this requires a fair amount of interaction with the database. We probably need to investigate why that is taking so long on your (virtualized?) machine, while Van sees virtually no time between these calls on his local machine.
Would you mind re-running this with the out-of-the-box ModeShape configuration? Your configuration has a few extra sources, and although I don't expect them to be interfering (they shouldn't even be used), I would like to isolate what exactly is causing the problem.
Can you also post the configuration for the "java:ModeShapeEDSRepo" data source? I wonder if there is some limitation there (e.g., maybe too small max connections in the pool).
I re-run server with Modeshape's out-of-the box configuration file and that gap is still there. I should notice that I doing this on my local machine (company laptot), I am not using virtualized hardware or remote server. Attached server.log, Modeshape's configuration file and modeshape-eds-ds.xml Attachment: Added: server.log.tar.bz2 Attachment: Added: modeshape-config.xml.3 Attachment: Added: modeshape-eds-store-ds.xml We tried running it on a RHEL server and are seeing some delays as well. Thanks for re-running and posting the info. To be more specific, my latest attachments were: server.log.tar.bz2 modeshape-config.xml.3 modeshape-eds-store-ds.xml Working with Randall, we've been able to duplicate the delay. He's made some improvements on re-start, however, initial startup will continue to take longer. This is a factor of the number of .cnd's that are to be loaded. When I removed all but 1 .cnd entry in the configuration file, you can see the start up time below (note the new registering log entry that tracks time of loading the .cnd's) 2011-09-23 15:35:45,490 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Started rebuilding indexes for repository 'eds' 2011-09-23 15:37:41,046 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Completed rebuilding indexes for repository 'eds' 2011-09-23 15:37:51,326 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:39:16,844 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Completed registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:39:16,844 INFO [org.modeshape.repository.ModeShapeEngine] (modeshape-start-repo-2-thread-1) Completed starting the "eds" repository 2011-09-23 15:39:16,861 INFO [org.modeshape.jboss.managed.JNDIManagedRepositories] (main) ModeShape Repositories bound to JNDI at name "jcr/local". When I include all the .cnd's the default configuration provides, you do encounter the delay, as show below: 2011-09-23 15:06:44,391 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Started rebuilding indexes for repository 'eds' 2011-09-23 15:08:39,948 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Completed rebuilding indexes for repository 'eds' 2011-09-23 15:08:56,678 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:16:30,674 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Completed registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:16:30,675 INFO [org.modeshape.repository.ModeShapeEngine] (modeshape-start-repo-2-thread-1) Completed starting the "eds" repository And on the subsequent restart, you do see the performance improvement: 2011-09-23 15:27:54,565 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Started rebuilding indexes for repository 'eds' 2011-09-23 15:27:56,036 INFO [org.modeshape.jcr.RepositoryQueryManager] (pool-16-thread-1) Completed rebuilding indexes for repository 'eds' 2011-09-23 15:28:05,822 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:28:05,866 INFO [org.modeshape.jcr.JcrEngine] (modeshape-start-repo-2-thread-1) Completed registering the node types defined in the configuration for the "eds" repository 2011-09-23 15:28:05,866 INFO [org.modeshape.repository.ModeShapeEngine] (modeshape-start-repo-2-thread-1) Completed starting the "eds" repository Also, part of the increase in time this release is because there's been new sequencers and their corresponding .cnd files added. In addition to the changes made to reduce the re-start times, we also made a few minor changes to reduce the time required to register the node types upon the first-time initialization of the repository. Tests that use ModeShape with a local PostgreSQL database shows reduced times for register node types, from 11+ seconds to about between 6-7 seconds. Hopefully this will have a similarly significant effect on the startup when using a remote database, when the total times are longer. For details, see MODE-1224. How do they do it? They use DatabaseInitializer class. http://anonsvn.jboss.org/repos/labs/labs/jbossesb/branches/JBESB_4_10_CP/product/rosetta/src/org/jboss/internal/soa/esb/dependencies/DatabaseInitializer.java Our initialization logic is far more complicated than just inserting a handful of statements. We can move to this style in the future (maybe for 6.0), but not for 5.2. Link: Added: This issue relates to MODE-1275 Created a jira to request the change to use the DatabaseInitializer class. Verified in ER5 |