8 Replies Latest reply on Dec 13, 2005 11:12 AM by bill.burke

    Performance problem with embedded EJB :/

    jacekolszak

      Hi everyone...

      I've a really performance problem with embedded EJB - my application starts in 55 seconds (and in about 170 in debug mode). I'm using it for unit testing, so such numbers are not tolerated :(

      I've added all jars to the list of ignored jars, but it didn't improved the start time so much.

      Any ideas how to speed up the execution time of embedded ejb ?

      Regards
      Jacek

        • 1. Re: Performance problem with embedded EJB :/
          bill.burke

          That doesn't seem right at all. How many EJBs/EntityManagers are you deploying? I've done some profiling with a EJB jar and one EntityManager being deployed. It takes 4-5 secs on my machine (3.4 GhZ). 80% of the time is in bootstrapping the kernel. This should be a fixed time. The 20% left, most of it is initializing Hibernate.

          Also, maybe you are not writing your JUnit test correctly and are bootstrapping the container with every test method? Please download Alpha 3 and check out the JUnit example for how to initalize the kernel just once for the entire class run.

          Let me know....

          Bill

          • 2. Re: Performance problem with embedded EJB :/
            jacekolszak

            Hmm.... Maybe I should say that I have 30 entities and 80 stateless beans :) I'm using one entity manager. The same problem with performance I've with my web-application (with embedded ejb3). I've Celeron 2.41 and 1 GB Ram.

            Second thing is the time which takes operations on database - simple request which gets all records from db ( for example 5 records from one table) takes about 15-120ms

            • 3. Re: Performance problem with embedded EJB :/
              slaboure

              Can you post a log file that shows the deploy process with time information?

              • 4. Re: Performance problem with embedded EJB :/
                jacekolszak

                Here is my log:

                15:42:25,432 WARN XsdBinder:1097 - NOT HANDLED WILDCARD IN GLOBAL MODEL GROUP
                15:42:35,525 INFO Environment:474 - Hibernate 3.1 rc1
                15:42:35,540 INFO Environment:504 - hibernate.properties not found
                15:42:35,540 INFO Environment:520 - using CGLIB reflection optimizer
                15:42:35,540 INFO Environment:550 - using JDK 1.4 java.sql.Timestamp handling
                15:42:35,853 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.adresfirmy.AdresFirmy
                15:42:35,868 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.adreskontrahenta.AdresKontrahenta
                15:42:35,900 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.banki.Bank
                15:42:35,915 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.dokksiegowy.DokKsiegowy
                15:42:35,947 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.firma.Firma
                15:42:35,978 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.grupavat.GrupaVat
                15:42:35,993 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kartoteka.Kartoteka
                15:42:36,009 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.konffirma.KonfFirma
                15:42:36,040 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontaktfirma.KontaktFirma
                15:42:36,056 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontaktkontrah.KontaktKontrah
                15:42:36,072 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowe.KontoBankowe
                15:42:36,072 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowefirmy.KontoBankoweFirmy
                15:42:36,087 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowekontrahenta.KontoBankoweKontrahenta
                15:42:36,103 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowepracownika.KontoBankowePracownika
                15:42:36,118 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankoweurzedu.KontoBankoweUrzedu
                15:42:36,134 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontoksiegowe.KontoKsiegowe
                15:42:36,150 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontrahent.Kontrahent
                15:42:36,181 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.odsetki.Odsetki
                15:42:36,197 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.okresewid.OkresEwid
                15:42:36,212 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.panstwo.Panstwo
                15:42:36,243 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.pracownik.Pracownik
                15:42:36,259 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.rokewid.RokEwid
                15:42:36,275 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.strukturaorg.StrukturaOrg
                15:42:36,290 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.strukturawlasnosciowafirmy.StrukturaWlasnosciowaFirmy
                15:42:36,322 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typdokumentu.TypDokumentu
                15:42:36,337 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typdzial.TypDzial
                15:42:36,337 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typkonta.TypKonta
                15:42:36,353 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.urzad.Urzad
                15:42:36,384 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.uzytsys.UzytSys
                15:42:36,400 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.vatstawka.VatStawka
                15:42:36,431 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.waluta.Waluta
                15:42:36,431 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.wojewodztwo.Wojewodztwo
                15:42:36,509 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.users.Uprawnienie
                15:42:36,525 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.users.Uzytkownik
                15:42:37,837 INFO Configuration:1014 - processing extends queue
                15:42:37,837 INFO Configuration:1018 - processing collection mappings
                15:42:37,853 INFO CollectionBinder:459 - Mapping collection: pl.ramzes.ksiegi.firma.Firma.adresy -> AdresFirmy
                15:42:37,853 INFO CollectionBinder:459 - Mapping collection: pl.ramzes.ksiegi.rokewid.RokEwid.okresyEwid -> OkresEwid
                15:42:37,853 INFO Configuration:1027 - processing association property references
                15:42:37,853 INFO Configuration:1049 - processing foreign key constraints
                15:42:38,118 INFO Configuration:1014 - processing extends queue
                15:42:38,118 INFO Configuration:1018 - processing collection mappings
                15:42:38,118 INFO Configuration:1027 - processing association property references
                15:42:38,134 INFO Configuration:1049 - processing foreign key constraints
                15:42:38,150 INFO ConnectionProviderFactory:72 - Initializing connection provider: org.hibernate.ejb.InjectedDataSourceConnectionProvider
                15:42:38,165 INFO InjectedDataSourceConnectionProvider:34 - Using provided datasource
                15:42:38,712 INFO SettingsFactory:77 - RDBMS: PostgreSQL, version: 8.0.4
                15:42:38,728 INFO SettingsFactory:78 - JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 8.0 JDBC3 with SSL (build 311)
                15:42:38,759 INFO Dialect:100 - Using dialect: org.hibernate.dialect.PostgreSQLDialect
                15:42:38,774 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
                15:42:38,774 INFO TransactionManagerLookupFactory:38 - instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
                15:42:38,790 INFO TransactionManagerLookupFactory:42 - instantiated TransactionManagerLookup
                15:42:38,790 INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
                15:42:38,790 INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
                15:42:38,790 INFO SettingsFactory:136 - JDBC batch size: 15
                15:42:38,806 INFO SettingsFactory:139 - JDBC batch updates for versioned data: disabled
                15:42:38,806 INFO SettingsFactory:144 - Scrollable result sets: enabled
                15:42:38,806 INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): disabled
                15:42:38,806 INFO SettingsFactory:160 - Connection release mode: after_statement
                15:42:38,806 INFO SettingsFactory:187 - Default batch fetch size: 1
                15:42:38,806 INFO SettingsFactory:191 - Generate SQL with comments: disabled
                15:42:38,806 INFO SettingsFactory:195 - Order SQL updates by primary key: disabled
                15:42:38,806 INFO SettingsFactory:338 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
                15:42:38,821 INFO ASTQueryTranslatorFactory:21 - Using ASTQueryTranslatorFactory
                15:42:38,821 INFO SettingsFactory:203 - Query language substitutions: {}
                15:42:38,821 INFO SettingsFactory:209 - Second-level cache: enabled
                15:42:38,821 INFO SettingsFactory:213 - Query cache: disabled
                15:42:38,821 INFO SettingsFactory:325 - Cache provider: org.hibernate.cache.HashtableCacheProvider
                15:42:38,821 INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
                15:42:38,821 INFO SettingsFactory:237 - Structured second-level cache entries: disabled
                15:42:38,837 INFO SettingsFactory:264 - Statistics: disabled
                15:42:38,837 INFO SettingsFactory:268 - Deleted entity synthetic identifier rollback: enabled
                15:42:38,837 INFO SettingsFactory:283 - Default entity-mode: POJO
                15:42:39,196 INFO SessionFactoryImpl:155 - building session factory
                15:42:41,352 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
                15:42:41,352 INFO Configuration:1014 - processing extends queue
                15:42:41,368 INFO Configuration:1018 - processing collection mappings
                15:42:41,368 INFO Configuration:1027 - processing association property references
                15:42:41,368 INFO Configuration:1049 - processing foreign key constraints
                15:42:41,368 INFO Configuration:1014 - processing extends queue
                15:42:41,368 INFO Configuration:1018 - processing collection mappings
                15:42:41,368 INFO Configuration:1027 - processing association property references
                15:42:41,368 INFO Configuration:1049 - processing foreign key constraints
                15:42:41,384 INFO SchemaExport:153 - Running hbm2ddl schema export
                15:42:41,384 INFO SchemaExport:180 - exporting generated schema to database
                15:42:49,742 INFO SchemaExport:200 - schema export complete
                15:42:49,742 INFO Configuration:1014 - processing extends queue
                15:42:49,742 INFO Configuration:1018 - processing collection mappings
                15:42:49,742 INFO Configuration:1027 - processing association property references
                15:42:49,742 INFO Configuration:1049 - processing foreign key constraints
                15:42:49,742 INFO Configuration:1014 - processing extends queue
                15:42:49,742 INFO Configuration:1018 - processing collection mappings
                15:42:49,742 INFO Configuration:1027 - processing association property references
                15:42:49,758 INFO Configuration:1049 - processing foreign key constraints
                15:42:49,774 INFO NamingHelper:26 - JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
                15:42:49,789 INFO SessionFactoryImpl:432 - Checking 47 named queries
                15:42:53,742 INFO SessionFactoryImpl:831 - closing
                15:42:53,742 INFO SchemaExport:153 - Running hbm2ddl schema export
                15:42:53,758 INFO SchemaExport:180 - exporting generated schema to database
                15:42:54,914 INFO SchemaExport:200 - schema export complete
                


                Currently it takes about 35 s (30s+5second for initialize log4j and etc.)

                Any ideas how to speed up the execution time?

                • 5. Re: Performance problem with embedded EJB :/
                  bill.burke

                  Well, it looks like it is taking ~ 11 seconds to export the schema from two EntityManagers using hbm2ddl schema export. Maybe you can precreate your schema in the database and shut this feature off in persistence.properties in ejb3.deployer/META-INF/persistence.properties?

                  Another 10 seconds looks like the initialization of the container. (1st 10 seconds). We are working on speeding that up, but it is low priority right now.

                  • 6. Re: Performance problem with embedded EJB :/
                    maxandersen

                    also try and set hibernate.cglib.use_reflection_optimizer property to false (it should also remove a good deal of seconds spent in the creation of the building of your sessionfactory)

                    • 7. Re: Performance problem with embedded EJB :/
                      jacekolszak

                       

                      Well, it looks like it is taking ~ 11 seconds to export the schema from two EntityManagers using hbm2ddl schema export. Maybe you can precreate your schema in the database and shut this feature off in persistence.properties in ejb3.deployer/META-INF/persistence.properties?


                      You mean change hbm2ddl.auto to update instead of create-drop ?


                      also try and set hibernate.cglib.use_reflection_optimizer property to false (it should also remove a good deal of seconds spent in the creation of the building of your sessionfactory)


                      Thanks, I set this.


                      Here is my current log (still not so fast, but it is better than before):
                      10:52:52,472 WARN XsdBinder:1097 - NOT HANDLED WILDCARD IN GLOBAL MODEL GROUP
                      10:53:11,832 INFO Environment:474 - Hibernate 3.1 rc1
                      10:53:11,848 INFO Environment:504 - hibernate.properties not found
                      10:53:11,848 INFO Environment:520 - using CGLIB reflection optimizer
                      10:53:11,848 INFO Environment:550 - using JDK 1.4 java.sql.Timestamp handling
                      10:53:12,004 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.dbf.beans.Konfiguracja
                      10:53:12,035 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.adresfirmy.AdresFirmy
                      10:53:12,051 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.adreskontrahenta.AdresKontrahenta
                      10:53:12,051 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.banki.Bank
                      10:53:12,066 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.dokksiegowy.DokKsiegowy
                      10:53:12,082 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.firma.Firma
                      10:53:12,082 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.grupavat.GrupaVat
                      10:53:12,098 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kartoteka.Kartoteka
                      10:53:12,098 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.konffirma.KonfFirma
                      10:53:12,113 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontaktfirma.KontaktFirma
                      10:53:12,113 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontaktkontrah.KontaktKontrah
                      10:53:12,129 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowe.KontoBankowe
                      10:53:12,129 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowefirmy.KontoBankoweFirmy
                      10:53:12,129 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowekontrahenta.KontoBankoweKontrahenta
                      10:53:12,144 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankowepracownika.KontoBankowePracownika
                      10:53:12,144 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontobankoweurzedu.KontoBankoweUrzedu
                      10:53:12,160 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontoksiegowe.KontoKsiegowe
                      10:53:12,160 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.kontrahent.Kontrahent
                      10:53:12,176 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.odsetki.Odsetki
                      10:53:12,191 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.okresewid.OkresEwid
                      10:53:12,191 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.panstwo.Panstwo
                      10:53:12,207 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.pracownik.Pracownik
                      10:53:12,223 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.rokewid.RokEwid
                      10:53:12,223 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.strukturaorg.StrukturaOrg
                      10:53:12,223 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.strukturawlasnosciowafirmy.StrukturaWlasnosciowaFirmy
                      10:53:12,238 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typdokumentu.TypDokumentu
                      10:53:12,254 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typdzial.TypDzial
                      10:53:12,254 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.typkonta.TypKonta
                      10:53:12,254 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.urzad.Urzad
                      10:53:12,269 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.uzytsys.UzytSys
                      10:53:12,285 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.vatstawka.VatStawka
                      10:53:12,285 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.waluta.Waluta
                      10:53:12,285 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.ksiegi.wojewodztwo.Wojewodztwo
                      10:53:12,316 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.users.Uprawnienie
                      10:53:12,332 INFO Ejb3Configuration:314 - found EJB3 Entity bean: pl.ramzes.users.Uzytkownik
                      10:53:13,144 INFO Configuration:1014 - processing extends queue
                      10:53:13,160 INFO Configuration:1018 - processing collection mappings
                      10:53:13,160 INFO CollectionBinder:459 - Mapping collection: pl.ramzes.ksiegi.firma.Firma.adresy -> AdresFirmy
                      10:53:13,160 INFO CollectionBinder:459 - Mapping collection: pl.ramzes.ksiegi.rokewid.RokEwid.okresyEwid -> OkresEwid
                      10:53:13,160 INFO Configuration:1027 - processing association property references
                      10:53:13,160 INFO Configuration:1049 - processing foreign key constraints
                      10:53:13,379 INFO Configuration:1014 - processing extends queue
                      10:53:13,379 INFO Configuration:1018 - processing collection mappings
                      10:53:13,394 INFO Configuration:1027 - processing association property references
                      10:53:13,394 INFO Configuration:1049 - processing foreign key constraints
                      10:53:13,410 INFO ConnectionProviderFactory:72 - Initializing connection provider: org.hibernate.ejb.InjectedDataSourceConnectionProvider
                      10:53:13,410 INFO InjectedDataSourceConnectionProvider:34 - Using provided datasource
                      10:53:13,441 INFO SettingsFactory:77 - RDBMS: PostgreSQL, version: 8.0.4
                      10:53:13,441 INFO SettingsFactory:78 - JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 8.0 JDBC3 with SSL (build 311)
                      10:53:13,457 INFO Dialect:100 - Using dialect: org.hibernate.dialect.PostgreSQLDialect
                      10:53:13,473 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
                      10:53:13,488 INFO TransactionManagerLookupFactory:38 - instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
                      10:53:13,488 INFO TransactionManagerLookupFactory:42 - instantiated TransactionManagerLookup
                      10:53:13,488 INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
                      10:53:13,488 INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
                      10:53:13,504 INFO SettingsFactory:136 - JDBC batch size: 15
                      10:53:13,504 INFO SettingsFactory:139 - JDBC batch updates for versioned data: disabled
                      10:53:13,504 INFO SettingsFactory:144 - Scrollable result sets: enabled
                      10:53:13,504 INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): disabled
                      10:53:13,504 INFO SettingsFactory:160 - Connection release mode: after_statement
                      10:53:13,504 INFO SettingsFactory:187 - Default batch fetch size: 1
                      10:53:13,504 INFO SettingsFactory:191 - Generate SQL with comments: disabled
                      10:53:13,504 INFO SettingsFactory:195 - Order SQL updates by primary key: disabled
                      10:53:13,504 INFO SettingsFactory:338 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
                      10:53:13,504 INFO ASTQueryTranslatorFactory:21 - Using ASTQueryTranslatorFactory
                      10:53:13,504 INFO SettingsFactory:203 - Query language substitutions: {}
                      10:53:13,504 INFO SettingsFactory:209 - Second-level cache: enabled
                      10:53:13,519 INFO SettingsFactory:213 - Query cache: disabled
                      10:53:13,519 INFO SettingsFactory:325 - Cache provider: org.hibernate.cache.HashtableCacheProvider
                      10:53:13,519 INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
                      10:53:13,519 INFO SettingsFactory:237 - Structured second-level cache entries: disabled
                      10:53:13,535 INFO SettingsFactory:264 - Statistics: disabled
                      10:53:13,535 INFO SettingsFactory:268 - Deleted entity synthetic identifier rollback: enabled
                      10:53:13,535 INFO SettingsFactory:283 - Default entity-mode: POJO
                      10:53:13,754 INFO SessionFactoryImpl:155 - building session factory
                      10:53:15,629 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
                      10:53:15,629 INFO SchemaUpdate:114 - Running hbm2ddl schema update
                      10:53:15,629 INFO SchemaUpdate:126 - fetching database metadata
                      10:53:15,723 INFO SchemaUpdate:142 - updating schema
                      10:53:15,738 INFO Configuration:1014 - processing extends queue
                      10:53:15,738 INFO Configuration:1018 - processing collection mappings
                      10:53:15,738 INFO Configuration:1027 - processing association property references
                      10:53:15,738 INFO Configuration:1049 - processing foreign key constraints
                      10:53:16,645 INFO TableMetadata:40 - table found: public.adresfirmy
                      10:53:16,645 INFO TableMetadata:41 - columns: [panstwo_id, ulica, aktywnyad, wojewodztwo_id, edited, gmina, nrdomu, id, kodmiej, firma_id, removed, datadadresu, rodzajkontaktu, miejscowosc, nrlokalu, adreskores]
                      10:53:16,645 INFO TableMetadata:43 - foreign keys: [fkdac5a27ef5fa1da1, fkdac5a27e5d1dd699, fkdac5a27e265e3dac]
                      10:53:16,645 INFO TableMetadata:44 - indexes: [adresfirmy_pkey]
                      10:53:16,738 INFO TableMetadata:40 - table found: public.adreskontrahenta
                      10:53:16,738 INFO TableMetadata:41 - columns: [ulica, panstwo_id, wojewodztwo_id, edited, gmina, kontrahent_id, nrdomu, id, kodmiej, removed, rodzajkontaktu, miejscowosc, nrlokalu, adreskores]
                      10:53:16,738 INFO TableMetadata:43 - foreign keys: [fkf3f8548265e3dac, fkf3f8548dfec03d6, fkf3f8548f5fa1da1]
                      10:53:16,738 INFO TableMetadata:44 - indexes: [adreskontrahenta_pkey]
                      10:53:16,816 INFO TableMetadata:40 - table found: public.banki
                      10:53:16,816 INFO TableMetadata:41 - columns: [panstwo_id, removed, edited, nazwa, nr, id]
                      10:53:16,816 INFO TableMetadata:43 - foreign keys: [fk3cfd18d265e3dac]
                      10:53:16,816 INFO TableMetadata:44 - indexes: [banki_pkey, banki_nr_key, banki_nazwa_key]
                      10:53:16,926 INFO TableMetadata:40 - table found: public.dokksiegowy
                      10:53:16,926 INFO TableMetadata:41 - columns: [jestnotatka, nrwlasdok, datawlasdok, czykorekta, nrewiddok, edited, terminplatnosci, kontrahent_id, datavat, id, uzytkownik_id, rokewid_id, firma_id, removed, dataksieg, okresewid_id, datawplywu, typdokumentu_id, dataopergosp, opis, nrdokkoryg]
                      10:53:16,926 INFO TableMetadata:43 - foreign keys: [fk5c83518edfec03d6, fk5c83518e5d1dd699, fk5c83518eef117093, fk5c83518e33974a7, fk5c83518e67a0167b, fk5c83518e6e8ab7b1]
                      10:53:16,926 INFO TableMetadata:44 - indexes: [dokksiegowy_pkey]
                      10:53:17,066 INFO TableMetadata:40 - table found: public.firma
                      10:53:17,066 INFO TableMetadata:41 - columns: [knazwa, datardzial, edited, nazwarej, strukturawlasnosci_id, dzial, id, ekd, nrrej, removed, stronawww, image, nip, aktywnosc, regon, platnikvat, pesel, organrej, dnazwa]
                      10:53:17,066 INFO TableMetadata:43 - foreign keys: [fk40be1c3ff7229f8]
                      10:53:17,066 INFO TableMetadata:44 - indexes: [firma_pkey]
                      10:53:17,145 INFO TableMetadata:40 - table found: public.firma_kartoteka
                      10:53:17,145 INFO TableMetadata:41 - columns: [firmy_id, kartoteki_id]
                      10:53:17,145 INFO TableMetadata:43 - foreign keys: [fkec0549c28bbddcec, fkec0549c25d28bf81]
                      10:53:17,145 INFO TableMetadata:44 - indexes: []
                      10:53:17,223 INFO TableMetadata:40 - table found: public.grupavat
                      10:53:17,223 INFO TableMetadata:41 - columns: [aktywna, removed, stawka_id, edited, opiss, typrej, opis, id]
                      10:53:17,223 INFO TableMetadata:43 - foreign keys: [fk2bf884eeafa94f15]
                      10:53:17,223 INFO TableMetadata:44 - indexes: [grupavat_opiss_key, grupavat_pkey]
                      10:53:17,301 INFO TableMetadata:40 - table found: public.kartoteka
                      10:53:17,301 INFO TableMetadata:41 - columns: [removed, nazwakart, edited, opis, id, predef]
                      10:53:17,301 INFO TableMetadata:43 - foreign keys: []
                      10:53:17,301 INFO TableMetadata:44 - indexes: [kartoteka_pkey, kartoteka_nazwakart_key]
                      10:53:17,395 INFO TableMetadata:40 - table found: public.konffirma
                      10:53:17,395 INFO TableMetadata:41 - columns: [edited, datazapisu, id, removed, firma_id, rokewid_id, rozkosztrodzic, automatkk, rozkoszt, dziennikitematyczne, ewidkoszt, metvat, waluta_id]
                      10:53:17,395 INFO TableMetadata:43 - foreign keys: [fke7b6a107b7b1e532, fke7b6a1076e8ab7b1, fke7b6a1075d1dd699]
                      10:53:17,395 INFO TableMetadata:44 - indexes: [konffirma_pkey, konffirma_rokewid_id_key, konffirma_rozkoszt_key, konffirma_firma_id_key, konffirma_waluta_id_key]
                      10:53:17,473 INFO TableMetadata:40 - table found: public.konfiguracja
                      10:53:17,473 INFO TableMetadata:41 - columns: [imported, id]
                      10:53:17,488 INFO TableMetadata:43 - foreign keys: []
                      10:53:17,488 INFO TableMetadata:44 - indexes: [konfiguracja_pkey]
                      10:53:17,566 INFO TableMetadata:40 - table found: public.kontaktfirma
                      10:53:17,566 INFO TableMetadata:41 - columns: [stanowisko, firma_id, nazwisko, removed, pracownik_id, edited, telefons, email, imie, telefonm, id]
                      10:53:17,566 INFO TableMetadata:43 - foreign keys: [fk3950aac35d1dd699, fk3950aac3e2b92b5a]
                      10:53:17,566 INFO TableMetadata:44 - indexes: [kontaktfirma_pkey]
                      10:53:17,645 INFO TableMetadata:40 - table found: public.kontaktkontrah
                      10:53:17,645 INFO TableMetadata:41 - columns: [stanowisko, nazwisko, removed, edited, telefons, email, kontrahent_id, imie, telefonm, id]
                      10:53:17,645 INFO TableMetadata:43 - foreign keys: [fk3a585e8fdfec03d6]
                      10:53:17,645 INFO TableMetadata:44 - indexes: [kontaktkontrah_pkey]
                      10:53:17,754 INFO TableMetadata:40 - table found: public.kontobankowe
                      10:53:17,754 INFO TableMetadata:41 - columns: [cyfrykont, pracownik_id, type, edited, kontrahent_id, urzad_id, id, bank_id, removed, firma_id, nazwa, nrrachunku, aktywnedata, aktywnekonto, waluta_id]
                      10:53:17,754 INFO TableMetadata:43 - foreign keys: [fk508a189cdfec03d6, fk508a189c5d1dd699, fk508a189ce2b92b5a, fk508a189c47378f11, fk508a189cb7b1e532, fk508a189cf81ac36]
                      10:53:17,754 INFO TableMetadata:44 - indexes: [kontobankowe_pkey]
                      10:53:17,848 INFO TableMetadata:40 - table found: public.kontoksiegowe
                      10:53:17,848 INFO TableMetadata:41 - columns: [nrkontaid, edited, czywalutowe, czyvat, rodzic_id, typkonta_id, wieloletnie, rodzajkonta, id, datazal, rokewid_id, removed, poziomkonta, kartoteka_id, nazwad, czydwusaldowe, nazwat, zablokowane, nazwap]
                      10:53:17,848 INFO TableMetadata:43 - foreign keys: [fk16f332bf9cd8d427, fk16f332bf24167e46, fk16f332bf8bba39f4, fk16f332bf6e8ab7b1]
                      10:53:17,848 INFO TableMetadata:44 - indexes: [kontoksiegowe_rokewid_id_key, kontoksiegowe_pkey]
                      10:53:17,941 INFO TableMetadata:40 - table found: public.kontrahent
                      10:53:17,941 INFO TableMetadata:41 - columns: [knazwa, odbiorca, dostawca, datardzial, edited, nazwarej, strukturawlasnosci_id, dzial, id, nrrej, kontrahentstaly, firma_id, removed, stronawww, nip, aktywnosc, regon, pesel, platnikvat, organrej, dnazwa]
                      10:53:17,941 INFO TableMetadata:43 - foreign keys: [fk3e5494fcff7229f8, fk3e5494fc5d1dd699]
                      10:53:17,941 INFO TableMetadata:44 - indexes: [kontrahent_pkey]
                      10:53:18,020 INFO TableMetadata:40 - table found: public.odsetki
                      10:53:18,020 INFO TableMetadata:41 - columns: [removed, dataod, edited, nrtabeli, wartodset, id]
                      10:53:18,020 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,020 INFO TableMetadata:44 - indexes: [odsetki_pkey]
                      10:53:18,082 INFO TableMetadata:40 - table found: public.okresewid
                      10:53:18,082 INFO TableMetadata:41 - columns: [rokewid_id, firma_id, removed, edited, datazammies, miesdataod, nazwa, statuszammies, miesdatado, id]
                      10:53:18,082 INFO TableMetadata:43 - foreign keys: [fk6d9194915d1dd699, fk6d9194916e8ab7b1]
                      10:53:18,098 INFO TableMetadata:44 - indexes: [okresewid_pkey]
                      10:53:18,160 INFO TableMetadata:40 - table found: public.panstwo
                      10:53:18,160 INFO TableMetadata:41 - columns: [removed, kodliczbowy, kod, edited, nazwa, czlonekue, id]
                      10:53:18,160 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,160 INFO TableMetadata:44 - indexes: [panstwo_pkey, panstwo_nazwa_key]
                      10:53:18,238 INFO TableMetadata:40 - table found: public.pracownik
                      10:53:18,238 INFO TableMetadata:41 - columns: [wielkoscud, edited, obywatelstwo, id, firma_id, nazwisko, paszport, datamodyf, nip, udzialowiec, imiematki, plec, imieojca, naziwskop, imie2, dowod, miejsceur, imie1, removed, dataod, nrpracownika, dataur, datado, narodowosc, dowodwyd, pesel]
                      10:53:18,238 INFO TableMetadata:43 - foreign keys: [fk5228d7e45d1dd699]
                      10:53:18,238 INFO TableMetadata:44 - indexes: [pracownik_pkey]
                      10:53:18,316 INFO TableMetadata:40 - table found: public.rokewid
                      10:53:18,316 INFO TableMetadata:41 - columns: [firma_id, removed, edited, nazwa, rokdo, rokod, zablokbo, id, statuszam, datazam]
                      10:53:18,316 INFO TableMetadata:43 - foreign keys: [fkb52de41b5d1dd699]
                      10:53:18,316 INFO TableMetadata:44 - indexes: [rokewid_pkey]
                      10:53:18,395 INFO TableMetadata:40 - table found: public.strukturaorg
                      10:53:18,395 INFO TableMetadata:41 - columns: [poziomdrzewa, firma_id, removed, poprzednia_id, edited, nazwa, schematobow, opisko, id]
                      10:53:18,395 INFO TableMetadata:43 - foreign keys: [fkb3c01a0d5d1dd699, fkb3c01a0dfa4ab124]
                      10:53:18,395 INFO TableMetadata:44 - indexes: [strukturaorg_pkey, strukturaorg_poprzednia_id_key]
                      10:53:18,457 INFO TableMetadata:40 - table found: public.strukturawlasnosciowafirmy
                      10:53:18,457 INFO TableMetadata:41 - columns: [removed, edited, nazwa, id]
                      10:53:18,457 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,457 INFO TableMetadata:44 - indexes: [strukturawlasnosciowafirmy_pkey]
                      10:53:18,520 INFO TableMetadata:40 - table found: public.typdokumentu
                      10:53:18,520 INFO TableMetadata:41 - columns: [domroz, removed, domnagl, edited, aktywnytd, nazwatypdok, id, opistypu, symbol]
                      10:53:18,520 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,520 INFO TableMetadata:44 - indexes: [typdokumentu_pkey, typdokumentu_opistypu_key, typdokumentu_nazwatypdok_key, typdokumentu_symbol_key]
                      10:53:18,598 INFO TableMetadata:40 - table found: public.typdzial
                      10:53:18,598 INFO TableMetadata:41 - columns: [removed, edited, nazwa, id]
                      10:53:18,598 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,598 INFO TableMetadata:44 - indexes: [typdzial_nazwa_key, typdzial_pkey]
                      10:53:18,660 INFO TableMetadata:40 - table found: public.typkonta
                      10:53:18,660 INFO TableMetadata:41 - columns: [removed, edited, nazwatypu, id]
                      10:53:18,660 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,660 INFO TableMetadata:44 - indexes: [typkonta_pkey, typkonta_nazwatypu_key]
                      10:53:18,723 INFO TableMetadata:40 - table found: public.uprawnienie
                      10:53:18,723 INFO TableMetadata:41 - columns: [nazwa, id]
                      10:53:18,723 INFO TableMetadata:43 - foreign keys: []
                      10:53:18,723 INFO TableMetadata:44 - indexes: [uprawnienie_pkey]
                      10:53:18,785 INFO TableMetadata:40 - table found: public.uprawnienie_uzytkownicy
                      10:53:18,801 INFO TableMetadata:41 - columns: [uprawnienia_id, uzytkownicy_id]
                      10:53:18,801 INFO TableMetadata:43 - foreign keys: [fk1916d53296dc6a6, fk1916d53241e1b9cb]
                      10:53:18,801 INFO TableMetadata:44 - indexes: []
                      10:53:18,863 INFO TableMetadata:40 - table found: public.urzad
                      10:53:18,863 INFO TableMetadata:41 - columns: [woj_id, panstwo_id, ulica, kodmiej, removed, nrlokalu, miejscowosc, edited, gmina, nrdomu, id, nazwaurzad]
                      10:53:18,863 INFO TableMetadata:43 - foreign keys: [fk4e37640276a05a, fk4e37640265e3dac]
                      10:53:18,879 INFO TableMetadata:44 - indexes: [urzad_pkey]
                      10:53:18,941 INFO TableMetadata:40 - table found: public.uzytsys
                      10:53:18,941 INFO TableMetadata:41 - columns: [datadodania, firma_id, removed, pracownik_id, login, edited, id]
                      10:53:18,941 INFO TableMetadata:43 - foreign keys: [fk6780060d5d1dd699, fk6780060de2b92b5a]
                      10:53:18,941 INFO TableMetadata:44 - indexes: [uzytsys_pracownik_id_key, uzytsys_pkey]
                      10:53:19,004 INFO TableMetadata:40 - table found: public.uzytkownicy
                      10:53:19,004 INFO TableMetadata:41 - columns: [login, haslo, id]
                      10:53:19,004 INFO TableMetadata:43 - foreign keys: []
                      10:53:19,020 INFO TableMetadata:44 - indexes: [uzytkownicy_pkey]
                      10:53:19,098 INFO TableMetadata:40 - table found: public.vatstawka
                      10:53:19,098 INFO TableMetadata:41 - columns: [removed, dataod, edited, datado, wartosc, nazwa, aktualna, opis, id]
                      10:53:19,098 INFO TableMetadata:43 - foreign keys: []
                      10:53:19,098 INFO TableMetadata:44 - indexes: [vatstawka_nazwa_key, vatstawka_wartosc_key, vatstawka_pkey]
                      10:53:19,160 INFO TableMetadata:40 - table found: public.waluta
                      10:53:19,160 INFO TableMetadata:41 - columns: [panstwo_id, removed, edited, przelicznik, nazwa, symbolwaluty, id]
                      10:53:19,160 INFO TableMetadata:43 - foreign keys: [fk99ff63a0265e3dac]
                      10:53:19,160 INFO TableMetadata:44 - indexes: [waluta_symbolwaluty_key, waluta_pkey]
                      10:53:19,238 INFO TableMetadata:40 - table found: public.wojewodztwo
                      10:53:19,238 INFO TableMetadata:41 - columns: [panstwo_id, removed, kod, edited, nazwa, id]
                      10:53:19,238 INFO TableMetadata:43 - foreign keys: [fk3fe7548b265e3dac]
                      10:53:19,238 INFO TableMetadata:44 - indexes: [wojewodztwo_nazwa_key, wojewodztwo_pkey]
                      10:53:19,238 INFO SchemaUpdate:162 - schema update complete
                      10:53:19,238 INFO NamingHelper:26 - JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
                      10:53:19,254 INFO SessionFactoryImpl:432 - Checking 47 named queries
                      


                      • 8. Re: Performance problem with embedded EJB :/
                        bill.burke

                         

                        "jacekolszak" wrote:

                        You mean change hbm2ddl.auto to update instead of create-drop ?


                        Remote it entirely from persistence.properties and your persistence.xml file and precreate your database before running the unit test. Update still queries the database for the table metadata to try and figure out if neeeds to alter tables at all. I think this will only shave off a few seconds though.

                        As I said before, we will do some refactorings for the kernel initialization which should shave off a few seconds (3?). I will eventually do some more profiling, but honestly it is a low priority as we're currently working on stability and functionality first. If you want to dive into this yourself, feel free. If you provide enough patches that convince us you have working knowledge of the sourcecode, we'll grant you CVS.