2

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

5
  • 1
    Is this statement part of a stored procedure? RPC usually indicates a stored procedure call, which is slightly different than an ad hoc query batch. And are your times of 40 and 64 really milliseconds and not seconds? May 21, 2020 at 3:05
  • @Solomon Rutzky - Yes, this is part of statement in stored procedure. Also yes originally time was in microseconds as collected from XE but I converted to seconds for a clarity May 21, 2020 at 6:17
  • @Josh Darnell, Thanks , helpful, that explains why the difference in time. But however the difference is too large for my client to digest. We need to find if there is a way to save those 24 secs or reduce. How can one confirm if this is bottleneck or not and can be improved? Appreciate your response, thanks May 21, 2020 at 15:30
  • @JoshDarnell: Sorry but i did not understand that when you say run from SSMS, my bad May 21, 2020 at 21:29
  • @beginnerdba I posted an answer, hopefully that's more clear than my brief comments. May 27, 2020 at 2:28

2 Answers 2

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.

1

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.

1
  • thanks for your answer, Yes i calculated correctly as originally from XE its microseconds so converted to seconds. Even that is what we are figuring out why it will go that slow, table is 200 M rows, not billion and no contention at server level. Its got good resources May 28, 2020 at 23:35

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.