3

I have extended event sessions running on 3 different servers. I am looking for long running or excessively called stored procedures and in-line queries (ORMs, primarily nHibernate).

The output for rpc_completed event_name shows 'sp_reset_connection' for object_type and statement_text. But, it also has a query captured in sql_text.

Does Extended Events capture the 2 executions --sp_reset_connection and the query -- as a single event? Should I view the duration value to be for the combined time for sp_reset_connection plus the query in sql_text or statement_text? Or, is it capturing sp_reset_connection and simply showing the query that triggered sp_reset_connection?

I was expecting the sp_reset_connection and the queries to be separate events.

CLARIFICATION: Why does Extended Events return a conflict between fields?

1. object_name = 'sp_reset_connection'
2. statement = 'exec sp_reset_connection'
3. sql_text = a query (ex: '(@p0 int)SELECT specificat0_.ScenarioId ...')

Why is sql_text different? In a typical Extended Events row (XML), the 3 fields are in agreement as to what has been executed. Which leaves me with the question of "What was executed?". Should the duration field value be assigned to sp_reset_connection? Or the in-line sql found in sql_text? Or both?

I understand what sp_reset_connection is and how it works. What I do not understand is how Extended Events is reporting it. Profiler did not have ambiguity when reporting sp_reset_connection.

My conclusion is that Extended Events is returning the results for sp_reset_connection. However, that is a conclusion based on what I observe -- i.e a guess. I need something more concrete: even if only someone else that reached the same conclusion.

This article indicates that I can ignore sql_text.

https://www.sqlskills.com/blogs/jonathan/understanding-the-sql_text-action-in-extended-events/

Thank you for your help.

10
  • dup on SO
    – SMor
    Jan 5, 2022 at 1:03
  • You shouldn't care at all about sp_reset_connection, it's designed to reset the connection settings with connection pooling. It's called specially by a specific bit in a TDS packet, it takes up one eighth of a byte and a tiny amount of time to execute. See also sqlskills.com/blogs/bobb/… et al Jan 5, 2022 at 1:20
  • @Charlieface I agree. sp_reset_connection should not be an issue. Problem is which do I believe? object_name, statement or sql_text? sql_text contains a query. object_name = sp_reset_connection. statement = exec sp_reset_connection. duration = 5. My conclusion is that object_name = sp_reset_connection is the driver. But, that is just my opinion.
    – jim
    Jan 5, 2022 at 1:31
  • I think statement is just a representation of what an RPC call would look like if executed in T-SQL (Profiler shows the same by the way). An RPC call doesn't do that, it uses a more specialized TDS format. And sp_reset_connection isn't really an RPC call either, as mentioned. So I'm unclear what you are trying to find out: you cannot call sp_reset_connection from code, so it must be the RESETCONNECTION bit being set. Ergo, why do you care at all about this? It's simply an observational artefact and shouldn't affect your life Jan 5, 2022 at 1:39
  • 1
    Noting was executed, at least nothing that can be seen as "normal SQL or procedure call". A signal was sent over the TDS protocol instructing SQL Server to clean up this connection. XE represents this as sp_reset_connection, even though there's no procedure with that name. Or are you saying that you have something different in there like a "real" query or procedure? If so, please add details/example to your initial post and comment here. My guess in that case is that the client submitted a query or "real" proc call, and the TDS package also has the "reset" bit on. Jan 5, 2022 at 7:20

2 Answers 2

5

I will preface this by saying that sp_reset_connection is not something you normally need to worry about. It is not executed as a full RPC call, it's just a single bit flag in a TDS packet, and executes very quickly.

Furthermore, XEvents and Profiler present it, as well as normal RPC stored procedure calls, in the form exec SomeProc @param1..., but that is not what is actually executing. It is merely a textual representation of what such a call might look like if executed as a T-SQL batch. RPC calls instead use a specific TDS mechanism, which passes just SomeProc, and separately passes the parameters.

