Sql-server – Why does SQL Server Profiler show some completed statements in pairs (twice)

profilersql serversql-server-2016

In SQL Server profiler I am seeing pairs of completed statements. A pair is shown below. The TextData (query) is exactly the same. The SPIDs are different (86 & 88). The # of reads and writes are a little different.
(as an FYI, I am running a custom template where I am filtering out exec sp_reset_connection statements and showing just the completed statements).
I am seeing a bunch of these pairs of SQL:StmtCompleted and RPC:Completed and every pair contains the same SQL in TextData.

The statement shown was executed once by Entity Framework in the client.

My question: Is SQL Server actually running the queries twice? If yes, does this mean definitely the client is sending the query twice?

Best Answer

My question: Is SQL Server actually running the queries twice?

Yep! Given that the SPIDs are different, that means they were run from completely different connections. The fact that the duration and reads are different, as you mentioned, is also a good indicator that the query was run twice (possibly with different parameters).

If yes, does this mean definitely the client is sending the query twice?

I would say yes. You should look into your application code. Maybe more than one user was accessing the system at the same time, or the query is being run from multiple threads, or something else.

Since this is EF, I might think this was the N+1 query problem (disclosure: that's my blog), but that would normally be all on the same SPID.

Related Solutions

Sql-server – How to get SQL Server Profiler to show amended tables

Try a trace on SP:Completed and RPC:Completed with column filters on TextData for:

% insert %
% delete %
% update %

Might get the odd spurious result but it'll narrow the field. Add SQL:BatchCompleted if you have a mix of procs and statements.

Sql-server – sp_ExecuteSQL, performance and table variables

There is an implicit CREATE TABLE at the beginning and DROP TABLE @T at the end as the table goes out of scope that aren't associated with either the INSERT or the SELECT statement.

If you replace with a #temp table you should see some additional reads for both the drop and create statements. For me I see 36 for the CREATE and 100 for the DROP so that accounts for 136 of your missing 137 reads.

(Script with #temp table)

EXEC sp_executesql N'
   CREATE TABLE #T 
  ( 
     x INT 
  ) 

INSERT INTO #T 
            (x) 
SELECT TOP 10 number 
FROM   master..spt_values 

SELECT * 
FROM   #T 
UNION 
SELECT * 
FROM   #T 

DROP TABLE #T
'

Best Answer

Related Solutions

Sql-server – How to get SQL Server Profiler to show amended tables

Sql-server – sp_ExecuteSQL, performance and table variables

Related Question