-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 8 posts ] 
Author Message
 Post subject: another idle in transaction question
PostPosted: Tue Jul 20, 2004 8:54 am 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
hibernate version: Hibernate 2.1.2
database: PostgreSQL 7.4.3 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 3.3.3 (Debian 20040422)

I (think) I am having problems with transactions staying open. I want to verify that it is a problem. The symptom is that I start up my program (which runs in a servlet container) and there is always (at least) one "idle in transaction" process per SessionFactory. This may be acceptable, but I want to find out. I have questions throughout the code...

Here is a snippet from the test program I have written:

Code:
        // just the classes I want to use
        Class[] classes = {
            StandardResource.class,
            Author.class,
            Group.class,
            User.class,
            PhysicalLocation.class,
            Contribution.class
        };

        // load some boring properties file - see properties file later on in the message
        Properties config = new Properties();
        FileInputStream fis = new FileInputStream( new File( "../build/properties/resource-hibernate.properties") );
        config.load( fis );

        Class.forName( "org.postgresql.Driver" );
        Configuration cfg = new Configuration();
        cfg.setProperties( config );

        for( int i = 0; i < classes.length; i++ )
        {
            cfg.addClass( classes[i] );
        }
        SessionFactory fact = cfg.buildSessionFactory();

        log.debug("sessoin factory created");

        // I have these sleeps in here so I can check the running processes and capture the logs...
        Thread.sleep(10000);


when I look at the database logs I see this
Code:
LOG:  connection received: host=192.168.1.3 port=4129
LOG:  connection authorized: user=postgres database=mydb
LOG:  statement: set datestyle to 'ISO'; select version(), case when pg_encoding_to_char(1) = 'SQL_ASCII' then 'UNKNOWN' else
getdatabaseencoding() end;
LOG:  statement: set client_encoding = 'UNICODE'
LOG:  statement: begin;


notice the "begin;" statement - this is starting a transaction. This means that just by creating a SessionFactory I have a transaction created. Is this correct or just some weird PostgreSQL thing?

continuing with the code
Code:
        Session session = fact.openSession();
        Transaction tx = session.beginTransaction();
        log.debug( "autocomit is : " + session.connection().getAutoCommit() ); // returns "false"
        log.debug("transaction started");
        Thread.sleep(10000);
        tx.commit();
        log.debug("commit");


The tx.commit() causes the previous transaction to be finished, but immediately opens a new transaction
Code:
LOG:  statement: commit;begin;


Code:
        Thread.sleep(2000);
        session.close();
        log.debug("close");
        Thread.sleep(2000);
        log.debug("done");
        Thread.sleep(10000);


if I do a "ps aux | grep postgres" I can still see that there is a postgres transaction that is "idle in transaction"

Code:
        log.debug( "is the session still connected? : " + session.isConnected() );
        fact.close();


Again, if I do a "ps aux | grep postgres" the "idle in transaction" message has gone, BUT there has been no command executed on the database. This means that the "begin;" that was executed earlier didn't have a corresponding "commit;" added to it, but (I assume) the socket connection to the db is closed. Is this ok?

Code:
        // again, just so I can stuff around at the OS level and see what is happening.
        Thread.sleep( 10000 );


my properties file that I load in
Code:
hibernate.dialect                  = net.sf.hibernate.dialect.PostgreSQLDialect
hibernate.generated.forced         = true
hibernate.show_sql                 = false
hibernate.connection.driver_class  = org.postgresql.Driver
hibernate.connection.url           = jdbc:postgresql://192.168.1.253/mydb
hibernate.connection.username      = postgres
hibernate.connection.password      = NONE_OF_YOUR_BUSINESS
database.jar                       = C:/programming/java/persistence/postgres/pg
74.213.jdbc3.jar
database.name                      = mydb


Any feedback on what is going on, to help my understanding of the issues, would be appreciated.

Mark


Top
 Profile  
 
 Post subject:
