Extended Events, sp_reset_connection and sql_text

Question

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.

Answer 1

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

and this one:

Answer 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!