Erik Darling – Page 81

Performance Issues With NOT EXISTS Queries In SQL Server

Posted on November 15, 2021May 16, 2022 by Erik Darling

Born Day

I’m going to start this post off sort of like Friday’s post:

Look, I really like EXISTS and NOT EXISTS. I do. They solve a lot of problems.

This post isn’t a criticism of them at all, nor do I want you to stop using them. I would encourage you to use them more, probably.

If you keep your head about you, you’ll do just fine.

The difference here is specific to NOT EXISTS, though, and it has to do with join reordering.

Or rather, the lack of join reordering.

Let’s get after it.

Happy Kids

When we write our query like so, things are fine.

The Users and Badges tables are relatively small, and a parallel hash join query makes short work of the situation.

SELECT
    c = COUNT_BIG(*)
FROM dbo.Users AS u
WHERE u.Reputation > 1000
AND   
(
    NOT EXISTS
        (
            SELECT
                1/0
            FROM dbo.Badges AS b
            WHERE b.UserId = u.Id
        )
    AND  NOT EXISTS
             (
                 SELECT
                     1/0
                 FROM dbo.Comments AS c
                 WHERE c.UserId = u.Id
             )      
);

This query finishes in a shart under a second.

Notice that since no rows pass the first join, the Comments table is left unscathed.

BUT THEN™

Bad Times

If we write the query like this, the optimizer leaves things alone, and we get a much worse-performing query.

SELECT
    c = COUNT_BIG(*)
FROM dbo.Users AS u
WHERE u.Reputation > 1000
AND   
(
    NOT EXISTS
        (
            SELECT
                1/0
            FROM dbo.Comments AS c
            WHERE c.UserId = u.Id
        )   
    AND NOT EXISTS
            (
                SELECT
                    1/0
                FROM dbo.Badges AS b
                WHERE b.UserId = u.Id
            )   
);

This one clocks in around 6 seconds, and complains of an excessive memory grant.

The big time suck here is spent hitting the Comments table, which is significantly larger than the Badges table.

Totally Wired

The order that you write joins and where clause elements in generally doesn’t matter much, but in the case of NOT EXISTS, it can make a huge difference.

I realize that there are only two NOT EXISTS clauses in these examples, and that hardly makes for a compelling “always” statement. But I did a lot of experimenting with more tables involved, and it really doesn’t seem like the optimizer does any reordering of anti-semi joins.

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.

Performance Issues With EXISTS Queries In SQL Server

Posted on November 12, 2021May 16, 2022 by Erik Darling

Dos Puntos

Look, I really like EXISTS and NOT EXISTS. I do. They solve a lot of problems.

This post isn’t a criticism of them at all, nor do I want you to stop using them. I would encourage you to use them more, probably.

But there’s some stuff you need to be aware of when you use them, whether it’s in control-flow logic, or in queries.

If you keep your head about you, you’ll do just fine.

IF EXISTS

The issue you can hit here is one of row goals. And a T-SQL implementation shortcoming.

If I run this query, it’ll chug along for about 10 seconds.

IF EXISTS
(
    SELECT 
       1/0
    FROM dbo.Posts AS p
    JOIN dbo.Votes AS v
        ON  p.Id = v.PostId
    WHERE v.VoteTypeId = 1
    AND   v.CreationDate >= '2018-12-01'
    AND   p.PostTypeId = 1
)
BEGIN
    SELECT x = 1;
END;

The part of the plan that we care about is a seek into the Votes table.

SQL SERVER’S COST BASED OPTIMIZER™ thinks that 2.52 (rounded to 3) rows will have to get read to find data we care about, but it ends up having to do way more work than that.

It’s worth a short topic detour here to point out that when you’re tuning a slow query, paying attention to operator costs can be a real bad time. The reason this query is slow is because the costing was wrong and it shows. Costed correctly, you would not get this plan. You would not spend the majority of the query execution time executes in the lowest-costed-non-zero operator.

Normally, you could explore query hints to figure out why this plan was chosen, but you can’t do that in the context of an IF branch. That sucks, because a Hash Join hinted query finished in about 400ms. We could solve a problem with that hint, or if we disabled row goals for the query.

