2 October 2017

3 Comments

2 October 2017

3 Comments

How to record T-SQL execution times using a SQL Prompt snippet

Guest post

This is a guest post from Phil Factor. Phil Factor (real name withheld to protect the guilty), aka Database Mole, has 30 years of experience with database-intensive applications.

Despite having once been shouted at by a furious Bill Gates at an exhibition in the early 1980s, he has remained resolutely anonymous throughout his career.

He is a regular contributor to Simple Talk and SQLServerCentral.

A SQL Prompt snippet is a pre-defined block of code, which we can insert at the current cursor position, or around currently-selected SQL text, in an SSMS query pane. DBAs use them to store all their most commonly-used checks and routines. It’s often useful to have your favorite troubleshooting scripts available to you within a few keystrokes, especially when firefighting an urgent issue, with people staring over your shoulder.

A developer like me uses them to try to aim for a better quality of code in the same amount of time. In this quick tip, I share the SQL Prompt snippet I use as a standard testbed for getting execution times for procedures and functions.

Doing T-SQL Code Timings

During development work, I might have two functions that perform the same task in different ways, and want to compare their performance. I need timings under different workloads so I can ensure the functions work at scale. I need to record all timings, so if I change a function, I can see if there is an improvement or regression.

For example, Listing 1 calls two functions that shred a JSON document into a SQL hierarchy table, JSONHierachy and ParseJSON, and then two, JSONVersion and ToJSON, which create JSON documents from a hierarchy table. I’m not going to show the full routines here because it’s a lot of code, and all these routines are published on Simple-Talk, in my series about JSON and SQL Server.

Listing 1

I want to compare the performance of each of these functions, and I want to store the results in a table so I can query them easily. How do I do it?

One way might be to use SET STATSTICS TIME. Once set to ON, SQL Server records millisecond timings for execution of every subsequent query or routine in the batch, until we issue SET STATSTICS TIME OFF. It’s a rather indiscriminate approach and often I don’t want to measure everything, only specific bits. In this case, I could use a simple ssit snippet, which puts SET STATSTICS TIME ON before each function and SET STATSTICS TIME OFF afterwards, and it would need a print statement to be certain what was being measured.

However, it still isn’t easy to associate the time with the part of the batch that was executed; I’d need to cut and paste the results. Also, there is a suspicion that the SET STATSTICS TIME ON could even affect the timings. I want more precision, and I want to save timings to a table.

The SQL Prompt Timings snippet

Listing 2 shows my timings snippet, which I can use and adapt to get the timings for specific parts of any routine.

Listing 2

In an SSMS query window, highlight the code in Listing 2 and, from the right-click context menu, select Create Snippet. Give it a name (I called mine timings) and a description and save it.

Next, select the original routine calls in Listing 1 and evoke the snippet from the Action list.

Figure 1

SQL Prompt will inject the selected code into the timings snippet, as shown in Figure 2. I’ve filled in the value for the $routine$ placeholder.

Figure 2

From there, with a quick bit of cut-and-paste, I extend it to record separate timings for each of the sections I want to measure (see the where <routine> ends comments in the code).

Listing 3

Figure 2 shows the results, with timing in milliseconds for each step in the batch.

Figure 2

Hmm, nearly half a second for JSONversion! I don’t like the look of that; clearly, this routine needs a bit more development work!

I can, of course, save the timings into a more permanent log, as part of testing. Often, I will run the sequence of tests with different sizes of data, a longer or shorted JSON document in this case, so it is useful to be able to compare with previous results. I often export the results and plot them in Excel or GnuPlot.

Guest post

This is a guest post from Phil Factor. Phil Factor (real name withheld to protect the guilty), aka Database Mole, has 30 years of experience with database-intensive applications.

Despite having once been shouted at by a furious Bill Gates at an exhibition in the early 1980s, he has remained resolutely anonymous throughout his career.

He is a regular contributor to Simple Talk and SQLServerCentral.

Share this post.

Share on FacebookShare on Google+Share on LinkedInTweet about this on Twitter

You may also like

  • Article

    Finding code smells using SQL Prompt: old-style join syntax (ST001)

    SQL Prompt implements a static code analysis rule, ST001, which will check code automatically, during development and testing work, for occurrences of non-ANSI standard JOIN syntax. The “old style” Microsoft/Sybase JOIN style for SQL, which uses the =* and *= syntax, has been deprecated and is no longer used. Queries that use this syntax will

  • Article

    Quickly rename variables all at once with SQL Prompt

    You’re going to run into situations where someone has made poor choices in naming objects, or maybe the business logic has changed and the object name no longer makes sense. Either way, easily and quickly taking care of renaming the objects within scripts can be a pain. Let’s take this code as an example: The

  • Article

    How to implement a SQL formatting standard using SQL Prompt v8

    With ten programmers working on the same project, how do you agree on a standard style for formatting SQL code, and then implement it consistently? One way is through draconian rules, meeting after meeting, and the occasional sacrifice of a programmer to put the fear in those who remain. If that doesn’t sound like fun,

  • Article

    SQL Prompt Hidden Gems: The SSMS Results Pane

    Within SSMS, when executing a query, we can view the query results in a grid, or tabular, format (Ctrl-D), as plain text (Ctrl-T), or we can write them to a plain-text reporting (.rpt) file using Ctrl-Shift-F. However, over my 20 plus years as a SQL programmer, I’ve often needed to take these results and use

  • University

    Take the SQL Prompt course

    This Redgate University course takes you from installation all the way up to getting the most out of the advanced operations in SQL Prompt. As well as autocompleting your code, you’ll learn how SQL Prompt can help you with code formatting, object renaming, code analysis, and other useful tip and tricks.

  • Forums

    SQL Prompt Forum

    Write, format, and refactor SQL effortlessly

  • Jerome Boyer

    Thanks Phil. I used at the start of the procedure I need to time:
    DECLARE @Timelapse DATETIME2(7);
    SET @Timelapse = SYSDATETIME();

    Procedure code

    and at the end:
    IF @Trace = ‘TIME’ — a variable used to support debugging
    SELECT DATEDIFF(MILLISECOND, @Timelapse, SYSDATETIME()) AS RunTime;

    My Create procedure template in SQLPrompt include these lines, as I felt they were adding trivial interpretation time. Is that a reasonable assumption or should I move to your suggestion and add the snippet with the log? Our ERP database has close to 3000 procedures and functions. Because our business is seasonal, the system has bottlenecks in peek season, while running smoothly off season. We were thinking of adding better timing logs, but were suspicious of the cost of doing so for many procedures. The idea was to look at the timing over time as you proposed and see which processes takes much longer under heavy SQL load.

    Does this approach makes sense?

    Phil, on a different note: can Redgate add Slack for sharing Redgate hub?

  • Phil, absolutely fantastic article!

  • daves

    When I select Insert Snippet I am prompted for the type of snippet. Do I choose function or stored procedure or something else? Thanks!