SQL Server Audit Logout Creates Huge Number of Reads

High number of reads in SQL Profiler

HIGH number of reads, but low durations.

This can be a sign of execution plans which use parallelism. You may look, also, at CPU vs. Duration. If CPU is greater than Duration then this hypothesis is true.

It seems to increase all the time

Increasing value of Reads (logical reads)

Maybe, another concurrent connection insert data.

What is Audit Logout in SQL Server Profiler?

If I remember correct, the duration of an Audit Logout is the amount of time the connection was open. E.g. nothing to do with speed of the command - just the amount of time the login was 'logged in'.

SQL Server Profiler: How to inspect/understand the duration for the Audit Logout event in more detail?

When starting the SQL Profiler a window Trace Properties is shown.
The second tab Events Selection is the place where the considered events can be selected.

Activate the option Show all events.

Enable for example the option "Showplan XML FOR Query Compile" under the section "Performance" to log more events.

Also see How to determine what is compiling in SQL Server

Making sense of the number of reads/writes in SQL Profiler

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.

SQL Connection Pooling and Audit Login/Logout

Remember that connections are pooled per connectionstring. If you have many databases and connect using many connectionstrings, your app will create a new connection when none exist with the correct connectionstring. Then it will pool that connection and, if the pool is full, bump an existing connection. The default Max Pool Size is 100 connections, so if you're routinely bouncing through more than 100 databases, you'll close and open connections all the time.

It's not ideal, but you can solve the problem by always connecting to a single database (one connection string) and then switch db context 'USE [DBName]'. There are drawbacks:

  • You lose the ability to specify a user/pass per connection string (your app user needs permission to all databases).
  • Your SQL becomes more complex (especially if you're using an out-of-the-box ORM or stored procs).

You could experiment with increasing the Max Pool Size if your database count isn't huge. Otherwise, if some databases are used frequently while others aren't, you could turn pooling off on the infrequent dbs. Both items are configured via connectionstring.

As far as metrics, monitoring the login and logout events on SQL Server is a good start. If your app is pooling nicely you shouldn't see a lot of them.



Related Topics



Leave a reply



Submit