Fixing It

In order to tune this, we need to toggle with the logic a little bit. Rather than put a query in the IF EXISTS, we’re going to set a variable based on the query, and use the IF logic on that, instead.

DECLARE
    @do_it bit;

SELECT
    @do_it = 
    (
        SELECT 
            CONVERT
            (
                bit,
                ISNULL
                (
                    MAX(1), 
                	0
                )
            )
        FROM dbo.Posts AS p
        JOIN dbo.Votes AS v
            ON  p.Id = v.PostId
        WHERE v.VoteTypeId = 1
        AND   v.CreationDate >= '2018-12-01'
        AND   p.PostTypeId = 1
    )
OPTION(HASH JOIN);

IF @do_it = 1
BEGIN
    SELECT x = 1;
END;

This produces the fast plan that we’re after. You can’t use a CASE expression here and get a hash join though, for reasons explained in this post by Pablo Blanco.

But here it is. Beautiful hash join.

EXISTS With OR Predicates

A common query pattern is to is EXISTS… OR EXISTS to sort out different things, but you can end up with a weird optimizer query rewrite (SplitSemiApplyUnionAll) that looks a lot like the LEFT JOIN… IS NULL pattern for finding rows that don’t exist. Which is generally a bad pattern, as discussed in the linked post.

Anyhoo.

SELECT
    c = COUNT_BIG(*)
FROM dbo.Users AS u
WHERE u.Reputation > 1000000
AND   EXISTS
      (
          SELECT
              1/0
          FROM dbo.Badges AS b
          WHERE b.UserId = u.Id
      )
OR    EXISTS
      (
          SELECT
              1/0
          FROM dbo.Comments AS c
          WHERE c.UserId = u.Id
      );

This is what I’m talking about, in the plan for this query.

Rather than do two semi joins here for the EXISTS, we get two right outer joins. That means (like in the linked post above), all rows between tables are joined, and filters are applied much later on in the plan. You can see one of the right outer joins, along with the filters (on expressions!) in the nice picture up there.

Fixing It

The fix here, of course (of course!) is to write the query in a way that the optimizer can’t apply that foolishness to.

SELECT
    c = SUM(x.c)
FROM 
(
    SELECT
        c = COUNT_BIG(*)
    FROM dbo.Users AS u
    WHERE u.Reputation > 1000000
    AND   EXISTS
          (
              SELECT
                  1/0
              FROM dbo.Badges AS b
              WHERE b.UserId = u.Id
          )
    
    UNION ALL
    
    SELECT
        c = COUNT_BIG(*)
    FROM dbo.Users AS u
    WHERE EXISTS
          (
              SELECT
                  1/0
              FROM dbo.Comments AS c
              WHERE c.UserId = u.Id
          )
) AS x;

This query completes in around 1.5 seconds, compared to 4.9 seconds above.

Seasoned Veteran

It’s rough when you run into these problems, because solutions aren’t always obvious (obvious!), nor is the problem.

Most of the posts I write about query tuning arise from issues I solve for clients. While most performance problems come from predictable places, sometimes you have to deal with edge cases like this, where the optimizer mis-costs things.

Thanks for reading!

Going Further

sp_WhoIsActive Version 12 Is Out!

Posted on November 11, 2021May 16, 2022 by Erik Darling

Get’em Daddy

You know, you love it, you often wondered if it would ever get a new version!

Someone JUST asked me yesterday if this has been updated recently. Thank you for sharing!

— Erin Stellato (@erinstellato) November 10, 2021

Now it has! <— Click there to get it.

What’s New?

New parameter, @get_memory_info, that exposes memory grant information, both in two top-level scalar columns and a new XML-based memory_info column.
Better handling of the newer CX* parallelism wait types that have been added post-2016
A top-level implicit_transaction identifier, available in @get_transaction_info = 1 mode
Added context_info and original_login_name to additional_info collection
A number of small bug fixes
Transition code to use spaces rather than tabs

New file name: Not an enhancement per se, but please note that starting with this release there is a new source file, sp_WhoIsActive.sql. The old file, who_is_active.sql, will be kept around for a few months and then removed. Please migrate any processes that might be using the old name.

