• Open Menu Close Menu
  • Apple
  • Shopping Bag
  • Apple
  • Mac
  • iPad
  • iPhone
  • Watch
  • TV
  • Music
  • Support
  • Search apple.com
  • Shopping Bag

Lists

Open Menu Close Menu
  • Terms and Conditions
  • Lists hosted on this site
  • Email the Postmaster
  • Tips for posting to public mailing lists
Re: JDBC Connection Debugging information
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: JDBC Connection Debugging information

  • Subject: Re: JDBC Connection Debugging information
  • From: Daniel Roy <email@hidden>
  • Date: Fri, 23 Mar 2012 11:43:31 -0400
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 = ""; 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
@@@@@@@@@@@


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
References: 
 >JDBC Connection Debugging information (From: Daniel Roy <email@hidden>)

  • Prev by Date: Re: [ANN] WOInject 1.0
  • Next by Date: Re: Opening multiple database channels
  • Previous by thread: JDBC Connection Debugging information
  • Next by thread: Re: JDBC Connection Debugging information
  • Index(es):
    • Date
    • Thread