I'm running an Extended Event session in SQL Server 2017 that's only recording
module_end events for a specific database. The reason for this trace is two-fold:
- I'm wanting to see the frequency (or lack-thereof) for which a stored procedure has been called.
- I'm trying to get some specifics for each procedure call (e.g. who called it, from where, how long it took, how many records were returned, etc.).
When looking at some of the results, I noticed that there were a few procedures on the list that had tens of millions of executions, but had never once had a
row_count greater than 0. There were plenty of other recorded events with
row_count seemingly properly populated, so I had initially considered that the ones that had never returned a result had been miscalled by the applications referencing them. However, this turned out not to be the case.
To get a better look at the parameters the procedures had been called with, I started up a Profiler session watching for just those procedure calls. The particular procedure I was checking was being called extremely frequently, and I got a good number of example calls rather quickly, and turned off the Profiler. There were a couple things noticed from this:
- The calls had legitimate parameters.
- Having made no changes to the Extended Event session, the recorded procedure calls during the time that the Profiler was active magically started recording the
Below is the definition of the Extended Event that I'm using:
Create Event Session [Test Event] On Server Add Event sqlserver.module_end ( Action (sqlserver.database_name, sqlserver.session_id) Where ( sqlserver.database_name = N'TestDatabase' And object_type = 'P' ) ) Add Target package0.ring_buffer (Set max_events_limit = 10000, max_memory = 51200) With ( Max_Memory = 4096KB, Event_Retention_Mode = Allow_Single_Event_Loss, Max_Dispatch_Latency = 30 Seconds, Max_Event_Size = 0KB, Memory_Partition_Mode = None, Track_Causality = On, Startup_State = On ) Go
And some sample code to test with:
Use TestDatabase Go Create Table TestTable ( ID Int Not Null Identity (1, 1) Primary Key Clustered, Name Varchar (20) ) Go Insert TestTable (Name) Values ('Alpha'), ('Bravo'), ('Charlie'), ('Delta'), ('Echo'), ('Foxtrot'), ('Golf') Go Create Procedure GetTestNameByID (@ID Int) As Begin Set NoCount On Select Name From TestTable Where ID = @ID End Go Execute GetTestNameByID @ID = 2 Execute GetTestNameByID @ID = 10 Execute GetTestNameByID @ID = Null Go Drop Procedure GetTestNameByID Drop Table TestTable Go
Note: the real procedure I'm noticing the odd behavior with is logically equivalent to the testing procedure above.
Running each of the three
Execute statements results in the following in the Extended Event:
In this example, the
row_counts recorded in the Extended Event are correct. However, in the actual environment, all of these are being recorded as
0, even though they are actually returning results.
Here are my questions:
- Is there something I can add to the Extended Event session to correctly record the
- Is there possibly some way these stored procedures are being called where they are actually returning results, but somehow emitting
0to the Extended Event?
- Why would an active SQL Profiler session have suddenly made the Extended Event session record the correct
Again, I do want to stress that there were no changes made to the Extended Event session, and there are seemingly correct results in the exact same trace file for other stored procedures.
Additional scenarios I've tested:
- Executing the stored procedure from within another procedure.
- Executing the stored procedure from another database on the same server.
- Executing the stored procedure from an
OPENROWSETsession on a different server.
- Executing the stored procedure within a
TRANSACTIONthat then forced a
- Executing the stored procedure within an uncommitted
- Use of
SET NOCOUNT ON
SETstatements after the actual
- Use of
OUTPUTin the procedure.
- Use of
- Checked for
SERVICE BROKERusage, and found that the queries were not being recorded with
All of the above situations failed to yield a
0 when supplied with a valid
I'm trying to understand how it can happen, and in turn, also trying to figure out how to remedy it.