PostPosted: Tue Jul 20, 2004 10:39 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Are you *sure* you do not have auto-commit enabled? That looks exactly like auto-commit behaviour (on most databases anyway; I'm not familiar with Postgresql).


Top
 Profile  
 
 Post subject:
PostPosted: Tue Jul 20, 2004 10:53 am 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
Steve, thanks for you very prompt reply.

I'm including the full details since there seems to be either (a) an issue with hibernate; or (b) more likely - an issue with my config.

I definately haven't changed the defaults. Here is my crappy JUnit test method in full...

Code:
    public void testMaintaintingConnection() throws IOException, HibernateException, InterruptedException, SQLException, ClassNotFoundException
    {
        Class[] classes = {
            StandardResource.class,
            Author.class,
            Group.class,
            User.class,
            PhysicalLocation.class,
            Contribution.class
        };

        Properties config = new Properties();
        FileInputStream fis = new FileInputStream( new File( "../build/properties/resource-hibernate.properties" ) );
        config.load( fis );

        Class.forName( "org.postgresql.Driver" );
        Configuration cfg = new Configuration();
        cfg.setProperties( config );

        for( int i = 0; i < classes.length; i++ )
        {
            cfg.addClass( classes[i] );
        }
        SessionFactory fact = cfg.buildSessionFactory();

        log.debug( "sessoin factory created" );
        Thread.sleep( 10000 );
        Session session = fact.openSession();
        Transaction tx = session.beginTransaction();
        log.debug( "autocomit is : " + session.connection().getAutoCommit() );
        log.debug( "transactionstarted" );
        Thread.sleep( 10000 );
        tx.commit();
        log.debug( "commit" );
        Thread.sleep( 2000 );
        session.close();
        log.debug( "close" );
        Thread.sleep( 2000 );
        log.debug( "done" );
        Thread.sleep( 10000 );
        log.debug( "is the session still connected? : " + session.isConnected() );
        fact.close();
        Thread.sleep( 10000 );
    }


And here is my log4j output...
Code:
[main] INFO  net.sf.hibernate.cfg.Environment:462  - Hibernate 2.1.2
[main] INFO  net.sf.hibernate.cfg.Environment:496  - loaded properties from resource hibernate.properties: {database.name=mapping, hibernate.connection.driver_class=org.postgresql.Driver, hibernate.cglib.use_reflection_optimizer=true, hibernate.dialect=net.sf.hibernate.dialect.PostgreSQLDialect, database.jar=C:/programming/java/persistence/postgres/pg74.213.jdbc3.jar, hibernate.connection.username=postgres, hibernate.connection.url=jdbc:postgresql://192.168.1.253/mapping, hibernate.generated.forced=true, hibernate.show_sql=false, hibernate.connection.password=HEY_DONT_LOOK_AT_THIS!!}
[main] INFO  net.sf.hibernate.cfg.Environment:519  - using CGLIB reflection optimizer
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/StandardResource.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.StandardResource -> RESOURCE
[main] WARN  net.sf.hibernate.type.CustomType:49  - custom type does not implement Serializable: class com.stateofflux.cms.hibernate.PublishedLevelTypeEnum
[main] INFO  net.sf.hibernate.cfg.Binder:547  - Mapping collection: com.stateofflux.cms.datatype.StandardResource.authorContributions -> RESOURCE_AUTHOR_CONTRIBUTION
[main] WARN  net.sf.hibernate.type.CustomType:49  - custom type does not implement Serializable: class com.stateofflux.cms.hibernate.ResourceTypeEnum
[main] INFO  net.sf.hibernate.cfg.Binder:200  - Mapping joined-subclass: com.stateofflux.cms.datatype.BlobResource -> BLOB_RESOURCE
[main] INFO  net.sf.hibernate.cfg.Binder:200  - Mapping joined-subclass: com.stateofflux.cms.datatype.ImageResource -> IMAGE_RESOURCE
[main] INFO  net.sf.hibernate.cfg.Binder:200  - Mapping joined-subclass: com.stateofflux.cms.datatype.StreetArt -> STREET_ART
[main] WARN  net.sf.hibernate.type.CustomType:49  - custom type does not implement Serializable: class com.stateofflux.cms.hibernate.StreetArtTypeEnum
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/Author.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.Author -> AUTHOR
[main] INFO  net.sf.hibernate.cfg.Binder:547  - Mapping collection: com.stateofflux.cms.datatype.Author.resourceContribution -> RESOURCE_AUTHOR_CONTRIBUTION
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/Group.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.Group -> APP_GROUP
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/User.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.User -> APP_USER
[main] INFO  net.sf.hibernate.cfg.Binder:547  - Mapping collection: com.stateofflux.cms.datatype.User.groups -> APP_USER_GROUP
[main] INFO  net.sf.hibernate.cfg.Binder:200  - Mapping joined-subclass: com.stateofflux.cms.datatype.StreetArtUser -> STREET_ART_USER
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/PhysicalLocation.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.PhysicalLocation -> PHYSICAL_LOCATION
[main] INFO  net.sf.hibernate.cfg.Configuration:329  - Mapping resource: com/stateofflux/cms/datatype/Contribution.hbm.xml
[main] INFO  net.sf.hibernate.cfg.Binder:229  - Mapping class: com.stateofflux.cms.datatype.Contribution -> CONTRIBUTION
[main] INFO  net.sf.hibernate.cfg.Configuration:595  - processing one-to-many association mappings
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.AuthorContribution, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.ResourceContribution, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.cfg.Configuration:604  - processing one-to-one association property references
[main] INFO  net.sf.hibernate.cfg.Configuration:629  - processing foreign key constraints
[main] INFO  net.sf.hibernate.dialect.Dialect:82  - Using dialect: net.sf.hibernate.dialect.PostgreSQLDialect
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:62  - Use outer join fetching: true
[main] INFO  net.sf.hibernate.connection.DriverManagerConnectionProvider:41  - Using Hibernate built-in connection pool (not for production use!)
[main] INFO  net.sf.hibernate.connection.DriverManagerConnectionProvider:42  - Hibernate connection pool size: 20
[main] INFO  net.sf.hibernate.connection.DriverManagerConnectionProvider:71  - using driver: org.postgresql.Driver at URL: jdbc:postgresql://192.168.1.253/mydb
[main] INFO  net.sf.hibernate.connection.DriverManagerConnectionProvider:72  - connection properties: {user=postgres, password=HEY_DONT_LOOK_AT_THIS!!}
[main] INFO  net.sf.hibernate.transaction.TransactionManagerLookupFactory:33  - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:102  - Use scrollable result sets: true
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:105  - Use JDBC3 getGeneratedKeys(): false
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:108  - Optimize cache for minimal puts: false
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:117  - Query language substitutions: {}
[main] INFO  net.sf.hibernate.cfg.SettingsFactory:128  - cache provider: net.sf.ehcache.hibernate.Provider
[main] INFO  net.sf.hibernate.cfg.Configuration:1080  - instantiating and configuring caches
[main] INFO  net.sf.hibernate.impl.SessionFactoryImpl:119  - building session factory
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.ImageResource, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.StreetArt, BulkBeanException: Cannot find specified property (property setThumbnail)
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.StandardResource, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.Group, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.StreetArtUser, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.PhysicalLocation, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.User, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.Author, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.Contribution, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.util.ReflectHelper:160  - reflection optimizer disabled for: com.stateofflux.cms.datatype.BlobResource, IllegalArgumentException: Cannot find matching method/constructor
[main] INFO  net.sf.hibernate.impl.SessionFactoryObjectFactory:82  - no JNDI name configured
[main] DEBUG com.stateofflux.HibernateConnection:55  - sessoin factory created
[main] DEBUG com.stateofflux.HibernateConnection:59  - autocomit is : false
[main] DEBUG com.stateofflux.HibernateConnection:60  - transactionstarted
[main] DEBUG com.stateofflux.HibernateConnection:63  - commit
[main] DEBUG com.stateofflux.HibernateConnection:66  - close
[main] DEBUG com.stateofflux.HibernateConnection:68  - done
[main] DEBUG com.stateofflux.HibernateConnection:70  - is the session still connected? : false
[main] INFO  net.sf.hibernate.impl.SessionFactoryImpl:531  - closing
[main] INFO  net.sf.hibernate.connection.DriverManagerConnectionProvider:137  - cleaning up connection pool: jdbc:postgresql://192.168.1.253/mydb


Any ideas?


Top
 Profile  
 
 Post subject:
PostPosted: Tue Jul 20, 2004 10:54 am 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
notice the "autocomit is : false" line near the bottom


Top
 Profile  
 
 Post subject:
PostPosted: Tue Jul 20, 2004 1:17 pm 
CGLIB Developer
CGLIB Developer

Joined: Thu Aug 28, 2003 1:44 pm
Posts: 1217
Location: Vilnius, Lithuania
You do not have any problem, It must work this way . There is no "begin" in JDBC so Driver must send this command after any transaction to begin a new one.


Top
 Profile  
 
 Post subject:
PostPosted: Tue Jul 20, 2004 8:05 pm 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
I've been trawling the postgresql mailing lists and I've come across these:

Basically this is a postgres jdbc driver problem and it is fixed in the cvs version of the 7.5 branch.

http://archives.postgresql.org/pgsql-ge ... g01157.php
http://archives.postgresql.org/pgsql-jd ... g00018.php
http://archives.postgresql.org/pgsql-ha ... g00269.php
http://archives.postgresql.org/pgsql-jd ... g00162.php

I'll test it then provide some info.

Mark


Top
 Profile  
 
 Post subject:
PostPosted: Wed Aug 04, 2004 3:26 am 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
I have the feeling that the JDBC driver is just not ready for production use. Please let me know if there is a problem with the test code here.

I am also using C3P0 (in this test)

This is what I am seeing

Code:
        Class[] classes = {
            StandardResource.class,
            Author.class,
            Group.class,
            User.class,
            PhysicalLocation.class,
            Contribution.class
        };

        Properties config = new Properties();
        FileInputStream fis = new FileInputStream( new File( "../build/properties/resource-hibernate.properties" ) );
        config.load( fis );

        Class.forName( "org.postgresql.Driver" );
        Configuration cfg = new Configuration();
        cfg.setProperties( config );

        for( int i = 0; i < classes.length; i++ )
        {
            cfg.addClass( classes[i] );
        }
        SessionFactory fact = cfg.buildSessionFactory();


// output:
// Aug 4 16:24:53 sof postgres[6703]: [2-1] LOG: connection received: host=192.168.1.1 port=2165
// Aug 4 16:24:53 sof postgres[6703]: [3-1] LOG: connection authorized: user=postgres database=mydb
// Aug 4 16:24:53 sof postgres[6703]: [4-1] LOG: statement: set datestyle to 'ISO'; select version(), case when pg_encoding_to_char(1) = 'SQL_ASCII' then 'UNKNOWN' else
// Aug 4 16:24:53 sof postgres[6703]: [4-2] getdatabaseencoding() end;
// Aug 4 16:24:53 sof postgres[6703]: [5-1] LOG: statement: set client_encoding = 'UNICODE'
// Aug 4 16:24:53 sof postgres[6703]: [6-1] LOG: statement: begin;
// Aug 4 16:24:53 sof postgres[6703]: [7-1] LOG: statement: rollback; begin;
// Aug 4 16:24:53 sof postgres[6703]: [8-1] LOG: statement: end

Code:
        log.debug( "sessoin factory created" );
        Thread.sleep( 10000 );
        Session session = fact.openSession();
        Transaction tx = session.beginTransaction();


// output
// Aug 4 16:26:20 sof postgres[6703]: [9-1] LOG: statement: begin;

Code:
        log.debug( "autocomit is : " + session.connection().getAutoCommit() );
        log.debug( "transactionstarted" );
        Thread.sleep( 10000 );
        tx.commit();


// output
// Aug 4 16:27:30 sof postgres[6703]: [10-1] LOG: statement: commit;begin;

Code:
        log.debug( "commit" );
        Thread.sleep( 2000 );
        session.close();


// output:
// Aug 4 16:28:02 sof postgres[6703]: [11-1] LOG: statement: rollback; begin;
// Aug 4 16:28:02 sof postgres[6703]: [12-1] LOG: statement: end

Code:
        log.debug( "close" );
        Thread.sleep( 2000 );
        log.debug( "done" );
        Thread.sleep( 10000 );
        log.debug( "is the session still connected? : " + session.isConnected() );
        fact.close();


Note that the transaction or the connection isn't closed!

Code:
        Thread.sleep( 10000 );


Top
 Profile  
 
 Post subject:
PostPosted: Wed Aug 04, 2004 3:39 am 
Newbie

Joined: Sun Apr 04, 2004 1:58 am
Posts: 13
Location: Melbourne, Australia
Ignore my last post - I'm getting a bit drowned in info here. Let me clarify..

markmansour wrote:
Code:
        log.debug( "commit" );
        Thread.sleep( 2000 );
        session.close();


// output:
// Aug 4 16:28:02 sof postgres[6703]: [11-1] LOG: statement: rollback; begin;
// Aug 4 16:28:02 sof postgres[6703]: [12-1] LOG: statement: end



you can see the transaction being closed with the 'end' statement...

markmansour wrote:
Code:
        fact.close();


Note that the transaction or the connection isn't closed!

Code:
        Thread.sleep( 10000 );


the loss of connections is not being logged. when I check the active processes, the connection to the db is being closed.

So, at the moment, everything looks ok. I still have issues with my application, but I now have to see if they are just MY logic errors. They joy of xwork and hibernate :)

Mark


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 8 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.