Code:
2005-08-05 10:40:36,806 INFO Environment:464 - Hibernate 3.0.5
2005-08-05 10:40:36,832 INFO Environment:482 - loaded properties from resource hibernate.properties: {hibernate.use_sql_comments=false, hibernate.connection.driver_class=oracle.jdbc.driver.OracleDriver, hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider, hibernate.cache.use_query_cache=true, hibernate.max_fetch_depth=1, hibernate.dialect=org.hibernate.dialect.OracleDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.query.substitutions=true 'Y', false 'N', yes 'Y', no 'N', hibernate.jdbc.batch_size=0, hibernate.connection.datasource=java:comp/env/jdbc/ibadb, hibernate.show_sql=false}
2005-08-05 10:40:36,835 INFO Environment:509 - using java.io streams to persist binary types
2005-08-05 10:40:36,836 INFO Environment:510 - using CGLIB reflection optimizer
2005-08-05 10:40:36,837 INFO Environment:540 - using JDK 1.4 java.sql.Timestamp handling
2005-08-05 10:40:37,552 INFO Configuration:1110 - configuring from resource: /hibernate.cfg.xml
2005-08-05 10:40:37,553 INFO Configuration:1081 - Configuration resource: /hibernate.cfg.xml
2005-08-05 10:40:37,830 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd in classpath under org/hibernate/
2005-08-05 10:40:37,847 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd in classpath
2005-08-05 10:40:37,973 DEBUG Configuration:1067 - show_sql=false
...
for each mapping file
...
2005-08-05 10:40:37,974 DEBUG Configuration:1262 - null<-org.dom4j.tree.DefaultAttribute@cc5436 [Attribute: name resource value "file_name.hbm.xml"]
2005-08-05 10:40:37,975 INFO Configuration:444 - Mapping resource: file_name.hbm.xml
2005-08-05 10:40:37,977 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
2005-08-05 10:40:38,001 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
2005-08-05 10:40:38,305 INFO HbmBinder:260 - Mapping class: class -> TABLE_NAME classpath
...
2005-08-05 10:40:41,191 DEBUG Configuration:998 - Preparing to build session factory with filters : {}
2005-08-05 10:40:41,191 INFO Configuration:875 - processing extends queue
2005-08-05 10:40:41,192 INFO Configuration:879 - processing collection mappings
...
for each mapping file:
...
2005-08-05 10:40:41,192 DEBUG HbmBinder:2466 - Second pass for collection: class
2005-08-05 10:40:41,193 INFO HbmBinder:2041 - Mapping collection: class -> TABLE_NAME
2005-08-05 10:40:41,194 DEBUG HbmBinder:2482 - Mapped collection key: ID, one-to-many: class
...
2005-08-05 10:40:41,512 INFO Configuration:888 - processing association property references
2005-08-05 10:40:41,512 INFO Configuration:917 - processing foreign key constraints
...
for each mapping file:
...
2005-08-05 10:40:41,513 DEBUG Configuration:964 - resolving reference to class: class
...
2005-08-05 10:40:41,711 INFO NamingHelper:26 - JNDI InitialContext properties:{}
2005-08-05 10:40:41,713 INFO DatasourceConnectionProvider:51 - Using datasource: java:comp/env/jdbc/ibadb
2005-08-05 10:40:41,758 DEBUG SettingsFactory:295 - could not get database version from JDBC metadata
2005-08-05 10:40:41,758 INFO SettingsFactory:77 - RDBMS: Oracle, version: Oracle8i Enterprise Edition Release 8.1.7.0.0 - Production
With the Partitioning option
JServer Release 8.1.7.0.0 - Production
2005-08-05 10:40:41,759 INFO SettingsFactory:78 - JDBC driver: Oracle JDBC driver, version: 9.2.0.3.0
2005-08-05 10:40:41,866 INFO Dialect:92 - Using dialect: org.hibernate.dialect.OracleDialect
2005-08-05 10:40:41,879 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
2005-08-05 10:40:41,947 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2005-08-05 10:40:41,948 INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
2005-08-05 10:40:41,949 INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
2005-08-05 10:40:41,951 INFO SettingsFactory:144 - Scrollable result sets: enabled
2005-08-05 10:40:41,951 DEBUG SettingsFactory:148 - Wrap result sets: disabled
2005-08-05 10:40:41,952 INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): disabled
2005-08-05 10:40:41,953 INFO SettingsFactory:160 - Connection release mode: null
2005-08-05 10:40:41,955 INFO SettingsFactory:184 - Maximum outer join fetch depth: 1
2005-08-05 10:40:41,955 INFO SettingsFactory:187 - Default batch fetch size: 1
2005-08-05 10:40:41,956 INFO SettingsFactory:191 - Generate SQL with comments: disabled
2005-08-05 10:40:41,957 INFO SettingsFactory:195 - Order SQL updates by primary key: disabled
2005-08-05 10:40:41,960 INFO SettingsFactory:334 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2005-08-05 10:40:42,008 INFO ASTQueryTranslatorFactory:21 - Using ASTQueryTranslatorFactory
2005-08-05 10:40:42,009 INFO SettingsFactory:203 - Query language substitutions: {no='N', true='Y', yes='Y', false='N'}
2005-08-05 10:40:42,010 INFO SettingsFactory:209 - Second-level cache: enabled
2005-08-05 10:40:42,010 INFO SettingsFactory:213 - Query cache: enabled
2005-08-05 10:40:42,011 INFO SettingsFactory:321 - Cache provider: org.hibernate.cache.EhCacheProvider
2005-08-05 10:40:42,017 INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
2005-08-05 10:40:42,017 INFO SettingsFactory:237 - Structured second-level cache entries: disabled
2005-08-05 10:40:42,018 INFO SettingsFactory:308 - Query cache factory: org.hibernate.cache.StandardQueryCacheFactory
2005-08-05 10:40:42,026 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
2005-08-05 10:40:42,079 INFO SettingsFactory:261 - Statistics: disabled
2005-08-05 10:40:42,080 INFO SettingsFactory:265 - Deleted entity synthetic identifier rollback: disabled
2005-08-05 10:40:42,082 INFO SettingsFactory:279 - Default entity-mode: pojo
2005-08-05 10:40:42,618 INFO SessionFactoryImpl:152 - building session factory
2005-08-05 10:40:42,619 DEBUG SessionFactoryImpl:161 - Session factory constructed with filter configurations : {}
2005-08-05 10:40:42,620 DEBUG SessionFactoryImpl:164 - instantiating session factory with properties: {show_sql=false, java.vendor=Sun Microsystems Inc.,
...
...
for each mapping file:
...
2005-08-05 10:40:44,215 DEBUG BasicEntityPersister:2220 - Static SQL for entity: class
2005-08-05 10:40:44,215 DEBUG BasicEntityPersister:2222 - Version select: ...
2005-08-05 10:40:44,216 DEBUG BasicEntityPersister:2223 - Snapshot select: ...
2005-08-05 10:40:44,217 DEBUG BasicEntityPersister:2225 - Insert 0: ...
2005-08-05 10:40:44,217 DEBUG BasicEntityPersister:2226 - Update 0: ...
2005-08-05 10:40:44,218 DEBUG BasicEntityPersister:2227 - Delete 0: ...
2005-08-05 10:40:44,219 DEBUG CacheFactory:39 - instantiating cache region: class usage strategy: read-write
2005-08-05 10:40:44,222 WARN EhCacheProvider:97 - Could not find configuration [class]; using defaults.
2005-08-05 10:40:44,226 DEBUG EhCacheProvider:100 - started EHCache region: class
....
2005-08-05 10:40:48,103 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
2005-08-05 10:40:48,107 DEBUG SessionFactoryObjectFactory:76 - registered: ff8080820587162e0105871645e40000 (unnamed)
2005-08-05 10:40:48,108 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
2005-08-05 10:40:48,113 DEBUG SessionFactoryImpl:262 - instantiated session factory
2005-08-05 10:40:48,140 INFO UpdateTimestampsCache:43 - starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache
2005-08-05 10:40:48,141 WARN EhCacheProvider:97 - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
2005-08-05 10:40:48,142 DEBUG EhCacheProvider:100 - started EHCache region: org.hibernate.cache.UpdateTimestampsCache
2005-08-05 10:40:48,145 INFO StandardQueryCache:50 - starting query cache at region: org.hibernate.cache.StandardQueryCache
2005-08-05 10:40:48,146 WARN EhCacheProvider:97 - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.
2005-08-05 10:40:48,146 DEBUG EhCacheProvider:100 - started EHCache region: org.hibernate.cache.StandardQueryCache
2005-08-05 10:40:48,147 INFO SessionFactoryImpl:379 - Checking 0 named queries
2005-08-05 10:42:37,889 DEBUG SessionImpl:250 - opened session at timestamp: 4600844115193856
2005-08-05 10:42:37,894 DEBUG JDBCTransaction:46 - begin
2005-08-05 10:42:37,896 DEBUG ConnectionManager:296 - opening JDBC connection
2005-08-05 10:42:37,898 DEBUG JDBCTransaction:50 - current autocommit status: true
2005-08-05 10:42:37,899 DEBUG JDBCTransaction:52 - disabling autocommit
...
Here the application starts:
...
2005-08-05 10:42:37,917 DEBUG SessionImpl:829 - find: select obj from class as obj where obj.state = ? order by obj.name
2005-08-05 10:42:37,921 DEBUG QueryParameters:221 - parameters: [state]
2005-08-05 10:42:37,926 DEBUG QueryParameters:224 - named parameters: {}
2005-08-05 10:42:38,102 DEBUG QueryTranslatorImpl:207 - parse() - HQL: select obj from class as obj where obj.state = ? order by obj.name
...
2005-08-05 10:42:38,150 DEBUG ErrorCounter:72 - throwQueryException() : no errors
2005-08-05 10:42:38,303 DEBUG HqlSqlBaseWalker:120 - query() << begin, level = 1
2005-08-05 10:42:38,366 DEBUG FromElement:88 - FromClause{level=1} : class (obj) -> obj_
2005-08-05 10:42:38,389 DEBUG FromReferenceNode:48 - Resolved : obj -> obj_._ID
2005-08-05 10:42:38,399 DEBUG DotNode:476 - getDataType() : state -> org.hibernate.type.StringType@1f7dbd8
2005-08-05 10:42:38,408 DEBUG FromReferenceNode:48 - Resolved : obj.state -> obj_.STATE
2005-08-05 10:42:38,412 DEBUG FromReferenceNode:48 - Resolved : obj -> obj_.SITE_ID
...
2005-08-05 10:42:38,416 DEBUG HqlSqlBaseWalker:125 - query() : finishing up , level = 1
...
2005-08-05 10:42:38,489 DEBUG ErrorCounter:72 - throwQueryException() : no errors
2005-08-05 10:42:38,535 DEBUG QueryTranslatorImpl:177 - HQL: select obj
2005-08-05 10:42:38,537 DEBUG ErrorCounter:72 - throwQueryException() : no errors
2005-08-05 10:42:38,574 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-08-05 10:42:38,593 DEBUG AbstractBatcher:378 - preparing statement
2005-08-05 10:42:38,596 DEBUG StringType:59 - binding 'state' to parameter: 1
2005-08-05 10:42:38,645 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 0)
2005-08-05 10:42:38,789 DEBUG Loader:405 - processing result set
2005-08-05 10:42:38,791 DEBUG Loader:410 - result set row: 0
...
for each row of the result list
...
2005-08-05 10:42:38,837 DEBUG LongType:86 - returning '111' as column: COLNAME_
2005-08-05 10:42:38,842 DEBUG Loader:828 - result row: EntityKey[class#111]
2005-08-05 10:42:38,844 DEBUG Loader:978 - Initializing object from ResultSet: [class#111]
2005-08-05 10:42:38,900 DEBUG BasicEntityPersister:1651 - Hydrating entity: [class#111]
..
for each column in the row returned:
...
2005-08-05 10:42:38,902 DEBUG StringType:86 - returning 'Some name' as column: COLNAME
...
2005-08-05 10:42:40,453 DEBUG Loader:429 - done processing result set (27 rows)
2005-08-05 10:42:40,474 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 1)
2005-08-05 10:42:40,476 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-08-05 10:42:40,477 DEBUG AbstractBatcher:416 - closing statement
2005-08-05 10:42:40,482 DEBUG Loader:528 - total objects hydrated: 27
2005-08-05 10:42:40,483 DEBUG TwoPhaseLoad:96 - resolving associations for [class#111]
...
for each one-to-many mapping:
....
2005-08-05 10:42:40,496 DEBUG CollectionLoadContext:141 - creating collection wrapper:[mappedclassname#111]
2005-08-05 10:42:40,519 DEBUG TwoPhaseLoad:119 - adding entity to second-level cache: [class#111]
2005-08-05 10:42:40,527 DEBUG ReadWriteCache:148 - Caching: class#111
2005-08-05 10:42:40,529 DEBUG EhCache:104 - key: class#111
2005-08-05 10:42:40,534 DEBUG EhCache:113 - Element for class#111 is null
2005-08-05 10:42:40,541 DEBUG ReadWriteCache:160 - Cached: class#111
2005-08-05 10:42:40,543 DEBUG TwoPhaseLoad:167 - done materializing entity [class#111]
...
2005-08-05 10:42:41,254 DEBUG ErrorCounter:72 - throwQueryException() : no errors
2005-08-05 10:42:41,255 DEBUG AbstractFlushingEventListener:52 - flushing session
2005-08-05 10:42:41,256 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
...
for each mapping file:
...
2005-08-05 10:42:41,259 DEBUG Cascades:836 - processing cascade ACTION_SAVE_UPDATE for: class
....
2005-08-05 10:42:42,480 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
2005-08-05 10:42:42,482 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
...
for each mapping file:
...
2005-08-05 10:42:42,497 DEBUG Collections:140 - Collection found: [class#111] was: [class#111] (uninitialized)
...
2005-08-05 10:42:42,859 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
2005-08-05 10:42:42,861 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
2005-08-05 10:42:42,862 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 0 deletions to 27 objects
2005-08-05 10:42:42,863 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 270 collections
2005-08-05 10:42:42,864 DEBUG Printer:83 - listing entities:
...
2005-08-05 10:42:42,946 DEBUG Printer:87 - more......
2005-08-05 10:42:42,947 DEBUG DefaultAutoFlushEventListener:60 - Dont need to execute flush
2005-08-05 10:42:42,949 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)