Mario -
Thanks for your time. There are some differences between the JCC logs.
One thing that looks suspect to me is that the "RECEIVE BUFFER:
ENDUOWRM" message is present after each qry when using the SIMPLE Data
source pool (as well as the Apache DBCP pool), but not always there
while using the GlassFish pool. Also ran a non-iBATIS application,
using the Glassfish Pool and we did get the RECEIVE BUFFER: ENDUOWRM
messages after each qry. Here are what I Believe to be relevant parts of
the JCC logs. These snippets start at the exact same place in the
application.
NOTES:
- In iBATIS/Glassfish pool log, it goes right into the next qry after
the "preparedstatem...@1ff1855] close () called" statement, and does not
contain a big section (including the ENDUOWRM portion) that's included
in the SIMPLE log.
- In iBATIS/GlassFish pool log, the next qry is using a different
connection for the next qry, while the SIMPLE log is using the same
connection for the next qry. This is not visible on the Glassfish pool
log because there are not any "close connection" statements from the
first qry.
Again thanks for taking the time. Any help would be greatly
appreciated. Please let me know if you want to see other parts of the
log or have any other question...
Jeff
1. iBATIS app with SIMPLE Data Source:
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][result...@de43f3]
next () called
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][result...@de43f3]
next () returned false
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][preparedstatem...@4d0ca0]
getMoreResults () called
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][preparedstatem...@4d0ca0]
getMoreResults () returned false
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][result...@de43f3]
close () called
******THIS BELOW SECTION IS NOT PRESENT ON THE GLASSFISH POOL
LOG*************
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][preparedstatem...@4d0ca0]
close () called
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
isClosed () called
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
isClosed () returned false
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
getAutoCommit () returned false
[ibm][db2][jcc][Time:1239883639750][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
rollback () called
[ibm][db2][jcc]
[t4][time:1239883639750][thread:httpSSLWorkerThread-8080-0][tracepoint:5][Request.flush]
[ibm][db2][jcc][t4] SEND BUFFER: RDBRLLBCK (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 000AD00100010004 200F ........
. ..}.......
[ibm][db2][jcc][t4]
[ibm][db2][jcc]
[t4][time:1239883639781][thread:httpSSLWorkerThread-8080-0][tracepoint:2][Reply.fill]
[ibm][db2][jcc][t4] RECEIVE BUFFER: ENDUOWRM (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 002BD05200010025 220C000611490004
.+.R...%"....I.. ..}.............
[ibm][db2][jcc][t4] 0010 00162110D1F3E3F1 4040404040404040
..!.....@@@@@@@@ ....J3T1
[ibm][db2][jcc][t4] 0020 4040404040400005 211502
@@@@@@..!.. .....
[ibm][db2][jcc][t4]
[ibm][db2][jcc][t4] RECEIVE BUFFER: SQLCARD (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0000 000BD00300010005 2408FF
........$.. ..}........
[ibm][db2][jcc][t4]
[ibm][db2][jcc][connect...@1f68572] DB2 LUWID:
GA101042.H306.013A86120719.0001
[ibm][db2][jcc][Time:1239883639781][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
isClosed () called
[ibm][db2][jcc][Time:1239883639781][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
isClosed () returned false
[ibm][db2][jcc][Time:1239883639781][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
getAutoCommit () returned false
[ibm][db2][jcc][Time:1239883639781][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
rollback () called
[ibm][db2][jcc]
[t4][time:1239883639781][thread:httpSSLWorkerThread-8080-0][tracepoint:5][Request.flush]
[ibm][db2][jcc][t4] SEND BUFFER: RDBRLLBCK (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 000AD00100010004 200F ........
. ..}.......
[ibm][db2][jcc][t4]
[ibm][db2][jcc]
[t4][time:1239883639828][thread:httpSSLWorkerThread-8080-0][tracepoint:2][Reply.fill]
[ibm][db2][jcc][t4] RECEIVE BUFFER: ENDUOWRM (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 002BD05200010025 220C000611490004
.+.R...%"....I.. ..}.............
[ibm][db2][jcc][t4] 0010 00162110D1F3E3F1 4040404040404040
..!.....@@@@@@@@ ....J3T1
[ibm][db2][jcc][t4] 0020 4040404040400005 211502
@@@@@@..!.. .....
[ibm][db2][jcc][t4]
[ibm][db2][jcc][t4] RECEIVE BUFFER: SQLCARD (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0000 000BD00300010005 2408FF
........$.. ..}........
[ibm][db2][jcc][t4]
[ibm][db2][jcc][connect...@1f68572] DB2 LUWID:
GA101042.H306.013A86120719.0002
*******************END OF MARKED SECTION************************
[ibm][db2][jcc][Time:1239883639828][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
getAutoCommit () returned false
[ibm][db2][jcc][Time:1239883639828][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
prepareStatement ( SELECT DISTINCT CODE_REGN AS regions
FROM J3TEST.REGN WHERE REGN_FK_AGEN = ? ) called
[ibm][db2][jcc][Time:1239883639828][Thread:httpsslworkerthread-8080-0][connect...@1f68572]
prepareStatement () returned com.ibm.db2.jcc.a...@1fbfeae
—------------------------------------END OF
SNIPPET---------------------------------
2. iBATIS app with GlassFish Connection Pool:
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][result...@372f43]
next () called
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][result...@372f43]
next () returned false
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][preparedstatem...@1ff1855]
getMoreResults () called
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][preparedstatem...@1ff1855]
getMoreResults () returned false
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][result...@372f43]
close () called
[ibm][db2][jcc][Time:1239883479171][Thread:httpsslworkerthread-8080-0][preparedstatem...@1ff1855]
close () called
****new QRY ****
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][connect...@1331ce6]
getTransactionIsolation () returned 1
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][connect...@1331ce6]
getAutoCommit () returned true
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][connect...@1331ce6]
setAutoCommit (false) called
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][connect...@1331ce6]
prepareStatement ( SELECT DISTINCT CODE_REGN AS regions
FROM J3TEST.REGN WHERE REGN_FK_AGEN = ? ) called
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][connect...@1331ce6]
prepareStatement () returned com.ibm.db2.jcc.a...@255d
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][preparedstatem...@255d]
setString (1, BOP) called
[ibm][db2][jcc][Time:1239883479187][Thread:httpsslworkerthread-8080-0][preparedstatem...@255d]
execute () called
—------------------------------------END OF
SNIPPET---------------------------------
3. iBTIS app with the DBCP Commons Pool:
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][result...@b1164d]
next () called
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][result...@b1164d]
next () returned false
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][preparedstatem...@594008]
getMoreResults () called
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][preparedstatem...@594008]
getMoreResults () returned false
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][result...@b1164d]
close () called
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][preparedstatem...@594008]
close () called
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
isClosed () called
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
isClosed () returned false
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
getAutoCommit () returned false
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
isReadOnly () returned false
[ibm][db2][jcc][Time:1239888889968][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
rollback () called
[ibm][db2][jcc]
[t4][time:1239888889968][thread:httpSSLWorkerThread-8080-0][tracepoint:5][Request.flush]
[ibm][db2][jcc][t4] SEND BUFFER: RDBRLLBCK (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 000AD00100010004 200F ........
. ..}.......
[ibm][db2][jcc][t4]
[ibm][db2][jcc]
[t4][time:1239888890015][thread:httpSSLWorkerThread-8080-0][tracepoint:2][Reply.fill]
[ibm][db2][jcc][t4] RECEIVE BUFFER: ENDUOWRM (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 002BD05200010025 220C000611490004
.+.R...%"....I.. ..}.............
[ibm][db2][jcc][t4] 0010 00162110D1F3E3F1 4040404040404040
..!.....@@@@@@@@ ....J3T1
[ibm][db2][jcc][t4] 0020 4040404040400005 211502
@@@@@@..!.. .....
[ibm][db2][jcc][t4]
[ibm][db2][jcc][t4] RECEIVE BUFFER: SQLCARD (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0000 000BD00300010005 2408FF
........$.. ..}........
[ibm][db2][jcc][t4]
[ibm][db2][jcc][connect...@3e0c6] DB2 LUWID:
GA101042.A707.018146133451.0001
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
clearWarnings () called
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
getAutoCommit () returned false
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
setAutoCommit (true) called
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
getAutoCommit () returned true
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
getTransactionIsolation () returned 1
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
getAutoCommit () returned true
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
setAutoCommit (false) called
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
prepareStatement ( SELECT DISTINCT CODE_REGN AS regions
FROM J3TEST.REGN WHERE REGN_FK_AGEN = ? ) called
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][connect...@3e0c6]
prepareStatement () returned com.ibm.db2.jcc.a...@176ade8
[ibm][db2][jcc][Time:1239888890015][Thread:httpsslworkerthread-8080-0][preparedstatem...@176ade8]
setString (1, BOP) called
—------------------------------------END OF
SNIPPET---------------------------------
4. non-iBATIS (straight JDBC coding) application with Glassfish
Connection pool
[ibm][db2][jcc][Time:1239886497015][Thread:httpsslworkerthread-8080-0][result...@128cbd3]
next () returned true
[ibm][db2][jcc][Time:1239886497015][Thread:httpsslworkerthread-8080-0][result...@128cbd3]
getString (SUFFIX_USER) called
[ibm][db2][jcc][Time:1239886497015][Thread:httpsslworkerthread-8080-0][result...@128cbd3]
getString (1) called
[ibm][db2][jcc][Time:1239886497015][Thread:httpsslworkerthread-8080-0][result...@128cbd3]
getString () returned
[ibm][db2][jcc][Time:1239886497015][Thread:httpsslworkerthread-8080-0][result...@128cbd3]
close () called
[ibm][db2][jcc]
[t4][time:1239886497015][thread:httpSSLWorkerThread-8080-0][tracepoint:5][Request.flush]
[ibm][db2][jcc][t4] SEND BUFFER: RDBCMM (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 000AD00100010004 200E ........
. ..}.......
[ibm][db2][jcc][t4]
[ibm][db2][jcc]
[t4][time:1239886497046][thread:httpSSLWorkerThread-8080-0][tracepoint:2][Reply.fill]
[ibm][db2][jcc][t4] RECEIVE BUFFER: ENDUOWRM (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0 1 2 3 4 5 6 7 8 9 A B C D E F
0123456789ABCDEF 0123456789ABCDEF
[ibm][db2][jcc][t4] 0000 002BD05200010025 220C000611490004
.+.R...%"....I.. ..}.............
[ibm][db2][jcc][t4] 0010 00162110D1F3E3F1 4040404040404040
..!.....@@@@@@@@ ....J3T1
[ibm][db2][jcc][t4] 0020 4040404040400005 211501
@@@@@@..!.. .....
[ibm][db2][jcc][t4]
[ibm][db2][jcc][t4] RECEIVE BUFFER: SQLCARD (ASCII)
(EBCDIC)
[ibm][db2][jcc][t4] 0000 000BD00300010005 2408FF
........$.. ..}........
[ibm][db2][jcc][t4]
[ibm][db2][jcc][connect...@1aa7618] DB2 LUWID:
GA101042.C506.0188C6125455.0002
[ibm][db2][jcc][Time:1239886497062][Thread:httpsslworkerthread-8080-0][preparedstatem...@1969fa5]
close () called
[ibm][db2][jcc][Time:1239886497062][Thread:httpsslworkerthread-8080-0][connect...@1aa7618]
prepareStatement (SELECT DISTINCT CODE_REGN FROM J3TEST.REGN WHERE
REGN_FK_AGEN = ?) called
[ibm][db2][jcc][Time:1239886497062][Thread:httpsslworkerthread-8080-0][connect...@1aa7618]
prepareStatement () returned com.ibm.db2.jcc.a...@15db23e
[ibm][db2][jcc][Time:1239886497062][Thread:httpsslworkerthread-8080-0][preparedstatem...@15db23e]
clearParameters () called
[ibm][db2][jcc][Time:12398864970
—------------------------------------END OF
SNIPPET---------------------------------
>>> Mario Ds Briggs <mario.bri...@in.ibm.com> 4/15/2009 7:07 AM >>>
Did you do a compare of the JCC log for the same application run with
a - the glassfish connection pool
b - the ibatis SIMPLE datasource
thanks
Mario
"Jeff Hibbs"
<jhi...@bop.gov>
To
10/04/2009 22:20 <user-java@ibatis.apache.org>
cc
Please respond to
Subject
user-j...@ibatis. Re: Idle Threads - Glassfish/DB2
apache.org
Hi Nathan -
Thanks for the suggestion...as you suspected, it works fine in the test
env
with the SIMPLE datasource that comes with ibatis. While this does
give us
more information, at this point I still have to use the Glassfish
connection pools in production, as ours is one of many apps that reside
on
these (cluster) servers, and we must conform to the standard
Connection
Pools.
Any additional insight into these questions would be greatly
appreciated....
1. Why are the iBATIS queries keeping idle threads open on DB2 while
the
straight JDBC coded queries are not.
2. Why does this only appear to happen with Glassfish Connection
Pools?
Again, thanks for you help! Jeff
>>> Nathan Maves <nathan.ma...@gmail.com> 4/3/2009 10:29 AM >>>
Jeff,
Not to state the obvious but it does not seem like an ibatis issue. It
sounds more like the connection pool implementation of Glassfish. As a
test
you might try creating your own connection pool using the SIMPLE
datasource
type in ibatis just to ensure that it is an issue with Glassfish.
Nathan
On Fri, Apr 3, 2009 at 8:15 AM, Jeff Hibbs <jhi...@bop.gov> wrote:
Hello All -
Any help will be greatly appreciated...Thanks!!!
Our iBatis-based application was running on Sun1 Server/DB2 Version
8 -
z/OS with no problems. When we migrated to Glassfish V2, the DB
folks
noticed many idle threads coming from our application which uses
iBATIS
2.1.5 (July 2005 Build). Other (non-iBATIS) applications that use
straight JDBC (no ORM) on the same server, using the same
connection
pool, were not causing idle threads. Below is a sample what the DBA
is
seeing:
—---------------------------------------------------------------------------------------------------------------------
Primauth Planname name ID Status elapsed time CPU time
xxxxxxxxx DISTSERV SYSLN100 SERVER *DB2 5:23.78195 0.000969
xxxxxxxxx DISTSERV SYSLN100 SERVER *DB2 5:23.67919 0.001146
xxxxxxxxx DISTSERV SYSLN100 SERVER *DB2 5:23.59251 0.000896
xxxxxxxxx DISTSERV SYSLN100 SERVER *DB2 5:18.40476 0.001567
xxxxxxxxx DISTSERV SYSLN100 SERVER *DB2 5:18.38349 0.001066
14.46.15 STC12568 DSNL028I #J3P1 GAD00841.K6FE.C3F92EF69C21=157421
914
914 ACCESSING DATA FOR
914 LOCATION xx.xxx.x.xx
914 IPADDR xx.xxx.x.xx
14.48.14 STC12568 DSNL027I #J3P1 SERVER DISTRIBUTED AGENT WITH 561
561 LUWID=GAD00840.PC1B.C3F92F10E401=157523
561 THREAD-INFO=xxxxxx:genie4:xxxxxxx:db2jcc_applic
561 RECEIVED ABEND=04E
561 FOR REASON=00D3003B
14.48.14 STC12568 DSNL027I #J3P1 SERVER DISTRIBUTED AGENT WITH 562
562 LUWID=GAD00840.PC20.C3F92F1B5DDF=157544
562 THREAD-INFO=xxxxxxx:genie4:xxxxxxx:db2jcc_applic
562 RECEIVED ABEND=04E
562 FOR REASON=00D3003B
—-----------------------------------------------------------------------------------------------------------------------
I'm not going to pretend to know what all this means, but
apparently
iBATIS/Glassfish is not releasing the threads after the SQL
completes.
Again, other non-iBATIS applications using the same connection pool
are
not generating these ilde threads. From a user's perspective the
system
is running fine - the queries are returning quickly. Also, we are
not
exhausting the connections in the connection pool, but apparently
some
resources in DB2 are incorrectly being left open. I guess I'm not
sure
of the difference between a "connection" and a "thread" from the
DB2
perspective.
We have been able to replicate this in the Test env. Here's what we
know
so far:
- Tried iBATIS 2.3.3.720: same results
- Used replaced glassfish with Tomcat and the problem went away
Obvious questions:
1. Why are the iBATIS queries keeping idle threads open on DB2 while
the
straight JDBC coded queries are not.
2. Why does this only appear to happen with Glassfish?
Here's our iBATIS config:
<settings
useStatementNamespaces="false"
cacheModelsEnabled="true"
enhancementEnabled="true"
/>
<transactionManager type="JDBC" >
<dataSource type="JNDI">
<property name="DataSource"
value="java:comp/env/@isds.datasource.name
@"/>
</dataSource>
</transactionManager>
.......
TEST Connection Pool Info:
Datasource Classname: com.ibm.db2.jcc.DB2DataSource (prod same)
Resource Type:javax.sql.DataSource (prod same)
Pool Settings:
Initial and Minimum Pool Size:8 (prod = 0)
Maximum Pool Size: 32 (prod = 300)
Pool Resize Quantity: 2 (prod = 5)
Idle Timeout: 300 (prod = 15)
Max Wait Time:60000 (prod = 60000)
