What is "Audit Logout" in SQL Server Profiler?

Question

I'm running a data import (using C#/Linq), and naturally I'm trying to optimize my queries as much as possible. To this end I'm running a trace on the DB using SQL Server Profiler, with my trace filtered by my SQL login name (it's a name that can uniquely be attributed to my data import process).

Strangely enough, most of my SQL statements are really quick :) - very few queries even break over the 1ms mark. But spaced in between all my queries are several rows where the EventClass is "Audit Login" or "Audit Logout" - and the duration of an "Audit Logout" can be up to a minute!

Has this got something to do with the fact that I'm using transactions in my import? If so, is there any way to find which are the big-hitting queries so I can clean those up?

Heller

related: #279901 – Paperback

related: #44920875 – Stillhunt

Answer 1

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'.

Pistoia

Interesting, thanks! But then why is the number of reads so high (~400,000) when the number of reads for the queries between the "login" and "logout" is only 56? – Heller

It is the number of ms from login to logout. Not the actual amount of times the queries within the connection used. 400 000ms is about 7 minutes. Look at the CPU, reads and write columns to try and locate queries that are high on CPU and/or disk usage - both killing performance. – Pistoia

I'm sorry, do you mean that Reads responses to time measurement? – Fifteen

The logout "Reads" value seems really high on mine, considering there's only one operation with 3 reads listed between it and login. – Worry

It should be noted that the Reads column doesn't represent rows returned by queries but the # of logical disk reads. A query that doesn't even return anything may scan an entire table of 1 million record looking for the nothing to return which would generate a very large # of reads. So the # of reads isn't really be naturally correlated with the # of queries. – Tentative

The "Reads" seems to be a monotone, increasing value. When I find two consecutive "Audit Logout" rows in the trace, and subtract the "Reads" at the earlier row from the "Reads" in the later row, I get a small positive value that is equal to the "Reads" in the later's contained database activity or "RPC". – Effluent

Answer 2

Login/Logout events are related to the setting up / tearing down. IIRC the time is the 'was logged in for time' as opposed to a processing duration as with other log events.

In general, one hides these events unless you suspect there's an issue with connection pool management etc.

The raw times for the batches should be sufficient to diagnose the time the actual activity is taking including the impact of any transactions etc.

Paperback

Is it possible to inspect that "setting up / tearing down" in more detail? Please see following related question: #44920875 – Stillhunt

Answer 3

Also worth noting as in this answer that Audit Login/Logout may just mean the connection is being reused from / returned to the connection pool.

You can use another field from the event to determine if it's a connection pool event or a 'real' login/logout.

Syverson

Answer 4

The Audit Logout event class indicates that a user has logged out of (logged off) Microsoft SQL Server. Events in this class are fired by new connections or by connections that are reused from a connection pool.

it's the total time the connection was logged in for, including idle time, so it doesn't indicate a performance problem. Also profiling logins/logouts is very unlikely to cause a performance problem. You'd be better off looking for poorly performing queries, possibly long-running queries.

For more info i suggest https://msdn.microsoft.com/en-us/library/ms175827.aspx :)

Uticas

Are you sure Audit Logout events are fired when connections are reused from a connection pool? I thought connection pools were an example of a reason why you might see high Audit Logout durations, because the connection is open but idle for most of its life, – Altazimuth