Category: Extended Events

Shortness, Shortness

I use sp_HumanEvents to troubleshoot all sorts of SQL Server issues.

Most frequently, I used it to troubleshoot stored procedure performance like this:

EXEC sp_HumanEvents
    @event_type = 'query',                   
    @query_duration_ms = 5000,               
    @session_id = N'60',                    
    @keep_alive = 1,
    @debug = 1;

The session it creates will have this definition:

CREATE EVENT SESSION keeper_HumanEvents_query
    ON SERVER  
      ADD EVENT sqlserver.module_end 
        (SET collect_statement = 1
         ACTION (sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.query_hash_signed, sqlserver.query_plan_hash_signed)
         WHERE ( 
            sqlserver.is_system = 0 
     AND duration >= 5000000
     AND sqlserver.session_id = 60
 )),
      ADD EVENT sqlserver.rpc_completed 
        (SET collect_statement = 1
         ACTION(sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.query_hash_signed, sqlserver.query_plan_hash_signed)
         WHERE ( 
            sqlserver.is_system = 0 
     AND duration >= 5000000
     AND sqlserver.session_id = 60
 )),
      ADD EVENT sqlserver.sp_statement_completed 
        (SET collect_object_name = 1, collect_statement = 1
         ACTION(sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.query_hash_signed, sqlserver.query_plan_hash_signed) 
         WHERE ( 
            sqlserver.is_system = 0 
     AND duration >= 5000000
     AND sqlserver.session_id = 60
 )),
      ADD EVENT sqlserver.sql_statement_completed 
        (SET collect_statement = 1
         ACTION(sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.query_hash_signed, sqlserver.query_plan_hash_signed)
         WHERE ( 
            sqlserver.is_system = 0 
     AND duration >= 5000000
     AND sqlserver.session_id = 60
 )),
      ADD EVENT sqlserver.query_post_execution_showplan
        (
         ACTION(sqlserver.database_name, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.query_hash_signed, sqlserver.query_plan_hash_signed)
         WHERE ( 
            sqlserver.is_system = 0 
     AND duration >= 5000000
     AND sqlserver.session_id = 60
 ))

I collect:

• module_end
• rpc_completed
• sp_statement_completed
• sql_statement_completed
• query_post_execution_showplan

Not all of them are relevant to stored procedure calls, but in larger contexts where I have no idea where long running queries might be coming from, it’s useful to get all these.

Weirdness, Weirdness

Where I find things getting somewhat annoying is when things start showing up in there that meet the duration filter, but don’t really give me anything further to go on.

To simulate what I mean, I’m going to use this stored procedure:

CREATE OR ALTER PROCEDURE
    dbo.Eventually
AS
BEGIN

    SET NOCOUNT, XACT_ABORT ON;
    
    WAITFOR DELAY '00:00:01.000';
    SELECT TOP (1) * FROM dbo.Badges AS b;
    WAITFOR DELAY '00:00:01.000';
    SELECT TOP (1) * FROM dbo.Comments AS c;
    WAITFOR DELAY '00:00:01.000';
    SELECT TOP (1) * FROM dbo.Posts AS p;
    WAITFOR DELAY '00:00:01.000';
    SELECT TOP (1) * FROM dbo.Users AS u;
    WAITFOR DELAY '00:00:01.000';
    SELECT TOP (1) * FROM dbo.Votes AS v;
    WAITFOR DELAY '00:00:01.000';

END;
GO 

EXEC dbo.Eventually;

There are six waitfor commands that each pause for 1 second. In between them are queries that finish in milliseconds.

If I watch the event output, eventually, I’ll see this:

Okay, so the stored procedure took more than 5 seconds, but… no individual query took more than 5 seconds.

To troubleshoot further, I have to set the duration bar even lower, and then figure out what I can meaningfully tune.

• Do I have one query that takes four seconds
• Do I have ten queries that take 500 milliseconds
• Do I have 500 queries that take ten milliseconds

I see this behavior quite a bit with queries that loop/cursor over tons of data. They might take a whole bunch of rows and do a lot of really fast queries over them, but the time adds up.

There’s not really a good solution for this, either. The closer you look, by reducing the duration filter to lower and lower values, the more you return, the more overhead you cause, and the longer you have to wait for things to finish.

Sure, you can wring someone’s neck about not “thinking in sets”, but that doesn’t help when the processing takes place by passing looped values to stored procedures, unless you have the freedom to make significant app changes by using table valued parameters or something instead.

Thanks for reading!

Going Further

