[hibernate-issues] [Hibernate-JIRA] Updated: (HHH-3349) SequenceStyleGenerator generates strange IDs for PostgreSQL database

SequenceStyleGenerator generates strange IDs for PostgreSQL database -------------------------------------------------------------------- Key: HHH-3349 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-3349 Project: Hibernate Core Issue Type: Bug Affects Versions: 3.2.6 Environment: hibernate-3.2.6.ga, hibernate-annotations-3.3.1.GA, hibernate-entitymanager-3.3.2.GA, hibernate-validator-3.0.0.GA, PostgreSQL 8.3.1 on Windows box. Sun Java 6 (Win32 on Vista 32 bits). Reporter: Adam Wozniak Attachments: postgresql-dialect.patch, PostgreSQLExtendedDialect.java Hello I've got a standalone application using environment: * PostgreSQL 8.3.1 (Win 32) * hibernate-3.2.6.ga * hibernate-annotations-3.3.1.GA * hibernate-entitymanager-3.3.2.GA * hibernate-validator-3.0.0.GA I've got a PostgreSQL database sequence: CREATE SEQUENCE t_seq INCREMENT 10 MINVALUE 1 MAXVALUE 999999999999999999 START 11; My entity: @Entity @Table(name = "T") @org.hibernate.annotations.Entity(dynamicUpdate=true, dynamicInsert=true) public class T { private long id; @Id @Column(unique = true, nullable = false, precision = 18, scale = 0) @GeneratedValue(generator = "t_generator") @GenericGenerator( name = "t_generator", strategy = "org.hibernate.id.enhanced.SequenceStyleGenerator", parameters = { @Parameter(name = "sequence_name", value = "T_SEQ") , @Parameter(name = "increment_size", value = "10") , @Parameter(name = "optimizer", value = "pooled") } ) public long getId() { return id; } public void setId(long id) { this.id = id; } } And my test application to recreate this issue: for(int i = 0; i < 11; i++) { if(i == 0 || i == 10) System.out.println("Database hit to sequence will be performed."); T t = new T(); em.persist(t); } Reading this Steve Ebersole description ( http://blog.hibernate.org/2082.lace#comments ) I would expect, that I will get the following IDs: 11 12 13 14 15 16 17 18 19 20 21 But Hibernate generates: 101 102 103 104 105 106 107 108 109 110 111 Is it something wrong with my code? Or this is a issue in Hibernate? Note please, that on the same page ( http://blog.hibernate.org/2082.lace#comments ) other person claims that it doesn't work for his configuration based on PostgreSQL. You will find my log4j output for my test application on the end of my email. Regards, Adam Wozniak Piece of my log4j output: 2008-06-17 20:20:38,198 [main] DEBUG () SessionImpl: opened session at timestamp: 12137268381 2008-06-17 20:20:38,200 [main] DEBUG () JDBCTransaction: begin 2008-06-17 20:20:38,200 [main] DEBUG () ConnectionManager: opening JDBC connection 2008-06-17 20:20:38,200 [main] DEBUG () BasicResourcePool: trace com.mchange.v2.resourcepool.BasicResourcePool@104a4b6 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b206e9) 2008-06-17 20:20:38,202 [main] DEBUG () JDBCTransaction: current autocommit status: true 2008-06-17 20:20:38,202 [main] DEBUG () JDBCTransaction: disabling autocommit 2008-06-17 20:20:38,202 [main] DEBUG () JDBCContext: after transaction begin Database hit to sequence will be performed. 2008-06-17 20:20:39,467 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,469 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,469 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,472 [main] DEBUG () AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-06-17 20:20:39,479 [main] DEBUG () AbstractBatcher: select nextval ('T_SEQ') Hibernate: select nextval ('T_SEQ') 2008-06-17 20:20:39,480 [main] DEBUG () AbstractBatcher: preparing statement 2008-06-17 20:20:39,489 [main] DEBUG () GooGooStatementCache: cxnStmtMgr.statementSet( org.postgresql.jdbc4.Jdbc4Connection@1df3082 ).size(): 1 2008-06-17 20:20:39,489 [main] DEBUG () GooGooStatementCache: checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 1; num connections: 1; num keys: 1 2008-06-17 20:20:39,506 [main] DEBUG () SequenceStructure$1: Sequence identifier generated: 11 2008-06-17 20:20:39,506 [main] DEBUG () AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-06-17 20:20:39,507 [main] DEBUG () AbstractBatcher: closing statement 2008-06-17 20:20:39,507 [main] DEBUG () GooGooStatementCache: checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1 2008-06-17 20:20:39,508 [main] DEBUG () AbstractSaveEventListener: generated identifier: 101, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,513 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#101] 2008-06-17 20:20:39,530 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,530 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,530 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,530 [main] DEBUG () AbstractSaveEventListener: generated identifier: 102, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,531 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#102] 2008-06-17 20:20:39,531 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,531 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,531 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,532 [main] DEBUG () AbstractSaveEventListener: generated identifier: 103, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,532 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#103] 2008-06-17 20:20:39,533 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,533 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,533 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,533 [main] DEBUG () AbstractSaveEventListener: generated identifier: 104, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,534 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#104] 2008-06-17 20:20:39,534 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,534 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,534 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,534 [main] DEBUG () AbstractSaveEventListener: generated identifier: 105, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,535 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#105] 2008-06-17 20:20:39,535 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,535 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,535 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,536 [main] DEBUG () AbstractSaveEventListener: generated identifier: 106, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,536 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#106] 2008-06-17 20:20:39,537 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,537 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,537 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,537 [main] DEBUG () AbstractSaveEventListener: generated identifier: 107, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,537 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#107] 2008-06-17 20:20:39,538 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,538 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,538 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,538 [main] DEBUG () AbstractSaveEventListener: generated identifier: 108, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,539 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#108] 2008-06-17 20:20:39,539 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,539 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,539 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,539 [main] DEBUG () AbstractSaveEventListener: generated identifier: 109, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,540 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#109] 2008-06-17 20:20:39,541 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:39,541 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:39,541 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:39,541 [main] DEBUG () AbstractSaveEventListener: generated identifier: 110, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:39,541 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#110] Database hit to sequence will be performed. 2008-06-17 20:20:40,912 [main] DEBUG () IdentifierValue: id unsaved-value: 0 2008-06-17 20:20:40,912 [main] DEBUG () AbstractSaveEventListener: transient instance of: net.cellbell.model.T 2008-06-17 20:20:40,913 [main] DEBUG () DefaultPersistEventListener: saving transient instance 2008-06-17 20:20:40,913 [main] DEBUG () AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-06-17 20:20:40,913 [main] DEBUG () AbstractBatcher: select nextval ('T_SEQ') Hibernate: select nextval ('T_SEQ') 2008-06-17 20:20:40,914 [main] DEBUG () AbstractBatcher: preparing statement 2008-06-17 20:20:40,914 [main] DEBUG () GooGooStatementCache: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache ----> CACHE HIT 2008-06-17 20:20:40,914 [main] DEBUG () GooGooStatementCache: checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 1; num connections: 1; num keys: 1 2008-06-17 20:20:40,917 [main] DEBUG () SequenceStructure$1: Sequence identifier generated: 21 2008-06-17 20:20:40,917 [main] DEBUG () AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-06-17 20:20:40,917 [main] DEBUG () AbstractBatcher: closing statement 2008-06-17 20:20:40,917 [main] DEBUG () GooGooStatementCache: checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1 2008-06-17 20:20:40,918 [main] DEBUG () AbstractSaveEventListener: generated identifier: 111, using strategy: org.hibernate.id.enhanced.SequenceStyleGenerator 2008-06-17 20:20:40,918 [main] DEBUG () AbstractSaveEventListener: saving [net.cellbell.model.T#111] 2008-06-17 20:20:40,919 [main] DEBUG () JDBCTransaction: commit 2008-06-17 20:20:40,919 [main] DEBUG () SessionImpl: automatically flushing session 2008-06-17 20:20:40,922 [main] DEBUG () AbstractFlushingEventListener: flushing session 2008-06-17 20:20:40,923 [main] DEBUG () AbstractFlushingEventListener: processing flush-time cascades 2008-06-17 20:20:40,924 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,925 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,925 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,925 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,926 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,927 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,927 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,927 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,927 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,929 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,929 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,929 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,929 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,929 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,930 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,930 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,930 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,930 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,931 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,932 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,932 [main] DEBUG () Cascade: processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,932 [main] DEBUG () Cascade: done processing cascade ACTION_PERSIST_ON_FLUSH for: net.cellbell.model.T 2008-06-17 20:20:40,932 [main] DEBUG () AbstractFlushingEventListener: dirty checking collections 2008-06-17 20:20:40,933 [main] DEBUG () AbstractFlushingEventListener: Flushing entities and processing referenced collections 2008-06-17 20:20:40,939 [main] DEBUG () AbstractFlushingEventListener: Processing unreferenced collections 2008-06-17 20:20:40,939 [main] DEBUG () AbstractFlushingEventListener: Scheduling collection removes/(re)creates/updates 2008-06-17 20:20:40,940 [main] DEBUG () AbstractFlushingEventListener: Flushed: 11 insertions, 0 updates, 0 deletions to 11 objects 2008-06-17 20:20:40,940 [main] DEBUG () AbstractFlushingEventListener: Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections 2008-06-17 20:20:40,942 [main] DEBUG () Printer: listing entities: 2008-06-17 20:20:40,942 [main] DEBUG () Printer: net.cellbell.model.T{id=105} 2008-06-17 20:20:40,943 [main] DEBUG () Printer: net.cellbell.model.T{id=104} 2008-06-17 20:20:40,943 [main] DEBUG () Printer: net.cellbell.model.T{id=107} 2008-06-17 20:20:40,943 [main] DEBUG () Printer: net.cellbell.model.T{id=106} 2008-06-17 20:20:40,945 [main] DEBUG () Printer: net.cellbell.model.T{id=101} 2008-06-17 20:20:40,945 [main] DEBUG () Printer: net.cellbell.model.T{id=103} 2008-06-17 20:20:40,945 [main] DEBUG () Printer: net.cellbell.model.T{id=102} 2008-06-17 20:20:40,945 [main] DEBUG () Printer: net.cellbell.model.T{id=109} 2008-06-17 20:20:40,945 [main] DEBUG () Printer: net.cellbell.model.T{id=108} 2008-06-17 20:20:40,946 [main] DEBUG () Printer: net.cellbell.model.T{id=111} 2008-06-17 20:20:40,946 [main] DEBUG () Printer: net.cellbell.model.T{id=110} 2008-06-17 20:20:40,946 [main] DEBUG () AbstractFlushingEventListener: executing flush 2008-06-17 20:20:40,947 [main] DEBUG () ConnectionManager: registering flush begin 2008-06-17 20:20:40,951 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#101] 2008-06-17 20:20:40,956 [main] DEBUG () AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-06-17 20:20:40,957 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,957 [main] DEBUG () AbstractBatcher: preparing statement 2008-06-17 20:20:40,957 [main] DEBUG () GooGooStatementCache: cxnStmtMgr.statementSet( org.postgresql.jdbc4.Jdbc4Connection@1df3082 ).size(): 2 2008-06-17 20:20:40,959 [main] DEBUG () GooGooStatementCache: checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 1; num connections: 1; num keys: 2 2008-06-17 20:20:40,959 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#101] 2008-06-17 20:20:40,960 [main] DEBUG () NullableType: binding '101' to parameter: 1 2008-06-17 20:20:40,964 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#102] 2008-06-17 20:20:40,965 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,965 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,965 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#102] 2008-06-17 20:20:40,967 [main] DEBUG () NullableType: binding '102' to parameter: 1 2008-06-17 20:20:40,967 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#103] 2008-06-17 20:20:40,967 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,968 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,968 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#103] 2008-06-17 20:20:40,970 [main] DEBUG () NullableType: binding '103' to parameter: 1 2008-06-17 20:20:40,970 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#104] 2008-06-17 20:20:40,970 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,970 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,971 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#104] 2008-06-17 20:20:40,971 [main] DEBUG () NullableType: binding '104' to parameter: 1 2008-06-17 20:20:40,971 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#105] 2008-06-17 20:20:40,972 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,972 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,972 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#105] 2008-06-17 20:20:40,973 [main] DEBUG () NullableType: binding '105' to parameter: 1 2008-06-17 20:20:40,973 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#106] 2008-06-17 20:20:40,973 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,975 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,976 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#106] 2008-06-17 20:20:40,977 [main] DEBUG () NullableType: binding '106' to parameter: 1 2008-06-17 20:20:40,977 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#107] 2008-06-17 20:20:40,977 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,978 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,979 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#107] 2008-06-17 20:20:40,979 [main] DEBUG () NullableType: binding '107' to parameter: 1 2008-06-17 20:20:40,979 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#108] 2008-06-17 20:20:40,980 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,980 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,980 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#108] 2008-06-17 20:20:40,981 [main] DEBUG () NullableType: binding '108' to parameter: 1 2008-06-17 20:20:40,981 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#109] 2008-06-17 20:20:40,982 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,982 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,982 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#109] 2008-06-17 20:20:40,983 [main] DEBUG () NullableType: binding '109' to parameter: 1 2008-06-17 20:20:40,983 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#110] 2008-06-17 20:20:40,983 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,983 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,984 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#110] 2008-06-17 20:20:40,984 [main] DEBUG () NullableType: binding '110' to parameter: 1 2008-06-17 20:20:40,984 [main] DEBUG () AbstractEntityPersister: Inserting entity: [net.cellbell.model.T#111] 2008-06-17 20:20:40,984 [main] DEBUG () AbstractBatcher: reusing prepared statement 2008-06-17 20:20:40,985 [main] DEBUG () AbstractBatcher: /* insert net.cellbell.model.T */ insert into T (id) values (?) Hibernate: /* insert net.cellbell.model.T */ insert into T (id) values (?) 2008-06-17 20:20:40,985 [main] DEBUG () AbstractEntityPersister: Dehydrating entity: [net.cellbell.model.T#111] 2008-06-17 20:20:40,986 [main] DEBUG () NullableType: binding '111' to parameter: 1 2008-06-17 20:20:40,986 [main] DEBUG () BatchingBatcher: Executing batch size: 11 2008-06-17 20:20:40,995 [main] DEBUG () AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-06-17 20:20:40,995 [main] DEBUG () AbstractBatcher: closing statement 2008-06-17 20:20:40,995 [main] DEBUG () GooGooStatementCache: checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 1; num keys: 2 2008-06-17 20:20:40,996 [main] DEBUG () ConnectionManager: registering flush end 2008-06-17 20:20:40,996 [main] DEBUG () AbstractFlushingEventListener: post flush 2008-06-17 20:20:40,996 [main] DEBUG () JDBCContext: before transaction completion 2008-06-17 20:20:40,996 [main] DEBUG () SessionImpl: before transaction completion 2008-06-17 20:20:41,044 [main] DEBUG () JDBCTransaction: re-enabling autocommit 2008-06-17 20:20:41,045 [main] DEBUG () JDBCTransaction: committed JDBC Connection 2008-06-17 20:20:41,045 [main] DEBUG () JDBCContext: after transaction completion 2008-06-17 20:20:41,045 [main] DEBUG () ConnectionManager: aggressively releasing JDBC connection 2008-06-17 20:20:41,045 [main] DEBUG () ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-06-17 20:20:41,050 [main] DEBUG () GooGooStatementCache: checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 1; num keys: 2 2008-06-17 20:20:41,051 [main] DEBUG () BasicResourcePool: trace com.mchange.v2.resourcepool.BasicResourcePool@104a4b6 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@b206e9) 2008-06-17 20:20:41,051 [main] DEBUG () SessionImpl: after transaction completion 2008-06-17 20:20:41,051 [main] DEBUG () PersistenceUtil: Closing EntityManager: org.hibernate.ejb.EntityManagerImpl@13c8540... 2008-06-17 20:20:41,052 [main] DEBUG () SessionImpl: closing session 2008-06-17 20:20:41,052 [main] DEBUG () ConnectionManager: connection already null in cleanup : no action 2008-06-17 20:20:41,051 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] DEBUG () GooGooStatementCache: checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 1; num keys: 2 2008-06-17 20:20:41,055 [main] DEBUG () PersistenceUtil: EntityManager: org.hibernate.ejb.EntityManagerImpl@13c8540 closed. 2008-06-17 20:20:41,055 [main] INFO () PersistenceUtil: Closing main EntityManagerFactory... 2008-06-17 20:20:41,056 [main] INFO () SessionFactoryImpl: closing 2008-06-17 20:20:41,058 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] DEBUG () ThreadPoolAsynchronousRunner$PoolThread: Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main] interrupted. Shutting down. 2008-06-17 20:20:41,058 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] DEBUG () ThreadPoolAsynchronousRunner$PoolThread: Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main] interrupted. Shutting down. 2008-06-17 20:20:41,058 [main] DEBUG () ActiveManagementCoordinator: MBean: com.mchange.v2.c3p0:type=PooledDataSource[1hge11v7u163uw8e90ilzp|405f6] unregistered. 2008-06-17 20:20:41,059 [main] DEBUG () ActiveManagementCoordinator: C3P0Registry mbean unregistered. 2008-06-17 20:20:41,060 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] DEBUG () ThreadPoolAsynchronousRunner$PoolThread: Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main] interrupted. Shutting down. 2008-06-17 20:20:41,062 [main] DEBUG () AbstractPoolBackedDataSource: com.mchange.v2.c3p0.PoolBackedDataSource@405f6 has been closed.