What Does It Look Like?

For memory grant information:

You’ll wanna run like so:

EXEC sp_WhoIsActive
    @get_memory_info = 1;

You’ll get back some new columns:

In the XML, you’ll see stuff like this, which is pretty cool.

<memory_info>
  <memory_grant>
    <request_time>2021-11-11T05:08:57.870</request_time>
    <grant_time>2021-11-11T05:08:57.870</grant_time>
    <requested_memory_kb>17350600</requested_memory_kb>
    <granted_memory_kb>17747912</granted_memory_kb>
    <used_memory_kb>17743872</used_memory_kb>
    <max_used_memory_kb>17743872</max_used_memory_kb>
    <ideal_memory_kb>85373512</ideal_memory_kb>
    <required_memory_kb>1352</required_memory_kb>
    <dop>8</dop>
    <query_cost>4791.8359</query_cost>
  </memory_grant>
  <resource_semaphore>
    <timeout_error_count>0</timeout_error_count>
    <target_memory_kb>69402424</target_memory_kb>
    <max_target_memory_kb>69402424</max_target_memory_kb>
    <total_memory_kb>69402424</total_memory_kb>
    <available_memory_kb>51654512</available_memory_kb>
    <granted_memory_kb>17747912</granted_memory_kb>
    <used_memory_kb>17679048</used_memory_kb>
    <grantee_count>1</grantee_count>
    <waiter_count>0</waiter_count>
  </resource_semaphore>
  <workload_group>
    <name>default</name>
    <request_max_memory_grant_percent>25</request_max_memory_grant_percent>
    <request_max_cpu_time_sec>0</request_max_cpu_time_sec>
    <request_memory_grant_timeout_sec>0</request_memory_grant_timeout_sec>
    <max_dop>0</max_dop>
  </workload_group>
  <resource_pool>
    <name>default</name>
    <min_memory_percent>0</min_memory_percent>
    <max_memory_percent>100</max_memory_percent>
    <min_cpu_percent>0</min_cpu_percent>
    <max_cpu_percent>100</max_cpu_percent>
  </resource_pool>
</memory_info>

For parallelism information:

You’ll wanna run like so:

EXEC sp_WhoIsActive
    @get_task_info = 2;

You’ll see this in the wait_info column, if your queries are hitting parallelism waits. Previously we only support CXPACKET, but now we support CXPACKET, CXCONSUMER, CXSYNC_PORT, and CXSYNC_CONSUMER.

This can be really helpful for tracking down issues in parallel queries.

For implicit transaction information:

You’ll wanna run like so:

EXEC sp_WhoIsActive
    @get_transaction_info = 1;

You’ll see a new column that will tell you if your god-awful JDBC driver is using the absolute mistake known as implicit transactions.

For additional info:

You’ll wanna run like so:

EXEC sp_WhoIsActive
    @get_additional_info = 1;

You’ll get back this column:

If you click on it, you’ll get back this output, which now includes original login name, and context info.

<additional_info>
  <text_size>2147483647</text_size>
  <language>us_english</language>
  <date_format>mdy</date_format>
  <date_first>7</date_first>
  <quoted_identifier>ON</quoted_identifier>
  <arithabort>ON</arithabort>
  <ansi_null_dflt_on>ON</ansi_null_dflt_on>
  <ansi_defaults>OFF</ansi_defaults>
  <ansi_warnings>ON</ansi_warnings>
  <ansi_padding>ON</ansi_padding>
  <ansi_nulls>ON</ansi_nulls>
  <concat_null_yields_null>ON</concat_null_yields_null>
  <transaction_isolation_level>ReadCommitted</transaction_isolation_level>
  <lock_timeout>-1</lock_timeout>
  <deadlock_priority>0</deadlock_priority>
  <row_count>0</row_count>
  <command_type>SELECT</command_type>
  <sql_handle>0x020000004d3842022d406c17300f7e339224b8c5e0392bbb0000000000000000000000000000000000000000</sql_handle>
  <plan_handle>0x060008004d38420210a907e34d01000001000000000000000000000000000000000000000000000000000000</plan_handle>
  <statement_start_offset>122</statement_start_offset>
  <statement_end_offset>534</statement_end_offset>
  <host_process_id>16688</host_process_id>
  <group_id>2</group_id>
  <original_login_name>sa</original_login_name>
  <context_info>0x0000008a</context_info>
