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 (Webobjects-dev@lists.apple.com)
>>> Help/Unsubscribe/Update your Subscription:
>>> https://lists.apple.com/mailman/options/webobjects-dev/chill%40global-village.net
>>>
>>> This email sent to ch...@global-village.net
>>
>> --
>> 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
smime.p7s
Description: S/MIME cryptographic signature
_______________________________________________ Do not post admin requests to the list. They will be ignored. Webobjects-dev mailing list (Webobjects-dev@lists.apple.com) Help/Unsubscribe/Update your Subscription: https://lists.apple.com/mailman/options/webobjects-dev/archive%40mail-archive.com This email sent to arch...@mail-archive.com
