3

I have been debugging an issue in our production environment(on-premises) where queries perform slowly even the columns are indexed. The table has roughly 200 million rows, is not partitioned and is in full recovery mode.

The DELETEs only affects 1 row and INSERTs are only 1 row too.

I can see the duration in SQL Profiler, but it occurs during Audit Logout which I don't understand. For example the DELETE on top of the picture seems to take 0ms to run, but the Audit Logout takes 2867ms and it also has huge amount of reads. I have monitored the DB with PerfMon, but cannot see any related I/O or CPU issues.

Does it make sense that DELETE or INSERT with such a table could take seconds? Would anyone have an idea what is causing the latency?

SQL Profiler

0

1 Answer 1

4

Below are the descriptions of the Duration and Reads trace column values from the Audit Logout Event documentation:

  • Duration: Amount of time since the user logged in (approximately).
  • Reads: Number of logical read I/Os issued by the user during the connection.

The Audit Logout duration value in your trace reflects the time between reused pooled connections and the Reads value is cumulative for all activity since the connection was physically opened. Neither are related to the query slowness and not particularly useful for troubleshooting query performance.

The RPC:Completed duration reflects the server-side query duration for parameterized queries. There is no evidence of queries running more than a few milliseconds in this trace data.

Does it make sense that DELETE or INSERT with such a table could take seconds? Would anyone have an idea what is causing the latency?

If you do capture a long-running RPC call, check the plan captured by the Showplan XML Statistics Report to see if the actual plan is not optimal. If the plan looks good, consider that slowness can be caused by many factors, such as long-term blocking, resource waits, or running an unfiltered Profiler trace on a busy production server.

5
  • Very much appreciated. We have captured the XML Plan and it seems to be using indexes properly and the actual query runs very fast. Also while running these queries I cannot see any blocking factors in SQL Server Management Studio's activity monitor and these queries are run one after another instead of parallel.
    – Joni
    Apr 4, 2023 at 12:30
  • Also the queries run slowly without running the profiler trace. We are using Entity framework and this all makes me think that the library is doing something odd when we call SaveChangesAsync. Even with monitoring I cannot see any bottlenecks in our applications execution either.
    – Joni
    Apr 4, 2023 at 12:32
  • 1
    @Joni, if you don't see any long-running RPC calls the cause of the slowness lies elsewhere. Do you have application logging for query execution times and other external calls?
    – Dan Guzman
    Apr 4, 2023 at 14:12
  • We added more debug log briefly to our production systems and the log reports that SaveChangesAsync takes almost 3 seconds. It only adds a row to table and in some cases deletes a row. SQL Profiler tells us that these queries take only few milliseconds.
    – Joni
    Apr 11, 2023 at 4:38
  • I accept your answer since it was definitely helpful in pointing towards the right solution. I believe this problem was caused by bloated DbContext in Entity Framework and therefore this was not so much related to databases, but rather to programming.
    – Joni
    May 5, 2023 at 5:42

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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