8

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:

  1. I'm wanting to see the frequency (or lack-thereof) for which a stored procedure has been called.
  2. 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:

  1. The calls had legitimate parameters.
  2. 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 row_count correctly as 1 instead of 0.

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:

Extended Event Results

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:

  1. Is there something I can add to the Extended Event session to correctly record the row_count?
  2. Is there possibly some way these stored procedures are being called where they are actually returning results, but somehow emitting 0 to the Extended Event?
  3. Why would an active SQL Profiler session have suddenly made the Extended Event session record the correct row_count data?

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 OPENROWSET session on a different server.
  • Executing the stored procedure within a TRANSACTION that then forced a ROLLBACK.
  • Executing the stored procedure within an uncommitted TRANSACTION.
  • Use of SET NOCOUNT ON
  • Additional SELECT or SET statements after the actual SELECT.
  • Use of OUTPUT in the procedure.
  • Use of MERGE or UPDATE statements exclusively.
  • Checked for SERVICE BROKER usage, and found that the queries were not being recorded with is_system set to True.

All of the above situations failed to yield a row_count of 0 when supplied with a valid @ID parameter.

I'm trying to understand how it can happen, and in turn, also trying to figure out how to remedy it.

0

1 Answer 1

3

One case I know of is when the procedure is called via the Service Broker Activation.

I was able to reproduce (please note, I've added an extra statement to your procedure so that it would return more rows - a select from values (1) (2) (3)).

enter image description here

Notice that the last column is_system is True for executing the Activation procedure. This column is not tracked by default; you have to add it via Global Fields (Actions)

1
  • Unfortunately, it doesn't look like this is the cause. Adding is_system to the XE still showed 0 row_counts with is_system = False, and when I turned on a vanilla profiler, they immediately changed to a 1 row_count, also as is_system = False. But this is really good information, thank you!
    – Siyual
    Jun 30, 2022 at 13:33

Your Answer

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

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