Given that, and judging from my own testing, I think what is going on here is that XEvents is showing each procedure call, as well as a separate call to sp_reset_connection, even though they are from the same RPC call.

So for an ad-hoc batch with parameters, you get sql_text = '(@param1 ...)SELECT whatever', because that is the call that has triggered sp_reset_connection (although in testing I don't get this detail). And as mentioned in your linked article, this value should really be called input_buffer which is what it really represents.

Meanwhile, statement = 'exec sp_reset_connection' because that is what the equivalent T-SQL might look like (you can't actually call it directly in T-SQL, although you can with a normal RPC call eg via SqlClient).

And the actual object being called is stored in object_name = 'sp_reset_connection'. This is what you should focus on if you want to know if a stored procedure was called, or if sp_executesql was called (for ad-hoc). And you should add a filter to your XEvent to remove sp_reset_connection

....
  ADD EVENT sqlserver.rpc_completed(
    ACTION(sqlserver.sql_text)
    WHERE (object_name <> 'sp_reset_connection')
  )

To prove my point that there are two events being triggered, and that both show the input batch in sql_text, see the following screenshots of a parameterized ad-hoc batch sent from .Net's SqlClient

reset event

and this one:

main event

2
  • Thank you!! That was the goal!
    – jim
    Jan 5, 2022 at 14:31
  • Thank you again. I really appreciate the effort you made for the answer.
    – jim
    Jan 5, 2022 at 16:50
2

[EDIT] Charlieface is indeed correct in that the trace engine show two events and not one. I'll leave this for clarity and in case others read this thread.[/EDIT]

Charlieface's answer suggests that you see two events in the trace for what is actual one event in the engine. I.e., the client sends a query to SQL Server and the TDS package also has the "reset connection" bit turned on.

The way I read your updated question text, it seems that you have one event in the trace, not two events. I conclude this from your CLARIFICATION where you say you have three fields from what I assume is one (1) event:

CLARIFICATION: Why does Extended Events return a conflict between fields?

  1. object_name = 'sp_reset_connection'
  2. statement = 'exec sp_reset_connection'
  3. sql_text = a query (ex: '(@p0 int)SELECT specificat0_.ScenarioId ...')

So, The first two fields (1 and 2) represents the "clean up connection" bit in the TDS package. And the third field represent the actual query that was submitted (in that same package, represented as one event).

Say that you add the suggested filter to your trace:

WHERE (object_name <> 'sp_reset_connection')

You now miss the actual SQL query that the client submitted, which was the whole reason for running the trace in the first place!

7
  • 1
    Your answer is exactly what prompted me to ask my question. So, I up voted it. However, as best as I can tell it is a single event: exec sp_reset_connection. In addition to @charlieface's comment, I found the following: 1) the link I provided in the CLARIFICATION section of my Question; 2) my understanding of xevents rpc completed: one row - one event and 3) typical 5 microsecond duration for the events. The query text found in sql_text would take 50 to 500 milliseconds to execute (nHibernate sql). For now, I conclude that one row = exec sp_reset_connection. Thank you for your reply.
    – jim
    Jan 7, 2022 at 20:52
  • 1
    I indeed see two separate events in the XEvent trace, with the same sql_text but one has object_name = 'sp_reset_connection' will post a screenshot soon Jan 8, 2022 at 21:12
  • 1
    See new screenshots in my answer showing two separate events Jan 9, 2022 at 1:41
  • 1
    Thanks @Charlieface, that makes it perfectly clear! So there's really only one TDS package containing both the reset bit as well as a query, but XE show this as two events. IMO, XE is misleading in doing that, considering there's a field (action?) for the reset option available, so generating only one event should be less confusing. I'll leave my answer with some edits in case future readers might have the same line of thoughts... Jan 9, 2022 at 11:30
  • 1
    I think the point is that two procedures are being called via RPC, using the same input buffer. If you think of sql_text as representing the input buffer not the currently executing SQL, then it makes more sense Jan 9, 2022 at 11:31

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.