Transactions within transactions

[tyronetv]

I have a set of two logs that share a common field (RID). One log contains the "user" actions while the other log contains the java, odbc, etc., actions (ibatis log).

What I need to do, is figure out if there is a delay between when a user makes a request and the actual connection to the database.

2013-08-19 06:40:32,904 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning - <DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.getTransactionDetails {INPUT PARAMS} {transactionid=2404611298, callinguserid=-5710326788253269740}

2013-08-19 06:40:32,908 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-473946} Connection

... some other actions .....

2013-08-19 06:40:33,332 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning - <DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.lockTransaction {INPUT PARAMS} {transactionid=2404611298, latestchangeid=449327573, callinguserid=-5710326788253269740}

2013-08-19 06:40:33,333 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-473948} Connection

...some other actions....

2013-08-19 06:45:06,130 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning - <DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.getCouponFieldMappings {INPUT PARAMS} {documentTypeId=2642998, callinguserid=-5710326788253269740}

2013-08-19 06:45:06,130 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-486974} Connection

... and other various versions of this....

2013-08-19 06:40:32,904 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning - <DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.getTransactionDetails {INPUT PARAMS} {transactionid=2404611298, callinguserid=-5710326788253269740}

2013-08-19 06:40:32,908 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-473946} Connection

... some other actions .....

2013-08-19 06:40:33,332 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning - <DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.lockTransaction {INPUT PARAMS} {transactionid=2404611298, latestchangeid=449327573, callinguserid=-5710326788253269740}

2013-08-19 06:40:33,333 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-473948} Connection

...some other actions....

2013-08-19 06:45:06,130 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 c.r.t.r.o.service.OnlineDecisioning -<DAO CALL START> {USER ID} null {DAO PROCEDURE} OnlineDecisioning.getCouponFieldMappings {INPUT PARAMS} {documentTypeId=2642998, callinguserid=-5710326788253269740}

2013-08-19 06:45:06,130 DEBUG [andler-RMICallHandler-192] RID=1376919632894-63948 java.sql.Connection - {conn-486974} Connection

... and other various versions of this....

As you can see, the connection is VERY fast. Unfortunately, sometimes, it is not. When it is NOT we have a problem that is about ready to increase exponentially and cause some pain for our customers and, well, me.

What I want to do is put in place a 'real time' monitor that says the time between the line with <DAO CALL START> in a sourcetype of t2_app and the java.sql.Connection in the sourcetype of ibatis cant exceed X seconds or milliseconds. (And, also to be able to graph normal response times.)

I can do a <DAO START> to a <DAO COMPLETE> but that is too much. Just need to know from start to DB connect.

Suggestions?

Thanks!

[tyronetv · Accepted solution]

transaction RID startswith="DAO CALL START" endswith=" Connection"

Yeah... I should of figured that out sooner.

Thanks for the assist though.

[Ayn]

Perhaps something like

... | transaction RID startswith="DAO CALL START" endswith="java.sql.Connection" | search duration>1

?

[Ayn]

The startswith argument means transaction will begin a new transaction whenever it sees that string. What are your results when you use this?

[tyronetv]

Doesn't work. Been there done that. 😞

As you can see from my example, there are multiple connections to the DB under one RID.

I need each one encapsulated and that search didn't do it for me.

[tyronetv]

AFAICT from the logs, and because I am doing a transaction based upon the RID, the connect is just the next sequential step after the DAO START.

[Ayn]

How do you relate the db connection to a particular DAO START message? Or is it always sequential so you can count on that the first connection following DAO START is the connection that's related to it?