Load balancing port 9999 troubles

Hello,

Initially i made a post here, then I realized it is separate issue.
The case : Java 1.6 app connecting to a PostgreSQL 9.1 32bit m1.small database.
For demonstration I have created two copies of the same database and an application:
- the second database is derived by clone functionality
- the second app is derived by changing the jdbc url only.
First environment is using port 5432 to connect to the database (explicitly open in the Security Groups), second one port 9999. Despite the jdbc pooling library used the one on port 9999 can't stop openning connections until the connection limit is exhausted (please see the screenshots) with no obvious reason. Both environments have no load at all.

Is there any way to explain this? What can I do to prevent such a "connection leak"? Currently the cluster configuration can't be utilized in any way ...

Best Regards,
Aleksandar

I am currently unable to see the attachment in your post. I am trying to remedy that.

Can you please share some details about your JDBC pooling library, and its configuration.

Thanks,

Hello,

I am attaching the same file again.
We are using c3p0 with Hibernate. The pool start with 5 connections and grow up to 20 if there is load (wich we don't have).
I think the balancer is not able to properly forward the connection, so the app opens new connection while the old one is still alive (just a guess). The same connection pool is working perfectly for quite a lot of time against fixed instance on 5432 ... I investigated them - they are all IDLE and the DB server is not under load.
Furthermore I am keeping the environment up for you so you will be able to see yourself (the one ending with "_clone").

Best Regards,
Aleksandar

Hello,

do you think it makes sence to keep the problematic cluster up (after all it costs money)? Any ideas where the problem might be?

Best Regards,
Aleksandar

I have been trying to reproduce this without using a JDBC pooler, but haven't been successful so far. Everytime I close a connection to the 9999 port, the connection count does go down on my cluster.

There's a possibility that a combination of c3p0 and Hibernate does not release/reuse the connections, but that doesn't explain why you don't see this problem on port 5432.

If possible, please leave the cluster running for a few more hours, while I investigate.

Thanks,

This message was edited 1 time. Last update was at 6 Jun 2012 12:23:07

Hi Aleksandar,

Thank you for keeping your JDBC app running while I performed tests on your cluster. Since I could not reliably reproduce the case using my psql connections, constant connections from your JDBC app helped in the diagnosis.

I think I have a handle on the situation now. pgpool is caching the connections to be reused for subsequent connections. But instead of releasing the connections after 5 minutes (parameter child_life_time=300 seconds), it chooses to reestablish the connection and keep it in the cache.

If you really start using the connections in the future through pgpool, it should start handing out cached connections instead of creating new connections. I have tested this by pounding your cluster's pgpool with 50 parallel psql sessions every second (each doing pg_sleep(3) and disconnecting) and could see that pgpool handled the load graciously and that total connection count on the database never went beyond 70.

From the logs I can see that all that your client app was doing was executing these SQL commands:

set extra_float_digits = 3
SHOW TRANSACTION ISOLATION LEVEL
select 1;

and then disconnecting.

It is troubling that pgpool wouldn't release the connections for such a simple app, I will take it up with the pgpool community.

Unfortunately I am unable to reproduce this using plain psql, so can you please provide me with the client code that you used and any c3p0 and Hibernate configuration that might be relevant for this case (like pool size, etc.).

Thanks a lot for being patient and all the help. Please feel free to terminate your _clone cluster.

Best regards,

Hello Gurjeet_S!

I'm glad you were able to investigate the case.
As I told you the app is staying still. The pool is initialized with the app and the SQLs you have found are just the queries, that verify the connection state in the pool every few seconds, namely "select 1".
For how c3p0 is working you may take a look here. The version deployed is using it ComboPooledDataSource with the following options, related to the pooling:
minPoolSize=5
maxPoolSize=50
maxIdleTime=10
idleConnectionTestPeriod=10
preferredTestQuery=select 1
testConnectionOnCheckout=true
It is really strange that the same configuration is working against 5432 and not with 9999. Do you think there is a way for us to accelerate the resolution?

I will terminate the _clone cluster, send me message if you need simple test app for troubleshooting.

Best Regards,
Aleksandar

Hello,

I have provided both source code and binary of sample application that is able to reproduce the issue in private communication.
It uses all standard and widely used technologies - Spring and Hibernate (bundled with c3po).
Do you have any progress on this or should I provide something more?

Thank you,
Aleksandar

Anybody there?

Aleksandar

Hi Aleksandar,

As I mentioned on 24 May in a private message to you, I had to take a few days off in an emergency. I am going to continue to work on this issue now.

Regards,

Hi Aleksandar,

I used the war file your sent, and I see the same behaviour as I saw with the source-code you sent earlier. In other words, the connections do not spike, and stay stable at the number configured in minPoolSize parameter.

Here are the steps I used to run your war file:

.) Follow instructions at http://stackoverflow.com/questions/3623412/jetty-run-war-using-only-command-line