If this is the kind of SQL Server stuff you love learning about, you’ll love my training. I’m offering a 75% discount to my blog readers if you click from here. I’m also available for consulting if you just don’t have time for that, and need to solve database performance problems quickly. You can also get a quick, low cost health check with no phone time required.

Month Of Sundays

A while back, Brent blogged about using September to raise awareness about free SQL Server community tools.

I thought this was a great idea because I maintain a number of them: my own scripts, the First Responder Kit scripts, and sp_WhoIsActive.

Unlike most people who left links in the comments, I read the entire post and decided to use the whole darn month to write about scripts I maintain and how I use them in my work.

Lest I be accused of not being able to read a calendar, I know that these are dropping a little earlier than the 1st of September. I do apologize for September not starting on a Monday.

There are other great tools and utilities out there, like Andy Mallon’s DBA Utility Database, but I don’t use them enough personally to be able to write about them fluently.

My goal here is to help you use each script with more confidence and understanding. Or even any confidence and understanding, if none existed beforehand.

Oral Board

First up is (well, I think) my most ambitious script: sp_HumanEvents. If you’re wondering why I think it’s so ambitious, it’s because the goal is to make Extended Events usable by Humans.

At present, that’s around 4000 lines of T-SQL. Now, sp_HumanEvents can do a lot of stuff, including logging event data to tables for a bunch of different potential performance issues.

When I was first writing this thing, I wanted it to be able to capture data in a few different ways to fit different monitoring scenarios. In this post, I’m going to show you how I most often use it on systems that have are currently experiencing blocking.

First, you need to have the Blocked Process Report enabled, which is under advanced options:

EXEC sys.sp_configure 'show advanced options', 1;
RECONFIGURE;
EXEC sys.sp_configure 'blocked process threshold', 5;
RECONFIGURE;

If you want to flip the advanced options setting back, you can. I usually leave it set to 1.

The second command turns on the blocked process report, and tells SQL Server to log any instances of blocking going on for 5 or more seconds. You can adjust that to meet your concerns with blocking duration, but I wouldn’t set it too low because there will be overhead, like with any type of monitoring.

Blockeroos

The way I usually set up to look at blocking that’s currently happening on a system — which is what I most often have to do — is to set up a semi-permanent session and watch what data comes in.

When I want to parse that data, I use sp_HumanEventsBlockViewer to do that. At first, I just want to see what kind of stuff starts coming in.

To set that session up, here’s what I do:

EXEC sp_HumanEvents
    @event_type = 'blocking',                   
    @keep_alive = 1;

What this will do is set up an Extended Event session to capture blocking from the Blocked Process Report. That’s it.

From there, you can either use my script (linked above), or watch data coming in via the GUI. Usually I watch the GUI until there’s some stuff in there to gawk at:

EXEC dbo.sp_HumanEventsBlockViewer
    @session_name = 'keeper_HumanEvents_blocking'

Blockerinos

Once you have the blocking collected, troubleshooting it is a whole… Fun… thing.

• Misguided use of transactions
• Misguided use of isolation levels
• Misguided use of locking hints

Are common reasons behind blocking, but not always. Common solutions are things like:

• Making sure foreign keys have supporting indexes, especially ones with cascading actions
• Getting angry at Triggers and throwing your computer out the window
• Making sure modification queries have adequate supporting indexes
• Batching modifications on large chunks of data
• Enabling an optimistic isolation level because Read Committed Is A Garbage Isolation Level

Thanks for reading!

Going Further

If this is the kind of SQL Server stuff you love learning about, you’ll love my training. I’m offering a 75% discount to my blog readers if you click from here. I’m also available for consulting if you just don’t have time for that, and need to solve database performance problems quickly. You can also get a quick, low cost health check with no phone time required.

Touchy, Touchy

I’ve made some slight tweaks to sp_HumanEvents.

One of them fixes a bug with view creation when you use a custom schema. The rest are minor tweaks and fixes that you (hopefully won’t notice one bit), but make me feel a little bit better about the state of the code.

You can learn how to use the proc, and download the latest version over here.

I took a look through SQL Server 2022’s new Extended Events, and haven’t seen anything in there that would warrant the amount of work it takes to add something new just yet. Maybe at some point, I suppose.

Some folks had asked about adding lightweight query profiling etc. as an option, but it still doesn’t return the kind of details that make it useful for query tuning.

I mean, I guess if you believe in memes it’s okay, but… Maybe you should stop that.

Thanks for reading!

Going Further

If this is the kind of SQL Server stuff you love learning about, you’ll love my training. I’m offering a 75% discount to my blog readers if you click from here. I’m also available for consulting if you just don’t have time for that and need to solve performance problems quickly.