</additional_info>

Which is useful for people doing really weird stuff. Questionable stuff.

Again, you can grab the new version here!

Thanks for reading!

Going Further

TRY_CAST And TRY_CONVERT Can Still Throw Errors In SQL Server

Posted on November 10, 2021May 16, 2022 by Erik Darling

It Was Written

I was a bit surprised by this, because I thought the whole point of these new functions was to avoid errors like this.

SELECT
    oops = TRY_CONVERT(uniqueidentifier, 1);
GO 

SELECT
    oops = TRY_CAST(1 AS uniqueidentifier);
GO

Both of these selects will throw the same error message:

Msg 529, Level 16, State 2, Line 2
Explicit conversion from data type int to uniqueidentifier is not allowed.

Which, you know, fine. I get that limitation of an explicit cast or convert, but why not just throw a NULL like other cases where the expression isn’t successful?

Bummer.

Thanks for reading!

Going Further

I’m Officially A Maintainer Of sp_WhoIsActive!

Posted on November 9, 2021May 16, 2022 by Erik Darling

Busyness, Man

sp_WhoIsActive is probably one of the most famous utilities in SQL Server. To the point where when I see people using sp_who – sp_who4762, I immediately disqualify their ability as a DBA.

If you think that’s unfair, it’s probably because you use sp_who2.

But anyway, with Mr. Machanic being busy with outside of SQL Server projects, the script hadn’t been getting much attention lately. Since I had been working on a couple issues, and saw other piling up, I offered to help with Adam’s project in the same way I help with the First Responder Kit stuff.

I’ll be working on issues over there to get new stuff and bug fixes into the script. If there’s anything you’d like to see in there, or see fixed, let us know!

Help You

If you’re hitting an issue with the script and you want to do some investigating, here’s what I suggest doing.

EXEC sp_WhoIsActive
    @show_own_spid = 1,
    @get_full_inner_text = 1;

Run that along with any of the other parameters you’re using, and click on the sql_text column, that’ll give you the whole query that WhoIsActive runs. Paste that into a new SSMS window, and get rid of the XML artifacts like <?query -- and --?>.

After that, you’ll have to declare a few variables to make things run correctly:

DECLARE
    @i bigint = 922337203685477580,
    @recursion smallint = 1,
    @blocker bit = 0;

You’ll also wanna delete some of the header information that comes along:

(@recursion SMALLINT, @filter sysname, @not_filter sysname, @first_collection_ms_ticks BIGINT)DECLARE @blocker BIT;
SET @blocker = 0;
DECLARE @i INT;
SET @i = 2147483647;

After that, you can hit F5 and it’ll run. If your problem is in the main branch of the script that generates all the complicated dynamic SQL, that’ll help you figure out exactly where the problem is.

Thanks!

Going Further

The Right Way To Check For NULLs In SQL Server Queries

Posted on November 8, 2021May 16, 2022 by Erik Darling

101ers

This is still one of the most common problems I see in queries.

People are terrified of NULLs. People are afraid to merge on freeways in Los Angeles.

What results is this endless stream of poorly performing queries, and some surprise logic bugs along the way.

I don’t have much more else of an intro. The TL;DR is that you should use natural expressions like IS NULL or IS NOT NULL, rather than any of the built in functions available to you in SQL Server, like ISNULL, COALESCE, et al. which are presentation layer functions with no relational meaning whatsoever.

From here on out, we’ll be calling them unnatural expressions. Perhaps that will get through to you.

Tuning Wizard

First is something I’ve covered before, but when you use unnatural expressions, the optimizer will not give you feedback about useful indexes.

The first query generates a missing index request, the second one does not. The optimizer has abandoned all hope with the use of an unnatural expression.

Lethargy

The other issue with unnatural expressions comes down to implicit conversion.

Take this, for instance.

DECLARE 
    @i int = 0;

SELECT 
    c = 
        CASE ISNULL(@i, '') 
             WHEN '' 
             THEN 1 
             ELSE 0 
        END;

