Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 

Cleveland DBA

Colleen Morrow is a Database Engineer for a software company in Westlake, Ohio. She has worked in the IT industry for 15+ years, doing everything from technical support to development to database administration on Informix, Oracle, and SQL Server platforms.

SQL Server 2012 – Bug in sys.fn_xe_file_target_read_file?

So I finally managed to get my hands on a VM with Windows 2008 R2 SP1 so I could install SQL 2012. (Aside: one of the biggest obstacles to progress is bureaucracy.) Anywho, I plan to explore all of the new features and functionality in 2012 and, of course, blog all about it here.

But I couldn’t resist diving in and checking out the newly expanded Extended Events in the hopes I’ll have something to add to my DDL Auditing presentation.Things were going well, I’d gotten the event session created and it was working as intended. One of the downsides to XEvents is that there’s no way to specify a table for your target. The best target for my particular scenario was an asynchronous file. Not ideal, but I can work with it.

Well, I think I can, anyway. I seem to be running into some wonky behavior while using the sys.fn_xe_file_target_read_file function. I’ll show you what I mean. I configured my XEvents session to trace object_altered, object_created, and object_deleted events. I started the session and ran through a test script a few times to make sure my session was capturing the events I wanted and filtering out what I didn’t want. Then I checked the log using the following query (I’ve stripped down the SELECT clause to only include the fields that illustrate the problem I’m having):

SELECT
	event_xml.value('(./action[@name="event_sequence"]/value)[1]', 'nvarchar(max)') as EventSequence,
	event_xml.value('(./action[@name="collect_system_time"]/value)[1]', 'nvarchar(max)') as SystemTime,
	substring(file_name, len(file_name)-charindex('\',reverse(file_name))+2, len(file_name)) as file_name_only,
	file_offset
FROM
	(SELECT file_name, file_offset, CAST(event_data AS XML) xml_event_data
		FROM sys.fn_xe_file_target_read_file ('D:\Data\MSSQL11.MSSQLSERVER\MSSQL\Log\DDL Audit*.xel', NULL, NULL, NULL)) AS event_table
	CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
ORDER BY file_name, file_offset, SystemTime, EventSequence

And I get these results:

So far so good. Now obviously I don’t want to report on the same changes over and over again, so what I was trying to do was use the initial_file_name and initial_offset parameters to grab new records. So if I had run an Audit report after the first set of changes, the next time I ran that report I would use the offset of the last record I’d reported (in this case 15872) to grab the records that came after that. Like so:

SELECT
	event_xml.value('(./action[@name="event_sequence"]/value)[1]', 'nvarchar(max)') as EventSequence,
	event_xml.value('(./action[@name="collect_system_time"]/value)[1]', 'nvarchar(max)') as SystemTime,
	substring(file_name, len(file_name)-charindex('\',reverse(file_name))+2, len(file_name)) as file_name_only,
	file_offset
FROM
	(SELECT file_name, file_offset, CAST(event_data AS XML) xml_event_data
		FROM sys.fn_xe_file_target_read_file ('D:\Data\MSSQL11.MSSQLSERVER\MSSQL\Log\DDL Audit*.xel', NULL,
		'D:\Data\MSSQL11.MSSQLSERVER\MSSQL\Log\DDL Audit_0_129671513097450000.xel', 15872)) AS event_table
	CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
ORDER BY file_name, file_offset, SystemTime, EventSequence

Which, correctly, returns this result set:

Still good. The problem starts when I have more than one file, which could happen with rollover, the instance restarting, or just stopping and starting the XEvents session. So let me do that and generate some more changes. Then I’ll rerun my initial query.

Here we can see that a new log file was created and the offset was reset. Now, according to BOL the initial_file_name is “The first file to be read from path” and initial_offset is “the offset in the first file where reading begins.” It also stresses that these two values are paired.  So, I would expect that if I ran this query:

SELECT
	event_xml.value('(./action[@name="event_sequence"]/value)[1]', 'nvarchar(max)') as EventSequence,
	event_xml.value('(./action[@name="collect_system_time"]/value)[1]', 'nvarchar(max)') as SystemTime,
	substring(file_name, len(file_name)-charindex('\',reverse(file_name))+2, len(file_name)) as file_name_only,
	file_offset
FROM
	(SELECT file_name, file_offset, CAST(event_data AS XML) xml_event_data
		FROM sys.fn_xe_file_target_read_file ('D:\Data\MSSQL11.MSSQLSERVER\MSSQL\Log\DDL Audit*.xel', NULL,
		'D:\Data\MSSQL11.MSSQLSERVER\MSSQL\Log\DDL Audit_0_129671535441930000.xel', 15872)) AS event_table
	CROSS APPLY xml_event_data.nodes('//event') n (event_xml)
ORDER BY file_name, file_offset, SystemTime, EventSequence

I’d get only rows 18 through 25, right?:

But I don’t. What I get is this:

It acknowledges the offset I specified, it’s only returning records after that offset. The problem is that it seems to be ignoring the initial_file_name parameter, because it’s returning records from both files. From everything I’ve read, I believe I’m using these parameters correctly, so perhaps there’s a bug in this version. Or maybe I am doing something wrong. Has anyone else out there had an opportunity to play with this and confirm or refute my findings? I’d love to get this working.

Comments

Leave a comment on the original post [colleenmorrow.com, opens in a new window]

Loading comments...