.) Download http://repo2.maven.org/maven2/org/mortbay/jetty/jetty-runner/8.1.4.v20120524/jetty-runner-8.1.4.v20120524.jar

.) Expand/explode your war file using: jar xvf SampleConnectionsPool.war

.) Edit the WEB-INF/spring-context.xml

.) Replace ADDRESS_HERE with host name of my cluster's only node. (Keep port number as 9999)

.) Relace SCHEMA_HERE with postgres.

.) Replace USER_HERE with postgres

.) Replace PASSWORD_HERE wit postgres

.) Set minPoolSize to 20.

.) Repackage the files into the war file: jar cvf SampleConnectionsPool.war index.jsp WEB-INF/ META-INF/

.) Run the app using jetty-runner: java -jar $HOME/Downloads/jetty-runner-8.1.4.v20120524.jar SampleConnectionsPool.war

(The logs are pasted atthe end of this post. Please make sure there are no warnings in that log that you think make it different from your deployment)

The result is that the "Connections" graph stays pretty much stable at 20. I relaunched app after setting the minPoolSize to 10, and the connections stay stable at 10.

https://docs.google.com/open?id=0B3QzOcgiKB2gcUlXTzQxeXcxeG8

Please let me know if I made some error is trying to reproduce the problem.

$ java -jar /mnt/storage/gurjeet/Downloads/jetty-runner-8.1.4.v20120524.jar SampleConnectionsPool.war
2012-06-06 13:59:20.644:INFO:omjr.Runner:Runner
2012-06-06 13:59:20.644:WARN:omjr.Runner:No tx manager found
2012-06-06 13:59:20.717:INFO:omjr.Runner