This will return a 1, because 0 and ” can be implicitly converted.

Perhaps less obvious, and more rare, is this:

DECLARE 
    @d datetime = '19000101';

SELECT 
    c = 
        CASE ISNULL(@d, '') 
             WHEN '' 
             THEN 1 
             ELSE 0 
        END;

Which will also return 1.

Not many databases have stuff going back to 1900, but I do see people using that as a canary value often enough.

Perfidy

If that’s not enough to get you off the idea, let’s look at how this stuff plays out in the real world.

First, let’s get ourselves an index. Without that, there’s fundamentally no difference in performance.

CREATE INDEX v ON dbo.Votes
    (BountyAmount);

Our gold standard will be these two queries:

SELECT
    c = COUNT_BIG(*)
FROM dbo.Votes AS v
WHERE v.BountyAmount IS NULL;

SELECT
    c = COUNT_BIG(*)
FROM dbo.Votes AS v
WHERE v.BountyAmount IS NOT NULL;

The first one that checks for NULL values returns a count of 182,348,084.

The second one that checks for NOT NULL values returns a count of 344,070.

Keep those in mind!

The query plans for them both look like this:

Which run, respectively (and respectably), in 846ms and 26ms. Obviously the query with the more selective predicate will have a time advantage, here.

Wrongly

Here’s where things start to go wrong.

This query returns incorrect results, but you’re probably used to that because of all the NOLOCK hints in your queries anyway.

SELECT
    c = COUNT_BIG(*)
FROM dbo.Votes AS v
WHERE ISNULL(v.BountyAmount, '') = '';

A count of 182,349,088 is returned rather than 182,348,084, because there are 1004 rows with a bounty of 0.

Even though we have an empty string in our query, it’s implicitly converted to 0.

And you thought you were so clever.

Badly

The exercises in futility that I see people carrying on with often look make use of ISNULL, COALESCE, and CASE expressions.

It’s worth noting here that COALESCE is only a CASE expression underneath, anyway. They are interchangeable in this respect.

For findings NULLs, people will screw up and do this:

SELECT
    c = COUNT_BIG(*)
FROM dbo.Votes AS v
WHERE ISNULL(v.BountyAmount, -1) = -1;

SELECT
    c = COUNT_BIG(*)
FROM dbo.Votes AS v
WHERE COALESCE(v.BountyAmount, -1) = -1;

We can use -1 here because it doesn’t naturally occur in the data. Results are correct for both, but performance is comparatively horrible.

We’re looking at 2.5 seconds compared to 900ms. This situation gets worse with the more selective predicates, too.

These both take roughly the same time as the other unnatural forms of this query, but recall the natural version of this query finished in under 30ms.

Deadly

I hope I don’t have to write about this anymore, but at the rate I see people doing this stuff, I kind of doubt it.

Broken Record Enterprises, it feels like sometimes.

I’m not sure why anyone thinks this is a good idea. I’ve heard rumors that it comes from application developers who are used to NULLs throwing errors writing SQL queries, where they don’t pose the same threat.

Who knows, though. Maybe people just really like the festive pink text color that functions turn in SSMS.

Thanks for reading!

Going Further

Dealing With Wide Missing Index Requests In SQL Server

Posted on November 5, 2021May 16, 2022 by Erik Darling

We’ve All Been There

You’re running a query that selects a lot of columns, and you get a missing index request.

For the sake of brevity, let’s say it’s a query like this:

SELECT
    p.*
FROM dbo.Posts AS p
WHERE p.ParentId = 0;

The missing index request I get for this query is about like so:

CREATE NONCLUSTERED INDEX [<Name of Missing Index, sysname,>]
ON [dbo].[Posts] ([ParentId])
INCLUDE ([AcceptedAnswerId],[AnswerCount],[Body],[ClosedDate],[CommentCount],[CommunityOwnedDate],
[CreationDate],[FavoriteCount],[LastActivityDate],[LastEditDate],[LastEditorDisplayName],[LastEditorUserId],
[OwnerUserId],[PostTypeId],[Score],[Tags],[Title],[ViewCount])

But that’s laughable, because it’s essentially a shadow clustered index. It’s every column in the table ordered by <some column>.

