Sql-server – Super poor UDF performance on only 1 server, not identical other server

functionsperformancequery-performancesql serversql server 2014

I have the following code that takes 20 times longer on one production box (db35) than another identical box (db34).

Both have:

Microsoft SQL Server 2014 (SP2-CU3) (KB3204388) – 12.0.5538.0 (X64)
Dec 15 2016 17:52:48
Copyright (c) Microsoft Corporation
Standard Edition (64-bit) on Windows NT 6.3 (Build 9600: )

Any idea what could cause this? These are production servers, so a reboot is not available for 2 weeks for our normal maintenance window. I also know that using the UDF is terrible and should be replaced, but that still does not answer the basic question. Below is sample code and results in milliseconds. Any suggestions would be greatly appreciated.

DB34 – good server results

Table '#A945FC1F'. Scan count 0, logical reads 1004081, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'sysschobjs'. Scan count 3, logical reads 2021, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 2, logical reads 2950297, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

 SQL Server Execution Times:  

   CPU time = 23922 ms,  elapsed time = 26046 ms.

DB34 execution time 26050ms.

DB35 – bad server results

Table '#BC355925'. Scan count 0, logical reads 1004081, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'sysschobjs'. Scan count 3, logical reads 1755, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 2, logical reads 2949345, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

SQL Server Execution Times:

   CPU time = 407687 ms,  elapsed time = 415084 ms.

DB35 execution time 415093ms.

Function

use master;
IF NOT EXISTS (SELECT * FROM sys.objects WHERE object_id = OBJECT_ID(N'[dbo].[GenerateDateKey]') AND type in (N'FN', N'IF', N'TF', N'FS', N'FT'))
BEGIN
execute dbo.sp_executesql @statement = N'
    CREATE FUNCTION [dbo].[GenerateDateKey] (
        @value [datetime]
      ) RETURNS [int] BEGIN

      RETURN DATEPART(yyyy, @value) * 10000
        + DATEPART(M, @value) * 100
        + DATEPART(d, @value)
    END
  ' 
END


set nocount on
declare @temp1 table (cd1 int, cd2 int, cd3 int, cd4 int, cd5 int, cd6 int);
declare @startDate datetime

set @startDate = getdate()

set statistics io on
set statistics time on

insert into @temp1
select top 1000000 [dbo].[GenerateDateKey](s1.create_date) as cd1,
                   [dbo].[GenerateDateKey](s1.modify_date) as cd2,
                   [dbo].[GenerateDateKey](s2.create_date) as cd3,
                   [dbo].[GenerateDateKey](s2.modify_date) as cd4,
                   [dbo].[GenerateDateKey](s3.create_date) as cd5,
                   [dbo].[GenerateDateKey](s3.modify_date) as cd6
from sys.objects s1 with (nolock), sys.objects s2 with (nolock), sys.objects s3 with (nolock)

print @@servername + ' generate  ' + cast(datediff(ms, @startdate, getdate()) as varchar(20))

Same exact hardware. I get the same results regardless of load/time of day run. The query plan is the same. The scans/reads are approx the same. Both physical Dell poweredge R610s. 192GB physical ram. 128GB to SQL Server. 50GB ramdisk for tempdb.

I have 32 total SQL Server 2014 instances in production, though some are different configurations (same version), but ALL of them run this query about the same except for the one (db35), which is 20 times worse.

If I replace the UDF with, for example, a cast/convert I get the same on both servers.

insert into @temp1
select top 1000000 
            cast(convert(char(10),s1.create_date,112) as int) as cd1,
            cast(convert(char(10),s1.modify_date,112) as int) as cd2,
            cast(convert(char(10),s2.create_date,112) as int) as cd3,
            cast(convert(char(10),s2.modify_date,112) as int) as cd4,
            cast(convert(char(10),s3.create_date,112) as int) as cd5,
            cast(convert(char(10),s3.modify_date,112) as int) as cd6
from sys.objects s1 with (nolock), sys.objects s2 with (nolock), sys.objects s3 with (nolock)

The issue isn't re-writing the query, that's easy with the cast/convert from above. The issue is why the UDF takes 20 times longer on one server than the other. I did notice when I updated the function with schemabinding that there was a 40% improvement, but it's still 4 minutes instead of 20 seconds.

Best Answer

Looks like Paul White nailed it in a comment:

Check for a profiler trace or extended events running on the slow server. Each iteration of the udf can generate multiple events, with shocking consequences.

There was a trace running against the server (by another DBA). He actually terminated just before Paul mentioned to look for traces, so that's why I didn't notice any. This trace had been running for 5 days, so it was apparently putting a lot of pressure on the memory utilization on the box. Anyway, I want to thank Paul and blobbles for their help.

Subqueries in CASE expressions

Consider the following (perfectly legal) query:

DECLARE @Base AS TABLE (a integer NULL);
DECLARE @When AS TABLE (b integer NULL);
DECLARE @Then AS TABLE (c integer NULL);
DECLARE @Else AS TABLE (d integer NULL);

SELECT
    CASE
        WHEN (SELECT W.b FROM @When AS W) = 1
            THEN (SELECT T.c FROM @Then AS T)
        ELSE (SELECT E.d FROM @Else AS E)
    END
FROM @Base AS B;

The semantics of CASE are that WHEN/ELSE clauses are generally evaluated in textual order. In the query above, it would be incorrect for SQL Server to return an error if the ELSE subquery returned more than one row, if the WHEN clause was satisfied. To respect these semantics, the optimizer produces a plan that uses pass-through predicates:

Pass-through predicates

The inner side of the nested loop joins are only evaluated when the pass-through predicate returns false. The overall effect is that CASE expressions are tested in order, and subqueries are only evaluated if no previous expression was satisfied.

CASE expressions with an EXISTS subquery

Where a CASE subquery uses EXISTS, the logical existence test is implemented as a semi-join, but rows that would normally be rejected by the semi-join have to be retained in case a later clause needs them. Rows flowing through this special kind of semi-join acquire a flag to indicate if the semi-join found a match or not. This flag is known as the probe column.

The details of the implementation is that the logical subquery is replaced by a correlated join ('apply') with a probe column. The work is performed by a simplification rule in the query optimizer called RemoveSubqInPrj (remove subquery in projection). We can see the details using trace flag 8606:

SELECT
    T1.ID,
    CASE
        WHEN EXISTS 
        (
            SELECT 1
            FROM #T2 AS T2
            WHERE T2.ID = T1.ID
        ) THEN 1 
    ELSE 0
    END AS DoesExist
FROM #T1 AS T1
WHERE T1.ID BETWEEN 5000 AND 7000
OPTION (QUERYTRACEON 3604, QUERYTRACEON 8606);

Part of the input tree showing the EXISTS test is shown below:

ScaOp_Exists 
    LogOp_Project
        LogOp_Select
            LogOp_Get TBL: #T2
            ScaOp_Comp x_cmpEq
                ScaOp_Identifier [T2].ID
                ScaOp_Identifier [T1].ID

This is transformed by RemoveSubqInPrj to a structure headed by:

LogOp_Apply (x_jtLeftSemi probe PROBE:COL: Expr1008)

This is the left semi-join apply with probe described previously. This initial transformation is the only one available in SQL Server query optimizers to date, and compilation will simply fail if this transformation is disabled.

One of the possible execution plan shapes for this query is a direct implementation of that logical structure:

NLJ Semi Join with Probe

The final Compute Scalar evaluates the result of the CASE expression using the probe column value:

Compute Scalar expression

The basic shape of the plan tree is preserved when the optimize considers other physical join types for the semi join. Only merge join supports a probe column, so a hash semi join, though logically possible, is not considered:

Merge with probe column

Notice the merge outputs an expression labelled Expr1008 (that the name is the same as before is a coincidence) though no definition for it appears on any operator in the plan. This is just the probe column again. As before, the final Compute Scalar uses this probe value to evaluate the CASE.

