We are told that SQL Server 2008 R2 Audit (and SQL Server 2008 Audit) has much less performance overhead than SQL Trace when we try to capture the same information. Knowing how SQL Server R2 Audit is implemented (i.e. on top of the extended events infrastructure), I’ve always taken that as a given and never bothered to check it out.
Recently, I had to capture some object access information, and it turned out that SQL Audit was not the most convenient tool for the task. I had to go back to SQL Trace. There, the question of how much cheaper is an audit relative to an equivalent trace came up. I thought it’s time to explore that a bit.
I wanted to explore two questions:
- In the most extreme case (i.e. when the processors are heavily loaded), how much degradation in transaction throughput should I expect if I turn on SQL Audit vs. if I turn SQL Trace?
- If the processors are moderately loaded, should I expect a performance degradation if I turn on SQL Audit or SQL Trace?
The first question is the worst case scenario you probably should never run into. But it’s always good to know where the boundary is. The second question is a realistic and more common scenario.
The processor load levels were controlled with my trusty TPC-C workload driver as follows:
- Heavy CPU load. This was generated by 100 simulated users submitting the standard TPC-C readonly queries without any wait between any two consecutive calls. The total processor time on the 12-core (or 24-logical-processor) server was sustained at ~92%, and the transaction throughput (as measured by one of the TPC-C transactions) was steady at ~16,000 per second or about 32,000 batch requests per second on the SQL Server 2008 R2 instance.
- Medium CPU load. This was generated by 100 simulated users submitting the standard TPC-C readonly queries with a 10ms wait between two consecutive calls. Compared to the previous load scenario, this otherwise rather small wait caused the total processor time on the server to sustain at a very low level at about 2%. In a way, it may be more appropriate to label this a light load level. But the sustained transaction throughput was about 3,100 per second or 6,200 batch requests per second, which still kept SQL Server busy looking up the pages.
For each of the above two load levels, three conditions were tested:
- No Audit/No Trace. In this case, I did not enable any SQL Audit session or run any SQL Trace. This was our baseline.
- With Audit. In this case, I turned on a standard audit with 1000ms queue delay and the output was sent to files with each file capped at 500MB. The database audit specification included all the SELECT statements on all the TPC-C user tables. No SQL Trace was enabled.
- With Trace. A SQL Trace that was more or less equivalent to the audit described above was started with the trace results sent to the same drive folder as in the above audit. The trace files were also specified to rollover to a new one ever 500MB. No SQL audit was enabled.
The SQL script to create the audit and the database audit specification is listed below:
USE [master]
GO
CREATE SERVER AUDIT [Audit]
TO FILE
(FILEPATH = N'E:\'
,MAXSIZE = 500 MB
,MAX_ROLLOVER_FILES = 2147483647
,RESERVE_DISK_SPACE = OFF
)
WITH
(QUEUE_DELAY = 1000
,ON_FAILURE = CONTINUE
,AUDIT_GUID = '5501f383-4357-42f5-a9c4-c87a66ecc08b'
)
GO
USE [sqlTestC]
GO
CREATE DATABASE AUDIT SPECIFICATION [DBAudit]
FOR SERVER AUDIT [Audit]
ADD (SELECT ON OBJECT::[dbo].[warehouse] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[district] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[customer] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[history] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[new_order] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[orders] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[item] BY [public]),
ADD (SELECT ON OBJECT::[dbo].[stock] BY [public])
WITH (STATE = ON)
GO
And the SQL script to create the SQL trace is pasted below:
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
set @maxfilesize = 500
exec @rc = sp_trace_create @TraceID output, 2, N'E:\Audit_Trace', @maxfilesize, NULL
if (@rc != 0) goto error
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 45, 7, @on
exec sp_trace_setevent @TraceID, 45, 55, @on
exec sp_trace_setevent @TraceID, 45, 8, @on
exec sp_trace_setevent @TraceID, 45, 16, @on
exec sp_trace_setevent @TraceID, 45, 48, @on
exec sp_trace_setevent @TraceID, 45, 64, @on
exec sp_trace_setevent @TraceID, 45, 1, @on
exec sp_trace_setevent @TraceID, 45, 9, @on
exec sp_trace_setevent @TraceID, 45, 17, @on
exec sp_trace_setevent @TraceID, 45, 25, @on
exec sp_trace_setevent @TraceID, 45, 41, @on
exec sp_trace_setevent @TraceID, 45, 49, @on
exec sp_trace_setevent @TraceID, 45, 10, @on
exec sp_trace_setevent @TraceID, 45, 18, @on
exec sp_trace_setevent @TraceID, 45, 26, @on
exec sp_trace_setevent @TraceID, 45, 34, @on
exec sp_trace_setevent @TraceID, 45, 50, @on
exec sp_trace_setevent @TraceID, 45, 66, @on
exec sp_trace_setevent @TraceID, 45, 3, @on
exec sp_trace_setevent @TraceID, 45, 11, @on
exec sp_trace_setevent @TraceID, 45, 35, @on
exec sp_trace_setevent @TraceID, 45, 51, @on
exec sp_trace_setevent @TraceID, 45, 4, @on
exec sp_trace_setevent @TraceID, 45, 12, @on
exec sp_trace_setevent @TraceID, 45, 28, @on
exec sp_trace_setevent @TraceID, 45, 60, @on
exec sp_trace_setevent @TraceID, 45, 5, @on
exec sp_trace_setevent @TraceID, 45, 13, @on
exec sp_trace_setevent @TraceID, 45, 29, @on
exec sp_trace_setevent @TraceID, 45, 61, @on
exec sp_trace_setevent @TraceID, 45, 6, @on
exec sp_trace_setevent @TraceID, 45, 14, @on
exec sp_trace_setevent @TraceID, 45, 22, @on
exec sp_trace_setevent @TraceID, 45, 62, @on
exec sp_trace_setevent @TraceID, 45, 15, @on
exec sp_trace_setevent @TraceID, 41, 7, @on
exec sp_trace_setevent @TraceID, 41, 15, @on
exec sp_trace_setevent @TraceID, 41, 55, @on
exec sp_trace_setevent @TraceID, 41, 48, @on
exec sp_trace_setevent @TraceID, 41, 64, @on
exec sp_trace_setevent @TraceID, 41, 1, @on
exec sp_trace_setevent @TraceID, 41, 9, @on
exec sp_trace_setevent @TraceID, 41, 25, @on
exec sp_trace_setevent @TraceID, 41, 41, @on
exec sp_trace_setevent @TraceID, 41, 49, @on
exec sp_trace_setevent @TraceID, 41, 26, @on
exec sp_trace_setevent @TraceID, 41, 50, @on
exec sp_trace_setevent @TraceID, 41, 66, @on
exec sp_trace_setevent @TraceID, 41, 3, @on
exec sp_trace_setevent @TraceID, 41, 11, @on
exec sp_trace_setevent @TraceID, 41, 35, @on
exec sp_trace_setevent @TraceID, 41, 51, @on
exec sp_trace_setevent @TraceID, 41, 4, @on
exec sp_trace_setevent @TraceID, 41, 12, @on
exec sp_trace_setevent @TraceID, 41, 60, @on
exec sp_trace_setevent @TraceID, 41, 5, @on
exec sp_trace_setevent @TraceID, 41, 13, @on
exec sp_trace_setevent @TraceID, 41, 29, @on
exec sp_trace_setevent @TraceID, 41, 61, @on
exec sp_trace_setevent @TraceID, 41, 6, @on
exec sp_trace_setevent @TraceID, 41, 14, @on
declare @intfilter int
declare @bigintfilter bigint
exec sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler - 95a2ce5b-6ec1-4d27-a667-fb86601af54a'
exec sp_trace_setstatus @TraceID, 1
select TraceID=@TraceID
goto finish
error:
select ErrorCode=@rc
finish:
go
The test results are summarized in the next two charts.
With all the CPUs on the server heavily loaded, turning on SQL Audit to log all the SELECT statements caused the transaction throughput to drop from 16,043 per second to 13,825 per second. That was about 14% drop. Given how heavy the load was and how busy the traffic was on the server, that’s a relatively small drop. Now the impact of turning on the trace was quite a different story. There, the transaction throughput went from 16,043 per second to a mere 5,012 per second. That was a 60% drop. if we use 5012 as the base reference, turning off the trace increased the transaction throughput for more than 300%. The difference in terms of performance impact was striking between SQL Audit and SQL Trace.
Again, I should note that this was an extreme case. In a real world situation, most likely the system wouldn’t be this busy. So the 14% drop in throughput is probably the ceiling, and you should probably expect much less an adverse impact by turning on a similar audit on a real production server. This next chart shows the result of turning on an audit (and separately a trace) when we don’t beat up the server with non-stop transaction traffic. As you can see, by just giving the server a little bit breathing room with a 10ms wait between the calls, the load on the server was reduced significantly and turning on either the audit or the trace had no impact at all on the throughput. Yes, the total CPU consumption went up a little bit as a result of turning on the audit or the trace, but the difference was rather insignificant.
These test results are good news for the SQL Server 2008 R2 audit feature. Now, only if it could be made a bit more useful!
The test environment was a DL360 G7 with two X5690 (6 core) processors and 64GB of RAM. Hyperthreading was enabled. The OS was Windows 2008 R2 Enterprise x64 Edition with SP1 and DBMS was SQL Server 2008 R2 Enterprise x64 Edition (10.50.1600).