And Again

Under many circumstances, you can trim all those included columns off and make sure there’s a usable index with ParentId as the leading column.

I’m not a fan of single key column indexes most of the time, so I’d avoid that practice.

But sure, if you have reasonably selective predicates, you’ll get a decent seek + lookup plan. That’s not always going to be the case, though, and for various reasons you may end up getting a poor-enough estimate on a reasonably selective predicate, which will result in a bad-enough plan.

Of course, other times you may not have very selective predicates at all. Take that query up there, for example. There are 17,142,169 rows in the Posts table (2013), and 6,050,820 of them qualify for our predicate on ParentId.

This isn’t a case where I’d go after a filtered index, either, because it’d only be useful for this one query. And it’d still be really wide.

There are four string columns in there, all nvarchar.

Title (250)
Tags (150)
LastEditorDisplayName(40)
Body(max)

Maybe Something Different

If I’m going to create an index like that, I want more out of it than I could get with the one that the optimizer asked for.

On a decently recent version of SQL Server (preferably Enterprise Edition), I’d probably opt for creating a nonclustered column store index here.

You get a lot of benefits from that, which you wouldn’t get from the row store index.

Column independence for searching
High compression ratio
Batch Mode execution

That means you can use the index for better searching on other predicates that aren’t terribly selective, the data source is smaller and less likely to be I/O bound, and batch mode is aces for queries that process a lot of rows.

Column store indexes still have some weird limitations and restrictions. Especially around data types and included columns, I don’t quite understand why there isn’t better parity between clustered and nonclustered column store.

Thanks for reading!

Going Further

LOB Data, Recompile, And Too Much tempdb Usage In SQL Server

Posted on November 4, 2021May 16, 2022 by Erik Darling

Stumper

I got a very interesting issue about sp_HumanEvents recently, and I couldn’t quite figure out why things were going wonky.

The problem was that at some point when monitoring blocking long-term, something was taking up a whole lot of tempdb.

I’m gonna say up front that the problem was using a recompile hint with LOB variable assignment in a loop. That doesn’t mean you should avoid any one of those things, but be careful when you use them in concert.

This post wouldn’t be possible without my friends Joe and Paul, who helped me track down the issue and with the internals of it.

Thumper

Rather than make you go through running and causing blocking, the issue is reproduced through this demo:

DECLARE @lob nvarchar(max) = N'x';
DECLARE @x xml = N'<x>' + REPLICATE(@lob, 1024 * 1024) + N'</x>';
DECLARE @loop integer = 0;
DECLARE @t table (x nvarchar(1));

WHILE @loop < 5
BEGIN

    INSERT 
        @t
    (
        x
    )
    SELECT 
        x = @x.value('(./x/text())[1]', 'nvarchar(1)')
    OPTION (RECOMPILE);

    DELETE @t;

    SELECT 
        ddtsu.internal_objects_alloc_page_count, 
        ddtsu.internal_objects_dealloc_page_count,
        internal_object_reserved_page_count = 
        (
            SELECT 
                SUM(internal_object_reserved_page_count)
            FROM tempdb.sys.dm_db_file_space_usage
        )
    FROM sys.dm_db_task_space_usage AS ddtsu
    WHERE ddtsu.session_id = @@SPID;

    SET @loop += 1;
END;

The trick here is to run it with the recompile hint available, and then quoted out.

Jumper

With recompile available, this is the result:

The internal objects keep going up, except the deallocated number. That’s the column in the middle.

With recompile quoted out, the numbers are a lot different.

All numbers stay stable.

Lumper

As Mr. White points out in his post, assigning to a variable prevents parameter embedding.

When it’s allowed, tempdb objects get cleaned up at the end of the statement.
When it’s not, it gets cleaned up at the end of the batch.

This has been reported to Microsoft for some analysis. Hopefully there’s some remedy for it in the future.

Thanks for reading!

Going Further

Updates To sp_HumanEvents, sp_QuickieStore, And More!

Posted on November 3, 2021May 16, 2022 by Erik Darling

For Free!

Here’s some stuff I’ve been working on lately:

Added an inline table valued function that strips characters from a string
Added a script to create useful Alerts in SQL Server

