Splunk Search

Transactions within transactions

tyronetv
Communicator

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!

Tags (2)
0 Karma
1 Solution

tyronetv
Communicator

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

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

Thanks for the assist though.

View solution in original post

0 Karma

tyronetv
Communicator

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

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

Thanks for the assist though.

0 Karma

Ayn
Legend

Perhaps something like

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

?

0 Karma

Ayn
Legend

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

0 Karma

tyronetv
Communicator

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.

0 Karma

tyronetv
Communicator

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.

0 Karma

Ayn
Legend

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?

0 Karma
Get Updates on the Splunk Community!

Extending Observability Content to Splunk Cloud

Register to join us !   In this Extending Observability Content to Splunk Cloud Tech Talk, you'll see how to ...

What's new in Splunk Cloud Platform 9.1.2312?

Hi Splunky people! We are excited to share the newest updates in Splunk Cloud Platform 9.1.2312! Analysts can ...

What’s New in Splunk Security Essentials 3.8.0?

Splunk Security Essentials (SSE) is an app that can amplify the power of your existing Splunk Cloud Platform, ...