7

alt text

See the SQL Statements indicated in this SQL Profiler view. All these events are coming from one Client machine that is busy with a long-running process, working through a couple thousand rows. Each processing of a row takes about 6.5 seconds, which is what the SQL Profiler is showing as the time between logouts, even though the actual update statement takes only 1ms. Each login/logout uses the same SPID. See that between any given Login and Logout event, the SQL Statements indicate a Reads count of 17 and a Writes count of 0. Yet, the Logout event indicates a total Reads count in excess of 2million and a writes count in excess of 10k. What events do I need to be profiling to try to figure out what statement is causing those reads/writes, because I suspect that those are the ones causing the 6.5 second delay, yet I can't see them happening?

AndreKR
  • 32,613
  • 18
  • 106
  • 168
Shawn de Wet
  • 5,642
  • 6
  • 57
  • 88

1 Answers1

7

The Reads/Writes figures given for the Audit:Logout event are the cumulative totals for the duration of that connection. In itself, the values don't tell you any detail - if you run 10 commands within the lifetime of a connection, you'll be seeing the total figures for all 10 commands within that session.

To know what the breakdown was by statement, you need to look at the SQL:BatchCompleted (or SQL:StmtCompleted) events that are recorded for that same SPID between the starting Audit:Login event, and the ending Audit:Logout event.

Update: Looking at the image, the thing that looks a bit odd (to me at least), is that after each Audit:Logout, the Reads value is not reset, and so each time it is being incremented by the number of reads for the statement being executed (17). I'm not sure 100% therefore at what point that figure will be reset - but the basic point is that the figure is cumulative and could have been built up over time/a number of statements so doesn't necessarily mean you have a heavy query hitting the server!

I suspect that Reads/Writes figures for Audit:Logout are behaving cumulatively as above. But the Duration bucks that trend. It looks like Duration is not cumulative. Some descriptions from MSDN:

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

AdaTheDev
  • 142,592
  • 28
  • 206
  • 200
  • It seems that the Duration column is the only one that resets since the last logout. The Reads/Writes are indeed cumulative on the SPID. So I am less panicked about the fact that there are so many...now I've still gotta try to figure out what is the cause of the 6.5sec duration when the actual statement is only 1ms! – Shawn de Wet Dec 01 '10 at 11:17
  • @Shawn -Can't see the full accuracy StartTime in the screenshot, but it looks almost as if the Duration shown is the time from one Audit:Logout to the next. Maybe that's why it's documented as being "approximately". I don't think it's anything to worry about. – AdaTheDev Dec 01 '10 at 11:22