Re: JDBC Connection Debugging information
Re: JDBC Connection Debugging information
- Subject: Re: JDBC Connection Debugging information
- From: Farrukh Ijaz <email@hidden>
- Date: Sat, 24 Mar 2012 01:30:59 +0300
I suspect the issue is because of inappropriate JDBC driver. Check if it's type 4. If not then download the latest one that is needed for the server you have.
Here you can search for jdbc driver:
http://jdbc.postgresql.org/download.html#current
http://devapp.sun.com/product/jdbc/drivers/search_results.jsp?jdbc_version=0&vendor_name=&cert_mode=and&jdbc_driver_type=4&jdbc_driver_type_mode=and&dbms=63&dbms_mode=and&features_mode=and&results_per_page=20&submit=Search
Farrukh
Chuck Hill <email@hidden> wrote:
>
>On 2012-03-23, at 8:43 AM, Daniel Roy wrote:
>
>> Thanks Chuck. I enabled some debugging info and I see the following happening when I connect to the remote test DB server. When I configure to run locally, the the local DB server introduces no delay. I have run a test using some basic vanilla JDBC connection code and confirmed that there is no delay updating/selecting, etc on the remote server - the delay only happens when I run our WO app. The only difference between local DB and remote DB is the remote DB has SSL enabled, but I'm not connecting via SSL.
>>
>> What would the repeated "Connection is in use for..." be telling me? Maybe a locking problem? It appears to take almost 3 minutes from the time a connection is made until the SQL is evaluated.
>
>Sounds like a timeout is happening, this message is from
>
> private void reap(long maxCheckoutMillis, long maxConnectionAgeMillis) throws SQLException {
> boolean restart = false;
> Connection reapingConnection = getConnection();
> try {
> if(!isFree()) {
> // Check the time it's been checked out and recycle
> long checkoutMillis = System.currentTimeMillis() - getLockTime();
> log.debug("Connection is in use for " + checkoutMillis + " ms: " + this);
> if (maxCheckoutMillis != 0) {
>
>Other than that, I have no idea. I never use this for JDBC connections and rarely use Postgres.
>
>
>Chuck
>
>
>> Below is the part of the app startup where the _dbupdater table is being updated for migrations.
>>
>> @@@@@@@@@
>> 2012-03-23 11:31:05,987 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - Using JDBCPlugIn 'com.webobjects.jdbcadaptor.PostgresqlPlugIn' for ERXJDBCAdaptor@2026228835
>> 2012-03-23 11:31:05,988 DEBUG ProcessTest[-:12345 0] er.extensions.eof.ERXEC (ERXEC.java:266) - After pushing: [er.extensions.eof.ERXEC@c00a029, er.extensions.eof.ERXEC@c00a029]
>> 2012-03-23 11:31:06,248 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:715) - Recycling connection: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@49cb1278: status = 2: lockTime = 0: creationDate = 0
>> 2012-03-23 11:31:06,249 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:280) - Starting up ConnectionPing
>> 2012-03-23 11:31:06,250 INFO ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:304) - Started Broker : <er.extensions.jdbc.ERXJDBCConnectionBroker: dbDriver = org.postgresql.Driver, dbServer = jdbc:postgresql://[DB_SERVER_REMOVED]/process_test, dbLogin = process_test, activeConnections = 1, maximumConnections = 5, maxCheckoutMillis = 600000, maxConnectionMillis = 86400000
>> 2012-03-23 11:31:06,368 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - === Begin Internal Transaction
>> 2012-03-23 11:31:06,373 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - Using JDBCPlugIn 'com.webobjects.jdbcadaptor.PostgresqlPlugIn' for JDBCAdaptor@973357419
>> 2012-03-23 11:31:06,374 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - fetching JDBC Info with JDBCContext@1835201934
>> 2012-03-23 11:31:06,377 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - connecting with dictionary: {minConnections = "1"; driver = "org.postgresql.Driver"; logPath = "/tmp/ERXJDBCConnectionBroker_@@name@@_@@WOPort@@.log"; maxCheckout = "600"; URL = "jdbc:postgresql://[DB_SERVER_REMOVED]/process_test"; maxConnections = "5"; plugin = "Postgresql"; connectionRecycle = "1.0"; username = "process_test"; password = "<password deleted for log>"; debugLevel = "3"; }
>> 2012-03-23 11:31:26,369 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 20001 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:31:46,370 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 40002 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:32:06,371 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 60003 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:32:26,372 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 80004 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:32:27,523 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - connection disconnected.
>> 2012-03-23 11:32:27,526 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - fetching JDBC Info with ERXJDBCAdaptor$Context@139556394
>> 2012-03-23 11:32:30,095 WARN ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:368) - Connections Exhausted! Will wait and try again in loop 0
>> 2012-03-23 11:32:46,374 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 100006 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:32:46,374 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 16279 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@7f7d2d70: status = 1: lockTime = 1332516750095: creationDate = 0
>> 2012-03-23 11:33:06,375 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 120007 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:33:06,375 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 36280 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@7f7d2d70: status = 1: lockTime = 1332516750095: creationDate = 0
>> 2012-03-23 11:33:26,376 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 140008 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:33:26,376 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 56281 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@7f7d2d70: status = 1: lockTime = 1332516750095: creationDate = 0
>> 2012-03-23 11:33:46,377 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 160009 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@6547bc27: status = 1: lockTime = 1332516666368: creationDate = 1332516666368
>> 2012-03-23 11:33:46,377 DEBUG ProcessTest[-:12345 0] er.extensions.jdbc.ERXJDBCConnectionBroker (ERXJDBCConnectionBroker.java:664) - Connection is in use for 76282 ms: er.extensions.jdbc.ERXJDBCConnectionBroker$ConnectionWrapper: connection = org.postgresql.jdbc3.Jdbc3Connection@7f7d2d70: status = 1: lockTime = 1332516750095: creationDate = 0
>> 2012-03-23 11:33:48,440 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - evaluateExpression: <com.webobjects.jdbcadaptor.PostgresqlExpression: "UPDATE _dbupdater SET lockowner = ?::varchar(100), updatelock = ?::int4 WHERE (modelname = ?::varchar(100) AND (updatelock = ?::int4 OR lockowner = ?::varchar(100)))" withBindings: 1:"ProcessTest-processtest.droy:12345"(lockOwner), 2:1(updateLock), 3:"ERAttachment"(modelName), 4:0(updateLock), 5:"ProcessTest-processtest.droy:12345"(lockOwner)>
>> 2012-03-23 11:33:48,476 DEBUG ProcessTest[-:12345 0] er.extensions.ERXAdaptorChannelDelegate.sqlLogging (ERXEOAccessUtilities.java:1222) - "_dbupdater"@75479767 expression took 36 ms: UPDATE _dbupdater SET lockowner = ?::varchar(100), updatelock = ?::int4 WHERE (modelname = ?::varchar(100) AND (updatelock = ?::int4 OR lockowner = ?::varchar(100))) withBindings: 1:ProcessTest-processtest.droy:12345[lockOwner], 2:1[updateLock], 3:ERAttachment[modelName], 4:0[updateLock], 5:ProcessTest-processtest.droy:12345[lockOwner]
>> 2012-03-23 11:33:48,477 DEBUG ProcessTest[-:12345 0] NSLog (ERXNSLogLog4jBridge.java:46) - === Commit Internal Transaction
>> @@@@@@@@@@@
>>
>>
>>
>> On 2012-03-22, at 2:55 PM, Chuck Hill wrote:
>>
>>> Your JDBC driver might have some logging options.
>>>
>>>
>>> On 2012-03-22, at 11:19 AM, Daniel Roy wrote:
>>>
>>>> Hi,
>>>>
>>>> Can anyone tell me if it's possible to enable some verbose logging information of the JDBC connection process while an application is starting? I'm debugging an application locally, but I'm trying to connect to an external PostgreSQL server for testing. The application startup process hangs after the ERXJDBCConnectionBroker is started. I *can* connect successfully and without any delay using admin tools like AquaDB Studio and pgAdmin.
>>>>
>>>> I'd like to know what it's waiting for….or why it can't get a connection right away.
>>>>
>>>> Thanks
>>>> Daniel
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Do not post admin requests to the list. They will be ignored.
>>>> Webobjects-dev mailing list (email@hidden)
>>>> Help/Unsubscribe/Update your Subscription:
>>>>
>>>> This email sent to email@hidden
>>>
>>> --
>>> Chuck Hill Senior Consultant / VP Development
>>>
>>> Practical WebObjects - for developers who want to increase their overall knowledge of WebObjects or who are trying to solve specific problems.
>>> http://www.global-village.net/gvc/practical_webobjects
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>
>
>--
>Chuck Hill Senior Consultant / VP Development
>
>Practical WebObjects - for developers who want to increase their overall knowledge of WebObjects or who are trying to solve specific problems.
>http://www.global-village.net/gvc/practical_webobjects
>
>
>
>
>
>
>
>
>
> _______________________________________________
>Do not post admin requests to the list. They will be ignored.
>Webobjects-dev mailing list (email@hidden)
>Help/Unsubscribe/Update your Subscription:
>
>This email sent to email@hidden
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden