SQL Server Profiler vs COALESCE (SP:STMTCOMPLETED)

Question

I was running a trace and found something that I don't understand. I have a procedure with a simple select statement that returns the first non-null value from a sequence of function calls.

I would expect each function to be called only once. Therefore, when profiling with SP:STMTCOMPLETED events, I'd expect to see just one set of records with the statements from that one call.

However, what I'm seeing is that set of records multiple times, which suggests the function is being called multiple times.

Is the function really being called twice? And why?

Here is the script to create the function and stored procedure:

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE FUNCTION [dbo].[FOO] (@v INT)
RETURNS bit AS  
BEGIN
    RETURN 0
END
GO

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE PROCEDURE [dbo].[POO]
@v int,
@p varchar(100)
AS
SELECT 
    @p as p,
    CASE @p
        WHEN 'x' THEN COALESCE(dbo.FOO(@v), 0)
        ELSE 1
    END as poo
GO

Here is the procedure call

exec dbo.POO @v = 13911, @p = 'x'

Here is the Profiler output showing two lines for the function FOO and one line for the procedure POO:

If I replace the COALESCE call with a CASE statement like this:

SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
ALTER PROCEDURE [dbo].[POO]
@v int,
@p varchar(100)
AS
SELECT 
    @p as p,
    CASE @p
        WHEN 'x' THEN CASE WHEN dbo.FOO(@v) = 1 THEN 1 ELSE 0 END
        ELSE 1
    END as poo
GO

I get just one row for FOO on the profiler:

Here is the profiling script generated by SQL Profiler (filtering by database name = dbTest):

/****************************************************/
/* Created by: SQL Server 2017 Profiler          */
/* Date: 05/08/2020  12:06:04 AM         */
/****************************************************/


-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
set @maxfilesize = 5 

-- Please replace the text InsertFileNameHere, with an appropriate
-- filename prefixed by a path, e.g., c:\MyFolder\MyTrace. The .trc extension
-- will be appended to the filename automatically. If you are writing from
-- remote server to local drive, please use UNC path and make sure server has
-- write access to your network share

exec @rc = sp_trace_create @TraceID output, 0, N'InsertFileNameHere', @maxfilesize, NULL 
if (@rc != 0) goto error

-- Client side File and Table cannot be scripted

-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 45, 1, @on
exec sp_trace_setevent @TraceID, 45, 9, @on
exec sp_trace_setevent @TraceID, 45, 3, @on
exec sp_trace_setevent @TraceID, 45, 4, @on
exec sp_trace_setevent @TraceID, 45, 5, @on
exec sp_trace_setevent @TraceID, 45, 6, @on
exec sp_trace_setevent @TraceID, 45, 7, @on
exec sp_trace_setevent @TraceID, 45, 8, @on
exec sp_trace_setevent @TraceID, 45, 10, @on
exec sp_trace_setevent @TraceID, 45, 11, @on
exec sp_trace_setevent @TraceID, 45, 12, @on
exec sp_trace_setevent @TraceID, 45, 13, @on
exec sp_trace_setevent @TraceID, 45, 14, @on
exec sp_trace_setevent @TraceID, 45, 15, @on
exec sp_trace_setevent @TraceID, 45, 16, @on
exec sp_trace_setevent @TraceID, 45, 17, @on
exec sp_trace_setevent @TraceID, 45, 18, @on
exec sp_trace_setevent @TraceID, 45, 22, @on
exec sp_trace_setevent @TraceID, 45, 25, @on
exec sp_trace_setevent @TraceID, 45, 26, @on
exec sp_trace_setevent @TraceID, 45, 28, @on
exec sp_trace_setevent @TraceID, 45, 29, @on
exec sp_trace_setevent @TraceID, 45, 34, @on
exec sp_trace_setevent @TraceID, 45, 35, @on
exec sp_trace_setevent @TraceID, 45, 41, @on
exec sp_trace_setevent @TraceID, 45, 48, @on
exec sp_trace_setevent @TraceID, 45, 49, @on
exec sp_trace_setevent @TraceID, 45, 50, @on
exec sp_trace_setevent @TraceID, 45, 51, @on
exec sp_trace_setevent @TraceID, 45, 55, @on
exec sp_trace_setevent @TraceID, 45, 60, @on
exec sp_trace_setevent @TraceID, 45, 61, @on
exec sp_trace_setevent @TraceID, 45, 62, @on
exec sp_trace_setevent @TraceID, 45, 64, @on
exec sp_trace_setevent @TraceID, 45, 66, @on


-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint

exec sp_trace_setfilter @TraceID, 35, 0, 6, N'dbTest'
-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1

-- display trace id for future references
select TraceID=@TraceID
goto finish

error: 
select ErrorCode=@rc

finish: 
go

Answer 1

Yes it is being called twice.

It gets expanded to CASE WHEN dbo.FOO(@v) IS NOT NULL THEN dbo.FOO(@v) ELSE 0 END

Both of the references to dbo.FOO are evaluated separately.

You can use ISNULL(dbo.FOO(@v), 0) instead to avoid this.

See Unnecessarily bad performance for coalesce(subquery) for more about this (migrated from old Connect site to new feedback site)

BTW with the scalar UDF inlining in 2019 it doesn't end up calling the function at all at runtime - the whole thing gets simplified to CASE WHEN [@p]='x' THEN (0) ELSE (1) END in this simple example (as it sees the function always returns 0 and just substitutes that value in).