eploying file:/tmp/del2/SampleConnectionsPool.war @ /
[o.e.j.w.WebAppContext{/,null},file:/tmp/del2/SampleConnectionsPool.war]
2012-06-06 13:59:20.733:INFO:oejs.Server:jetty-8.y.z-SNAPSHOT
2012-06-06 13:59:20.765:INFO:oejw.WebInfConfiguration:Extract jar:file:/tmp/del2/SampleConnectionsPool.war!/ to /tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp
2012-06-06 13:59:21.778:INFO:oejpw.PlusConfiguration:No Transaction manager found - if your webapp requires one, please configure one.
2012-06-06 13:59:24.091:INFO:oejsh.ContextHandler:started o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war
2012-06-06 13:59:24.129:INFO:oejsh.ContextHandler:started o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war
2012-06-06 13:59:24.129:INFO:oejsh.ContextHandler:started o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war
2012-06-06 13:59:24.129:INFO:oejsh.ContextHandler:started o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war
2012-06-06 13:59:24.138:INFO:/:Initializing Spring root WebApplicationContext
Jun 6, 2012 1:59:24 PM org.springframework.web.context.ContextLoader initWebApplicationContext
INFO: Root WebApplicationContext: initialization started
Jun 6, 2012 1:59:24 PM org.springframework.context.support.AbstractApplicationContext prepareRefresh
INFO: Refreshing Root WebApplicationContext: startup date [Wed Jun 06 13:59:24 EDT 2012]; root of context hierarchy
Jun 6, 2012 1:59:24 PM org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
INFO: Loading XML bean definitions from ServletContext resource [/WEB-INF/spring-context.xml]
Jun 6, 2012 1:59:24 PM org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
INFO: Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@1408a92: defining beans [dataSource,sessionFactory]; root of factory hierarchy
Jun 6, 2012 1:59:24 PM com.mchange.v2.log.MLog <clinit>
INFO: MLog clients using java 1.4+ standard logging.
Jun 6, 2012 1:59:24 PM com.mchange.v2.c3p0.C3P0Registry banner
INFO: Initializing c3p0-0.9.1.2 [built 21-May-2007 15:04:56; debug? true; trace: 10]
Jun 6, 2012 1:59:24 PM org.hibernate.cfg.Environment <clinit>
INFO: Hibernate 3.2.7
Jun 6, 2012 1:59:24 PM org.hibernate.cfg.Environment <clinit>
INFO: hibernate.properties not found
Jun 6, 2012 1:59:24 PM org.hibernate.cfg.Environment buildBytecodeProvider
INFO: Bytecode provider name : cglib
Jun 6, 2012 1:59:24 PM org.hibernate.cfg.Environment <clinit>
INFO: using JDK 1.4 java.sql.Timestamp handling
Jun 6, 2012 1:59:24 PM org.springframework.orm.hibernate3.LocalSessionFactoryBean buildSessionFactory
INFO: Building new Hibernate SessionFactory
Jun 6, 2012 1:59:24 PM org.hibernate.connection.ConnectionProviderFactory newConnectionProvider
INFO: Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider
Jun 6, 2012 1:59:24 PM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource getPoolManager
INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> z8kfsx8n1i3b7khununhq|2326a29c, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.postgresql.Driver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kfsx8n1i3b7khununhq|2326a29c, idleConnectionTestPeriod -> 10, initialPoolSize -> 3, jdbcUrl -> jdbc:postgresql://ec2-23-23-184-118.compute-1.amazonaws.com:9999/postgres, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 10, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 50, maxStatements -> 300, maxStatementsPerConnection -> 100, minPoolSize -> 20, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> select 1, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> true, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: RDBMS: PostgreSQL, version: 9.1.3
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 9.1 JDBC3 (build 901)
Jun 6, 2012 1:59:25 PM org.hibernate.dialect.Dialect <init>
INFO: Using dialect: org.hibernate.dialect.PostgreSQLDialect
Jun 6, 2012 1:59:25 PM org.hibernate.transaction.TransactionFactoryFactory buildTransactionFactory
INFO: Transaction strategy: org.springframework.orm.hibernate3.SpringTransactionFactory
Jun 6, 2012 1:59:25 PM org.hibernate.transaction.TransactionManagerLookupFactory getTransactionManagerLookup
INFO: No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Automatic flush during beforeCompletion(): disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Automatic session close at end of transaction: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: JDBC batch size: 15
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: JDBC batch updates for versioned data: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Scrollable result sets: enabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: JDBC3 getGeneratedKeys(): enabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Connection release mode: auto
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Default batch fetch size: 1
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Generate SQL with comments: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Order SQL updates by primary key: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Order SQL inserts for batching: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory createQueryTranslatorFactory
INFO: Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
Jun 6, 2012 1:59:25 PM org.hibernate.hql.ast.ASTQueryTranslatorFactory <init>
INFO: Using ASTQueryTranslatorFactory
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Query language substitutions: {}
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: JPA-QL strict compliance: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Second-level cache: enabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Query cache: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory createCacheProvider
INFO: Cache provider: org.hibernate.cache.NoCacheProvider
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Optimize cache for minimal puts: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Structured second-level cache entries: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Statistics: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Deleted entity synthetic identifier rollback: disabled
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Default entity-mode: pojo
Jun 6, 2012 1:59:25 PM org.hibernate.cfg.SettingsFactory buildSettings
INFO: Named query checking : enabled
Jun 6, 2012 1:59:25 PM org.hibernate.impl.SessionFactoryImpl <init>
INFO: building session factory
Jun 6, 2012 1:59:25 PM org.hibernate.impl.SessionFactoryObjectFactory addInstance
INFO: Not binding factory to JNDI, no JNDI name configured
Jun 6, 2012 1:59:25 PM org.springframework.web.context.ContextLoader initWebApplicationContext
INFO: Root WebApplicationContext: initialization completed in 1064 ms
2012-06-06 13:59:25.205:INFO:oejsh.ContextHandler:started o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war
2012-06-06 13:59:25.240:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:8080
^C2012-06-06 14:44:34.082:INFO:/:Closing Spring root WebApplicationContext
2012-06-06 14:44:34.100:INFO:oejsl.ELContextCleaner:javax.el.BeanELResolver purged
2012-06-06 14:44:34.100:INFO:oejsh.ContextHandler:stopped o.e.j.w.WebAppContext{/,file:/tmp/jetty-0.0.0.0-8080-SampleConnectionsPool.war-_-any-/webapp/},file:/tmp/del2/SampleConnectionsPool.war

Hello Gurjeet,

I'm glad you are back, hope everything is ok with you.
If you are unable to reproduce the issue at your side, then there is a difference in the database you are using. Otherwise I cannot explain why the same app is failing at my site. Please take another look at the screenshot I have already attached.
I will test again and will send you credentials for my environment in private message.

