Jeff,
For iBatis app with SimpleDatasource & DBCP, the transaction is getting
rolled back. (are u running a test case or something)
With Glassfish there is neither a commit or rollback being issued, which is
the problem, since AutoCommit is set to false.
With straight JDBC, i believe you are using auto-commit = true and hence
the implicit flush
Mario
"Jeff Hibbs"
<jhi...@bop.gov>
To
16/04/2009 21:19
cc
"Shau-Chi Tse" <sx...@bop.gov>,
Please respond to <user-java@ibatis.apache.org>
user-j...@ibatis. Subject
apache.org Re: Idle Threads - Glassfish/DB2
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)
