{"id":2178,"date":"2018-09-04T17:49:39","date_gmt":"2018-09-04T17:49:39","guid":{"rendered":"http:\/\/nenadnoveljic.com\/blog\/?p=2178"},"modified":"2018-09-04T17:49:39","modified_gmt":"2018-09-04T17:49:39","slug":"sql-server-extended-events-trace-overhead","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/sql-server-extended-events-trace-overhead\/","title":{"rendered":"SQL Server Extended Events Trace Overhead"},"content":{"rendered":"

SQL Server<\/h1>\n

In this blog post I’ll be measuring the Extended Events Trace overhead. Besides that I’ll be explaining potential pitfalls when interpreting the trace data. <\/p>\n

The testing was conducted on SQL Server 2017, build 14.0.1000.169.<\/p>\n

The following SQL batch took 61<\/span> seconds to complete:<\/p>\n

\r\nDECLARE @starttime datetime, @endtime datetime\r\nDECLARE @cnt int = 0, @ts_start int ;\r\n\r\nSET @starttime =getdate() ;\r\n\r\nBEGIN\r\n    WHILE @cnt < 100000000\r\n\tBEGIN\r\n\t   SET @cnt = @cnt + 1;\r\n\tEND;\r\nEND\r\n\r\nSET @endtime = GETDATE() ;\r\nSELECT @@spid spid, Datediff(s, @starttime, @endtime) elapsed_seconds\r\n\r\nGO\r\n\r\nspid      elapsed_seconds<\/span>\r\n58        61<\/span>\r\n<\/code><\/pre>\n
By sampling sys.dm_exec_requests in another session we can verify that the batch is CPU bound (the times are in ms):<\/p>\n
\r\ndeclare @spid int = 58, @i int = 1, @samples int = 60 ;\r\nbegin\r\n  while ( @i <= @samples ) \r\n  begin\r\n    select cpu_time,total_elapsed_time from sys.dm_exec_requests \r\n\t  where session_id = @spid\r\n\twaitfor delay '00:00:01'\r\n\tset @i = @i + 1\r\n  end\r\nend ;\r\n\r\ncpu_time<\/span>    total_elapsed_time\r\n56802<\/span>\t     60483\r\n<\/code><\/pre>\n
After starting the sql_batch_completed trace the execution time increased by more than 20%!<\/p>\n
CREATE EVENT SESSION [batch] ON SERVER \r\nADD EVENT sqlserver.sql_batch_completed(SET collect_batch_text=(1)\r\n    WHERE ([sqlserver].[session_id]=(58)))\r\nWITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)\r\nGO<\/code><\/pre>\n
\r\nspid        elapsed_seconds\r\n58          74<\/span>\r\n<\/code><\/pre>\n
According to the Extended Event Trace the overhead wasn’t spent on the CPU:<\/p>\n
\r\ncpu_time: 63,781,000 us<\/span>\r\nduration: 74,653,151 us\r\n<\/code><\/pre>\n
In contrast, according to sys.dm_exec_requests the overhead was completely CPU bound:<\/p>\n
\r\ncpu_time    total_elapsed_time\r\n73632<\/span>       74270\r\n<\/code><\/pre>\n
By observing the CPU time with the Task Manager we can confirm that the cpu_time information in sys.dm_exec_requests is correct.<\/p>\n
Luckily, not all events are detrimental to the performance. For example, the logout event doesn’t have any measurable impact, although it also collects the cpu_time:<\/p>\n
spid       elapsed_seconds\r\n58         62<\/span><\/code><\/pre>\n
CREATE EVENT SESSION [logout] ON SERVER \r\nADD EVENT sqlserver.logout(\r\n    WHERE ([package0].[equal_uint64]([sqlserver].[session_id],(58))))\r\nWITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)\r\nGO<\/code><\/pre>\n
Oracle<\/h1>\n
I executed an equivalent test case on an Oracle 12.2 database on Solaris 11.3:<\/p>\n
alter session set tracefile_identifier = 'LOOP' ;\r\nalter session set timed_statistics=true ;\r\nalter session set events '10046 trace name context forever, level 12' ;\r\n\r\nset timing on \r\n\r\ndeclare \r\n  i integer := 0 ;\r\nbegin\r\n  while i < 500000000\r\n  loop\r\n    i := i + 1 ;\r\n  end loop ;\r\nend ;\r\n\/\r\n\r\nALTER SESSION SET EVENTS '10046 trace name context off';<\/code><\/pre>\n
The tracing didn't introduce any measurable difference. The Oracle database CPU instrumentation is very efficient - it performs just two OS kernel calls to get the cumulative process CPU times before and after the SQL execution. Their difference is the time the process spent on the CPU. <\/p>\n
By the way, here are two articles about Oracle instrumentation internals:<\/p>\n