Best Regards,
Aleksandar

As you reported in your original post, I used the same configuration for my cluster as yours:

PostgreSQL 9.1 32bit m1.small database.

Hello,

I was able to reproduce the issue agains our test cluster. As a private message I have sent you the preconfigured application. Because the monitoring trough PPCD console does not currently work (show zero connections) I have used "SELECT count(datname) FROM pg_stat_activity where datname = 'enterprisedb'" to see that the number of connections is constantly growing up (that's why I'm unable to send you another screenshot). Please use the provided app to reproduce the problem and don't let it occupy all the connections.

Best Regards,
Aleksandar

Thanks Aleksandar, I am able to reproduce the problem with your new war file, which uses your cluster.

I will now try to use the same war file against my cluster. So that we can diagnose this problem without risking anything on your cluster.

Thanks for your patience and cooperation.
Best regards,

Hello,

did you get some idea of the problem? If the problem is not reproduceable against your cluster should I recreate(update) mine as a workaround? Or the issue is valid also against your cluster?

Best Regards,
Aleksandar

Yes, I was able to reproduce this against my cluster. This seems to be a bug in pgpool. It behaves like this if the connections are made to a non-default database.

We are investigating this and will update you when we have a fix.

Best regards,

Per the email conversation with pgpool community [1] and their FAQ [2] item "Is connection pool cache shared among pgpool process?" this inability to reuse cached connections is by design.

Your case can be solved by setting a lower limit on how long the cached connection should live, should there be no client connections for a long time. Currently it is set by default to 300 seconds (5 minutes), so if we set it to, say, 10 seconds, the the cached connections will be reused sooner rather than later, and you won't see as dramatic a spike in connections on the database side.

[1] http://www.pgpool.net/pipermail/pgpool-hackers/2012-June/000077.html
[2] http://pgpool.net/mediawiki/index.php/FAQ

Hello,

thank you for the update. It seems like a workaround of another issue, but we tried it.
Initially we were confused wich parameter you have in mind and how to update it. Then we decreased the values of connection_life_time, child_max_connections and child_life_time directly in pgpool.conf and restarted the running process. I personally don't like this approach since it requires SSH access and is not covered by the Configurations options provided by the PPCD console. With the new configuration the number of connections remain relatively few as expected. For me this means, that with the cost of some overhead (openning and discarding connections frequently) our problem may be resolved.
Can you please confirm this is the way to apply the workaround in a working cluster (or provide a recommended way of doing it). I have tested adding a replica successfully (the new configuration is copied) but applying a new configuration from the PPCD console(Just "Apply" button with no actual changes) failed in endless loop, so at the end I have deleted the cluster.

Thank you in advance!

Best Regards,
Aleksandar

In my post, I was referring to the parameter child_life_time. Setting that parameter alone should reduce the time a connection can live in connection cache if it is unused.

Hey Gurjeet,

have you checked the PPCD console, there is no such property there. As explained in the previous post that is the reason we have searched for pgpool.conf directly on the file sytem (should we actually do it?).
Is it about another property or is there a way this property to be added to the configuration?

Thank you,
Aleksandar

This message was edited 2 times. Last update was at 8 Aug 2012 12:53:54

bebewib wrote:
there is no such property there.

As of now we expose only 3 parameters in the PPCD Console: reset_query_list, white_function_list, black_function_list.

To change other parameters, one has to ssh into the primary instance and edit the /mnt/pcs/data/pgpool.conf file and restart/reload the pgpool service, like so:

/etc/init.d/pgpool-3.0 reload
Or
/etc/init.d/pgpool-3.0 restart

As for changing child_life_time to 10 seconds affecting the performance, I do not anticipate this change should cause any noticeable performance degradation.

Connection/disconnection attempts on a database cause a noticeable performance impact only if the duration of the query executed by the application is small as compared to the time it takes to create and destroy a database backend process. With child_life_time set to 10 seconds, the database connections will be disconnected only after a period of 10 seconds (only if a connection goes unused for that long). So the overhead of creating a new connection will be minimal, and if the application is busy enough then the disconnections may not happen at all.

On the other hand, this setting will help ensure that cached connections do not go unused for any longer than 10 seconds. Given pgpool's design that there's no guarantee that a new client connection will be served by the same pgpool process that holds the cached connection, I'd say this is a good thing.

Thank you so much for your instructions and userfull explanations!
You made my day!

Best,
Aleksandar