title: Hibernate batch size confusion
body: <p>This program does tens of thousands of consecutive inserts one after the other. I've never used Hibernate before. I'm getting extremely slow performance (if I just connect and execute the SQL manually I am 10-12x quicker. My batch_size is set to 50 as per many hibernate tutorials.</p>
  
  <p>Here is a log from a single insert - perhaps you could help me understand exactly what is happening:</p>
  
  <pre><code>START INSERT
  11:02:56.121 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13106053761                                                                                            
  11:02:56.121 [main] DEBUG o.h.transaction.JDBCTransaction - begin                                                                                                                               
  11:02:56.121 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection                                                                                                             
  11:02:56.121 [main] TRACE o.h.c.DriverManagerConnectionProvider - total checked-out connections: 0                                                                                                    
  11:02:56.121 [main] TRACE o.h.c.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0                                                                                          
  11:02:56.121 [main] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false                                                                                                    
  11:02:56.121 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction begin                                                                                                             
  11:02:56.121 [main] TRACE org.hibernate.impl.SessionImpl - setting flush mode to: MANUAL                                                                                                       
  11:02:56.121 [main] TRACE o.h.e.def.DefaultLoadEventListener - loading entity: [com.xyzcompany.foo.edoi.ejb.msw000.MSW000Rec#component[keyW000]{keyW000=F000    ADSUFC}]                           
  11:02:56.121 [main] TRACE o.h.e.def.DefaultLoadEventListener - creating new proxy for entity                                                                                                       
  11:02:56.122 [main] TRACE o.h.e.d.DefaultSaveOrUpdateEventListener - saving transient instance                                                                                                           
  11:02:56.122 [main] DEBUG o.h.e.def.AbstractSaveEventListener - generated identifier: component[keyW000]{keyW000=F000    ADSUFC}, using strategy: org.hibernate.id.CompositeNestedGeneratedValueGenerator
  11:02:56.122 [main] TRACE o.h.e.def.AbstractSaveEventListener - saving [com.xyzcompany.foo.edoi.ejb.msw000.MSW000Rec#component[keyW000]{keyW000=F000    ADSUFC}]                                    
  11:02:56.123 [main] TRACE o.h.e.d.AbstractFlushingEventListener - flushing session                                                                                                                    
  11:02:56.123 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades                                                                                                      
  11:02:56.123 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections                                                                                                          
  11:02:56.123 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Flushing entities and processing referenced collections                                                                             
  11:02:56.125 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Processing unreferenced collections                                                                                                 
  11:02:56.125 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates                                                                                   
  11:02:56.126 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 1 insertions, 0 updates, 0 deletions to 62 objects                                                                         
  11:02:56.126 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections                                                                                                                                                                                       
  11:02:56.132 [main] TRACE o.h.e.d.AbstractFlushingEventListener - executing flush                                                                                                                     
  11:02:56.132 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush begin                                                                                                             
  11:02:56.132 [main] TRACE o.h.p.entity.AbstractEntityPersister - Inserting entity: [com.xyzcompany.foo.edoi.ejb.msw000.MSW000Rec#component[keyW000]{keyW000=F000    ADSUFC}]                         
  11:02:56.132 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)                                                           
  11:02:56.132 [main] DEBUG org.hibernate.SQL - insert into MSW000 (W000_DATA_REC, W000_FILE_FLAGS, KEY_W000) values (?, ?, ?)                                                      
  11:02:56.132 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement                                                                                                                 
  11:02:56.132 [main] TRACE o.h.p.entity.AbstractEntityPersister - Dehydrating entity: [com.xyzcompany.foo.edoi.ejb.msw000.MSW000Rec#component[keyW000]{keyW000=F000    ADSUFC}]                       
  11:02:56.132 [main] TRACE org.hibernate.type.StringType - binding '    ADSUFCA                                                                                                                                                                                                                                                                                  ' to parameter: 1
  11:02:56.132 [main] TRACE org.hibernate.type.StringType - binding ' ' to parameter: 2                                                                                                         
  11:02:56.132 [main] TRACE org.hibernate.type.StringType - binding 'F000    ADSUFC' to parameter: 3                                                                                            
  11:02:56.132 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - Executing batch size: 1                                                                                                             
  11:02:56.133 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)                                                          
  11:02:56.133 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement                                                                                                                   
  11:02:56.133 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush end                                                                                                               
  11:02:56.133 [main] TRACE o.h.e.d.AbstractFlushingEventListener - post flush                                                                                                                          
  11:02:56.133 [main] DEBUG o.h.transaction.JDBCTransaction - commit                                                                                                                              
  11:02:56.133 [main] TRACE org.hibernate.impl.SessionImpl - automatically flushing session                                                                                                      
  11:02:56.133 [main] TRACE org.hibernate.jdbc.JDBCContext - before transaction completion                                                                                                       
  11:02:56.133 [main] TRACE org.hibernate.impl.SessionImpl - before transaction completion                                                                                                       
  11:02:56.133 [main] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection                                                                                                           
  11:02:56.133 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction completion                                                                                                        
  11:02:56.133 [main] DEBUG org.hibernate.jdbc.ConnectionManager - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!     
  11:02:56.133 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion                                                                                                        
  11:02:56.133 [main] TRACE org.hibernate.impl.SessionImpl - closing session                                                                                                                     
  11:02:56.133 [main] TRACE org.hibernate.jdbc.ConnectionManager - performing cleanup                                                                                                                  
  11:02:56.133 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]                            
  11:02:56.133 [main] TRACE o.h.c.DriverManagerConnectionProvider - returning connection to pool, pool size: 1                                                                                          
  11:02:56.133 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction completion                                                                                                        
  11:02:56.133 [main] DEBUG org.hibernate.jdbc.ConnectionManager - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!     
  11:02:56.134 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion                                                                                                        
  FINISH INSERT
  </code></pre>