sp_HumanEvents:

Added the recompile_cause column to the output of the recompile event
Added the wait_resource column to the blocking event output
Fixed a bug around table creation
MsSQLServerDBA fixed an issue where GO statements were preventing deploying with DBA Tools
Remove a recompile hint that was leading to high tempdb allocations (more on that tomorrow)

sp_QuickieStore:

Fixed a bug where date filtering was messing up query results

Enjoy, and as always, please let me know if there’s anything I can do to improve the scripts usability, or any issues you encounter while using them.

Thanks for reading!

Going Further

How To Use sp_HumanEvents To Troubleshoot A Slow Stored Procedure In SQL Server

Posted on November 2, 2021October 4, 2023 by Erik Darling

Number One Record

You’ve got a stored procedure that runs slowly, but the problem is that it’s… long. It’s really hard to tell which part is slow, sometimes.

With shorter procedures you can probably just collect actual execution plans and slam F5 like a tall glass of gin at 6am.

But you don’t wanna do that with the larger procedures, for a few practical reasons:

Lots of little queries run quickly, and we don’t care about those
Navigating through lots of plans in SSMS is tedious
There’s no differentiation when other procedures, etc. are invoked
You introduce a lot of overhead retrieving and rendering all those plans
The full query text might not be captured, which is a limitation in many places

Let’s save the day with sp_HumanEvents, my stored procedure that makes using Extended Events really easy.

Wanna Ride

There are a lot of issues you can run into with Extended Events. They’re rather unpleasant, and there’s almost zero guidance from Microsoft about usage.

Wouldn’t it be nice to just hit F5?

Once you have a window open with your procedure ready to run, take note of the session id that it’s using, and tailor this command for your situation:

EXEC sp_HumanEvents
    @event_type = 'query',                   
    @query_duration_ms = 1000,               
    @session_id = N'58',                    
    @keep_alive = 1;

Let’s break down what this does:

The events we want to focus on are for executed queries
We only care about queries that run for more than one second
We’re going to focus in on the session id for the query window we’re tuning in
We want the session to stay running so we can watch and re-watch after we make changes

I know it looks a little funny that @session_id is a string, but that’s because there are some sampling capabilities if you want to look at a workload instead of a single procedure without overwhelming a server by collecting everything.

Once that’s done, you’ll have a new Extended Event session like this, and you’ll wanna watch live data from it:

Watch Out Now

Once you’ve got that window open and you run your procedure, you’ll see any queries that meet the duration criteria, and you should see something that looks like this.

The procedure that I’m looking at in here is sp_BlitzCache, because it’s a good example of a procedure with a lot of queries in it, where only some of them (like the XML parsing) might get slowed down.

Some notes on the output:

The statement doesn’t get collected with the query plan (more on that in a second)
INSERT…EXEC shows up as two statements (lines 2 and 3 over there)

You only see these two columns at first, but you can go through and add in any other columns that you find useful from each specific session type.

Two Point Two

The output can be a little confusing at first. Generally the pattern is query plan, then statement associated with it.

If you click on each event, you can choose different elements from it to show in the main result window.

Here’s how I usually set things up to find what I wanna go after:

I like to grab CPU, duration, information about requested, granted, and used memory, and the statement.

Not every element is available in every event. Where things are NULL, that’s where they’re not available. I wish there were a general extended event that captured everything I need in one go, but that doesn’t seem to exist.

One last point on the output is that if you click on the query_post_execution_showplan lines, the query plan is available in the second result set:

Crossover

Before you ask, the lightweight profiling events are useless. They’re so nerfed and collect so little helpful detail that you might as well be looking at a cached plan or Query Store plan.

Lightweight, baby 🙄

To that point, I don’t recommend running something like this across a whole workload. Though Extended Events are purported to have far less observer overhead than Profiler, I’ve seen even heavily-filtered sessions like this slow workloads down quite a bit.

That goes for other traces and forms of monitoring as well. Don’t think this is a special case.

Anyway, this is how I work when I’m trying to tune things for clients. Hopefully you find it useful as well.

Grab sp_HumanEvents and lemme know how it goes on GitHub.

Thanks for reading.