The problem is that the optimizer doesn't fully explore alternatives that only become worthwhile with merge (or hash) semi join. In the nested loops plan, there is no advantage to checking if rows in T2 match the range on every iteration. With a merge or hash plan, this could be a useful optimization.

If we add a matching BETWEEN predicate to T2 in the query, all that happens is that this check is performed for each row as a residual on the merge semi join (tough to spot in the execution plan, but it is there):

SELECT
    T1.ID,
    CASE
        WHEN EXISTS 
        (
            SELECT 1
            FROM #T2 AS T2
            WHERE T2.ID = T1.ID
            AND T2.ID BETWEEN 5000 AND 7000 -- New
        ) THEN 1 
    ELSE 0
    END AS DoesExist
FROM #T1 AS T1
WHERE T1.ID BETWEEN 5000 AND 7000;

Residual predicate

We would hope that the BETWEEN predicate would instead be pushed down to T2 resulting in a seek. Normally, the optimizer would consider doing this (even without the extra predicate in the query). It recognizes implied predicates (BETWEEN on T1 and the join predicate between T1 and T2 together imply the BETWEEN on T2) without them being present in the original query text. Unfortunately, the apply-probe pattern means this is not explored.

There are ways to write the query to produce seeks on both inputs to a merge semi join. One way involves writing the query in quite an unnatural way (defeating the reason I generally prefer EXISTS):

WITH T2 AS
(
    SELECT TOP (9223372036854775807) * 
    FROM #T2 AS T2 
    WHERE ID BETWEEN 5000 AND 7000
)
SELECT 
    T1.ID, 
    DoesExist = 
        CASE 
            WHEN EXISTS 
            (
                SELECT * FROM T2 
                WHERE T2.ID = T1.ID
            ) THEN 1 ELSE 0 END
FROM #T1 AS T1
WHERE T1.ID BETWEEN 5000 AND 7000;

TOP trick plan

I wouldn't be happy writing that query in a production environment, it's just to demonstrate that the desired plan shape is possible. If the real query you need to write uses CASE in this particular way, and performance suffers by there not being a seek on the probe side of a merge semi-join, you might consider writing the query using different syntax that produces the right results and a more efficient execution plan.

Sql-server – Which of these queries is best for performance

Sometimes I wonder if SHORT scripts really is the best thing to focus on.

The size of a script has little to do with how efficiently the query will execute. A more compact statement will likely consume fewer resources in terms of compilation, but (re)compilation is usually a rare occurrence in a live system.

Fewer table accesses is usually desirable, though, and this does lead to more compact code.

Very generally speaking, a smaller execution plan will yield better results, and a lower estimated cost will yield better results. Again, though, it's highly situational. Cost estimates in particular can be way off in some cases. It's important to measure the actual execution time, because at the end of the day, that's what matters.

With left joins i can achieve what i want with just a few lines. But then I tried with a longer script, using unions. Which is the best method?

First of all, we need to know how much data will be in these tables in a real system. Right now there's so little it will be difficult to use the STATISTICS TIME performance metrics to figure out a winner -- the results that come back will be dominated by factors other than the query execution. With more data, it's likely the plans will change, thus rendering the comparison here moot.

Having said that, by looking at the query plans as they are now from a logical point of view, the first one is the winner.

You can see that the Clustered Index Scan of quantities appears once in the first plan, while it appears four times in the second one. The second plan also contains an expensive Distinct Sort as a result of using UNIONs (this operator could be eliminated by using UNION ALLs instead, which won't change the results).

The first query could also probably be improved, by getting index seeks on the colors and sizes tables, instead of table scans. It might be worth trying a hash match plan as well (which is what you'll probably see when quantities and products are larger), but for tables this small, the startup cost may be too much overhead to be of benefit.

What I would suggest you do is run each of the statements you want to test 10,000+ times in a loop, figure out the average execution time, and then compare.