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.
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 protected])
>> Help/Unsubscribe/Update your Subscription:
>> https://lists.apple.com/mailman/options/webobjects-dev/chill%40global-village.net
>>
>> This email sent to [email protected]
>
> --
> 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 protected])
Help/Unsubscribe/Update your Subscription:
https://lists.apple.com/mailman/options/webobjects-dev/archive%40mail-archive.com
This email sent to [email protected]
