Performance of Query where time captured from SP statement completed differs by large from RPC completed

Question

I am unable to understand the performance of below query when collected data from XE events:

Query

DECLARE @Importdate DATETIME = ISNULL ((

SELECT ImportDatetime
FROM
Customertable
where CustomerID = 1
and OrderID =1 
) , '01/01/2000')

This part of statement returns just 1 row

SP statement completed shows 40 secs

RPC Completed for above statement shows 64 secs

Need help to understand why RPC will show such a big difference and where to look for this problem ? I do not see any NW issue reported as such but what does this indicate here and query as simple as above seems to high for that run time

Please advice

Answer 1

Generally speaking rpc_completed includes network time, while sp_statement_completed does not. This is very likely the case for your query, since it only returns one row.

So one explanation is the extra time is spent sending data over the network to the client.

You could try measuring wait statistics for this query to confirm there are 24 seconds of ASYNC_NETWORK_IO waits that explain the difference.

If the server has SSMS installed, you could remote desktop into it and run the query there, which should have very little network wait time. In which case you'd see very little difference in the time on those two events for this statement.

Answer 2

First, you state that:

Yes, this is part of statement in stored procedure.

Is this the only statement in the stored procedure? While not impossible if testing, it would otherwise seem odd to have a stored procedure that sets a variable and then never uses it or does anything else. So, what then of the other statements in the stored procedure? Have all of their times been accounted for?

1. RPC:Starting — the Remote Procedure Call to exec the proc (i.e. not an ad hoc query batch)
2. SP:Starting — the stored procedure starts (if it's not in the cache, time will be spent compiling it)
3. One or more sets of:
   1. SP:StmtStarting
   2. SP:StmtCompleted
4. SP:Completed
5. RPC:Completed

If you want to check for latency, be sure to capture the EndTime and compare the values between:

• The final SP:StmtCompleted and SP:Completed
• SP:Completed and RPC:Completed
• If there are a lot of result rows being sent back and/or the calling app isn't consuming them quickly enough, that might show up as a larger than expected time difference between the final SP:StmtCompleted and SP:Completed.

Otherwise:

• Compile time might be difference between EndTime of SP:Starting and StartTime of first SP:StmtStarting.
• What other statements are in this proc and what are there durations?

Next, are we really talking about seconds here? 40 seconds for a SELECT of a single column given two INT (or similar) predicates? Even without an index to help I would expect such a query to return well before 40 seconds, unless there's a lot of contention and/or the table has billions of rows, or something like that. Is it possible that you divided by the wrong number? I think you're supposed to divide by 1000000. If these numbers are correct, then I would be more concerned about why that simple SELECT is taking 40 seconds than I would be about whatever else is taking up the remaining 24 seconds.