Can I get SSMS to show me the Actual query costs in the Execution plan pane?

Question

I'm fixing performance issues on a multistatement stored procedure in SQL Server. I want to know which part(s) I should spend time on.

I understand from How do I read Query Cost, and is it always a percentage? that even when SSMS is told to Include Actual Execution Plan, the "Query cost (relative to the batch)" figures is still based on cost estimates, which can be far off actuals

I understand from Measuring Query Performance : “Execution Plan Query Cost” vs “Time Taken” that I can surround invocation of the stored procedure with SET STATISTICS TIME statements, and I will then get a list like this in the Messages pane:

SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 1 ms.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

[etc]

 SQL Server Execution Times:
   CPU time = 187 ms,  elapsed time = 206 ms.

with one output message for each statement.

I can 'easily' (though not conveniently) associate the time statistics output with the statement-by-statement execution plans in the Execution plan pane, by counting them: The fourth SQL Server Execution Times message output corresponds to Query 4 in the Execution plan pane, and so on.

But is there a better way?

Answer 1

I don't know of a way to do this in the plan from Management Studio, but this is one of the many things the free SentryOne Plan Explorer will do for you when you generate an actual plan from within the tool - it includes all the runtime metrics per statement.

Answer 2

One good way to do this is with Profiler. Set up a "repro" of your problem proc on a dev or test box, ie a sample call to the proc with parameters. Then using Profiler, create a trace using either the TSQL_SPs template, or from a blank template, add the SP:StmtCompleted event. Add the Duration, Reads, Writes and CPU columns if not already available. Add a filter to the trace on your SPID (which you should know from Management Studio). You might also add a filter to Duration ( eg greater than 1000 = greater than 1 second ).

You can either run the trace in Profiler although there is overhead (do NOT do this on a production box) or export the definition and create a server side trace. The Profiler overhead is not so much of a big deal on a dedicated dev or test box.

Run the proc and let it complete. You may also which to collect the Actual Execution plan at this point.

Stop your trace and open the file, and you should see a line by line breakdown of your proc, including timings for each step. I find this more useful than the plan for identifying bottlenecks although the plan will come in handy when looking at the relevant sections to tune.

HTH

Answer 3

You could also use the sys.dm_exec_procedure_stats and sys.dm_exec_query_stats dynamic management views. The first of those gives information about the procedure as a whole; the second can be used to break out each query in the procedure. An example is shown below:

USE AdventureWorks;
GO
CREATE PROCEDURE dbo.Test
    @NameLike nvarchar(50)
AS
BEGIN
    SELECT
        ProductCount = COUNT_BIG(*)
    FROM Production.Product AS p
    JOIN Production.TransactionHistory AS th ON
        th.ProductID = p.ProductID
    WHERE
        p.Name LIKE @NameLike;

    SELECT
        pc.Name,
        ProductCount = COUNT_BIG(*)
    FROM Production.Product AS p
    JOIN Production.ProductSubcategory AS ps ON
        ps.ProductSubcategoryID = p.ProductSubcategoryID
    JOIN Production.ProductCategory AS pc ON
        pc.ProductCategoryID = ps.ProductCategoryID
    WHERE
        p.Name LIKE @NameLike
    GROUP BY
        pc.Name
    ORDER BY
        pc.Name;
END;
GO
EXECUTE dbo.Test @NameLike = N'A%';
EXECUTE dbo.Test @NameLike = N'F%';

Procedure statistics:

SELECT
    deps.last_execution_time,
    deps.last_worker_time,
    deps.last_physical_reads,
    deps.last_logical_writes,
    deps.last_logical_reads,
    deps.last_elapsed_time
FROM sys.dm_exec_procedure_stats AS deps
WHERE
    deps.database_id = DB_ID()
    AND deps.[object_id] = OBJECT_ID(N'dbo.Test', N'P');

Queries within the procedure:

SELECT
    query.the_text,
    deqs.last_execution_time,
    deqs.last_worker_time,
    deqs.last_physical_reads,
    deqs.last_logical_writes,
    deqs.last_logical_reads,
    deqs.last_clr_time,
    deqs.last_elapsed_time,
    deqs.last_rows    -- note: Only present from 2008 R2 onwards
FROM sys.dm_exec_query_stats AS deqs
CROSS APPLY sys.dm_exec_sql_text(deqs.[sql_handle]) AS dest
CROSS APPLY
(
    VALUES 
    (
        SUBSTRING
        (
            dest.[text], 
            deqs.statement_start_offset / 2 + 1,
            (ISNULL(NULLIF(deqs.statement_end_offset, -1), DATALENGTH(dest.[text])) - deqs.statement_start_offset) / 2 + 1
        )
    )
) AS query (the_text)
WHERE
    deqs.[sql_handle] IN
    (
        SELECT
            deps.[sql_handle]
        FROM sys.dm_exec_procedure_stats AS deps
        WHERE
            deps.database_id = DB_ID()
            AND deps.[object_id] = OBJECT_ID(N'dbo.Test', N'P')
    );