SQL Server – RML Utility – Converting Extended Events to SQL Server Profiler Trace Files

Background

Extended Events is the modern way to collect events.  But, in some cases one might want to convert Extended Events to SQL Server Profiler Traces.

RML Utility

Reading through a blog post found out one can convert files generated through Extended Events into Profiler Trace Files.

Download Site

The latest version of RML Utility are available here.

Curiosity

The saying goes curiosity killed the cat.

Same here this last Monday in January.

 

Installation

Download and Installed RML Utilities.

Review Installation

Targeted Folder

The targeted folder is C:\Program Files\Microsoft Corporation\RMLUtils

ReadTrace

File Version

Image

Explanation

The file version is 9.4.51.0

 

Processing

Code


set "_folderReadTrace=C:\Program Files\Microsoft Corporation\RMLUtils\"

set "_xelFolder=Z:\Microsoft\SQLServer\ExtendedEvents\TraceFiles\replay"

set "_xelFileFirst=replay_0_131617352214050000.xel"

set "_xelFileTarget=%_xelFolder%\%_xelFileFirst%"

set "_tracefile=Z:\Microsoft\SQLServer\ProfileTrace\TraceFiles"

set "_sqlServer=DBLAB"

if not exist %_tracefile% mkdir %_tracefile%

"%_folderReadTrace%\readtrace.exe"  -S%_sqlServer% -a -I"%_xelFileTarget%" -MS -o"%_tracefile%"

 

Output

Image

Textual


01/29/18 16:29:39.892 [0X000015D8] I/O Completion manager started
01/29/18 16:29:39.893 [0X00002BE4] Attempting DOD5015 removal of [Z:\Microsoft\S
QLServer\ProfileTrace\TraceFiles\ReadTrace.log]
01/29/18 16:29:39.896 [0X00002BE4] Readtrace a SQL Server trace processing utili
ty.
Version 9.04.0051 built for x64.
Copyright ⌐ 1997-2014 Microsoft. All Rights Reserved
01/29/18 16:29:39.897 [0X00002BE4]             Computer: D-ITS-AYSOSQL02
01/29/18 16:29:39.897 [0X00002BE4]          Base Module: C:\Program Files\Micros
oft Corporation\RMLUtils\ReadTrace.exe
01/29/18 16:29:39.897 [0X00002BE4]           Process Id: 6480
01/29/18 16:29:39.898 [0X00002BE4]  Active proc mask(0): 0x0000000F
01/29/18 16:29:39.898 [0X00002BE4]         Architecture: 9
01/29/18 16:29:39.898 [0X00002BE4]            Page size: 4096
01/29/18 16:29:39.898 [0X00002BE4]                 CPUs: 4
01/29/18 16:29:39.899 [0X00002BE4]     Processor groups: 1
01/29/18 16:29:39.899 [0X00002BE4]         Highest node: 0
01/29/18 16:29:39.899 [0X00002BE4]   Proximity: 00  Node: 00
01/29/18 16:29:39.900 [0X00002BE4] ---------------------------------------
01/29/18 16:29:39.900 [0X00002BE4]                Group: 0
01/29/18 16:29:39.900 [0X00002BE4] ---------------------------------------
01/29/18 16:29:39.901 [0X00002BE4]         Processor(s): 0x00000001 Function uni
ts: Separated
01/29/18 16:29:39.901 [0X00002BE4]         Package mask: 0x00000003
01/29/18 16:29:39.901 [0X00002BE4]         Processor(s): 0x00000002 Function uni
ts: Separated
01/29/18 16:29:39.901 [0X00002BE4]         Processor(s): 0x00000004 Function uni
ts: Separated
01/29/18 16:29:39.902 [0X00002BE4]         Package mask: 0x0000000C
01/29/18 16:29:39.902 [0X00002BE4]         Processor(s): 0x00000008 Function uni
ts: Separated
01/29/18 16:29:39.902 [0X00002BE4]         Processor(s): 0x0000000F assigned to
Numa node: 0
01/29/18 16:29:39.907 [0X00002BE4] Current time bias: 480 minutes 8.00 hours DST
 Standard
01/29/18 16:29:39.907 [0X00002BE4] -SDBLAB
01/29/18 16:29:39.908 [0X00002BE4] -a
01/29/18 16:29:39.908 [0X00002BE4] -IZ:\Microsoft\SQLServer\ExtendedEvents\Trace
Files\replay\replay_0_131617352214050000.xel
01/29/18 16:29:39.908 [0X00002BE4] File mirroring enabled, with single file targ
et
01/29/18 16:29:39.909 [0X00002BE4] -MS
01/29/18 16:29:39.909 [0X00002BE4] -oZ:\Microsoft\SQLServer\ProfileTrace\TraceFi
les
01/29/18 16:29:39.910 [0X00002BE4] Using language id (LCID): 1024 [English_Unite
d States.1252] for character formatting with NLS: 0x0006020E and Defined: 0x0006
020E
01/29/18 16:29:39.911 [0X00002BE4] Attempting to cleanup existing RML files from
 previous execution
01/29/18 16:29:39.991 [0X00002BE4] Detecting list of matching XEL files in the s
ame directory
01/29/18 16:29:40.039 [0X00002BE4]  INFO: Using additional file system cache rea
d ahead for XEL input
01/29/18 16:29:40.046 [0X00002BE4] XEL READER ERROR: The tookLock argument must
be set to false before calling this method.
01/29/18 16:29:40.048 [0X00002BE4] XEL READER ERROR: Attempt to open file Z:\Mic
rosoft\SQLServer\ExtendedEvents\TraceFiles\Replay\replay_0_131617352214050000.XE
L failed, see previous error(s) for more details.
01/29/18 16:29:40.049 [0X00002BE4] ERROR: Attempt to open Z:\Microsoft\SQLServer
\ExtendedEvents\TraceFiles\Replay\replay_0_131617352214050000.XEL failed.
01/29/18 16:29:40.050 [0X00002BE4] ERROR: Unable to construct proper base metada
ta generation for Z:\Microsoft\SQLServer\ExtendedEvents\TraceFiles\Replay\replay
_0_131617352214050000.XEL
01/29/18 16:29:40.053 [0X00002BE4] ERROR: Attempt to determine list of .XEL file
s failed.
01/29/18 16:29:40.057 [0X00002BE4] *** ERROR: Attempt to initialize trace file r
eader failed with operating system error 0x80070006 (The handle is invalid)
01/29/18 16:29:40.061 [0X00002BE4] Reads completed - Global Error Status 0xfffff
ffe
01/29/18 16:29:40.062 [0X00002BE4] Signaling worker threads to complete final ac
tions.
01/29/18 16:29:40.067 [0X00002BE4] Waiting for the worker threads to complete fi
nal actions.
01/29/18 16:29:40.069 [0X00002BE4] Performing general cleanup actions.
01/29/18 16:29:40.072 [0X00002BE4] Performing final mirroring actions.
01/29/18 16:29:40.075 [0X00002BE4] Total Events Processed: 0
01/29/18 16:29:40.076 [0X00002BE4]  Total Events Filtered: 0
01/29/18 16:29:40.077 [0X00002BE4] =============================================
=
01/29/18 16:29:40.079 [0X00002BE4] WARNING: A significant portion of the events
where filtered.
01/29/18 16:29:40.086 [0X00002BE4]          You may want to check the filtering
criteria.
01/29/18 16:29:40.088 [0X00002BE4] =============================================
=
01/29/18 16:29:40.090 [0X00002BE4] *********************************************
**********************************
* ReadTrace encountered one or more ERRORS. An error condition typically      *
* stops processing early and the ReadTrace output may be unusable.            *
* Review the log file for details.                                            *
*******************************************************************************
01/29/18 16:29:40.094 [0X00002BE4] ***** ReadTrace exit code: -2
01/29/18 16:29:40.097 [0X00002BE4]  INFO: Max set-aside XEL event hash table ent
ry count: 0
01/29/18 16:29:40.131 [0X00002BE4]
01/29/18 16:29:40.134 [0X00002BE4] INFO: Cleaning up connection info hash table
>

Explanation

Key details:

  1. [0X00002138] Detecting list of matching XEL files in the same directory
  2. [0X00002138] INFO: Using additional file system cache read ahead for XEL input
  3. [0X00002138] XEL READER ERROR: The tookLock argument must be set to false before calling this method.
  4. [0X00002138] XEL READER ERROR: Attempt to open file Z:\Microsoft\SQLServer\ExtendedEvents\TraceFies\Replay\replay_0_131617352214050000.XEL failed, see previous error(s) for more details.
  5. ERROR: Attempt to open Z:\Microsoft\SQLServer\ExtendedEvents\TraceFiles\Replay\replay_0_131617352214050000.XEL failed.
    [0X00002138] ERROR: Unable to construct proper base metadata generation for Z:\Microsoft\SQLServe
    \ExtendedEvents\TraceFiles\Replay\replay_0_131617352214050000.XEL
  6. [0X00002138] ERROR: Attempt to determine list of .XEL files failed.
  7. [0X00002138] *** ERROR: Attempt to initialize trace file reader failed with operating system error 0x80070006 (The handle is invalid)
  8. [0X00002138] Reads completed – Global Error Status 0xfffffffe
  9. [0X00002138] ***** ReadTrace exit code: -2

 

TroubleShooting

ReadTrace

Code


"C:\Program Files\Microsoft Corporation\RMLUtils\readtrace.exe" /?

Output

Explanation

  1. -I File name of the first .TRC or .XEL file to process [REQUIRED]. Note: XEL processing is ‘BETA’ and limited.
    • Clearly states that XEL ( Extended Events ) processing is in BETA mode and limited

SysInternals

Process Monitor

Captured Events
Image

Explanation

Confirmed that the extended event file was located and opened successfully.

 

Summary

It appears that readtrace at Version 9.4.51.0, last modified on Dec 10,2014 is starting to show its age.

BTW, in SQL Server parlance 9.x.y.z is MS SQL Server v2005.

Xpath Query – Compare Positional Versus Condition

Background

As always too much time on my hands.

I wanted to compare the query generated by XMLToolBox against one I tweaked gently.

Here is the post that introduces XMLToolBox.

 

Lab

Queries

XPath – Position


set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'

select

		  [resultValueUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/text/text()[1]' )
						as varchar(30)
				)




 

XPath – Condition


set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'



select

		  [resultValueUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/text/text()[1]' )
						as varchar(30)
				)


 

Compare Queries

Let us have the queries together and compare them.

 

Queried Together

Code



set nocount on;
go

declare @xml XML

set @xml=
'
<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = ''A'' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

'

select

		  [resultValueUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingPosition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[7]/text/text()[1]' )
						as varchar(30)
				)




select

		  [resultValueUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/value/text()[1]' )
						as varchar(10)
				)

		, [resultTextUsingCondition] 
			= cast
				(
					@xml.query('/event[@name="sql_batch_completed"]/data[@name="result"]/text/text()[1]' )
						as varchar(30)
				)

Query Plan Comparison – Query Inline

 

Query Plan Comparison – Side by Side

Using SQL Server Management Studio (SSMS) v2016, we can run both queries individually and compare the saved Query Plan

Image

Tabulated
Item Position  Condition
 Cached Plan Size  152 KB  192 KB
 CompileCPU  25  118
 CompileMemory  1736  2664
 CompileTime  25  118
 EstimatedSubtreeCost  806.458  410.401
 MemoryGrant  16128  17920
 OptimizationLevel  FULL  FULL
 RetrievedFromCache  true  true

 

 

Execution Time – Comparison

Image

 

Explanation
  1. Consistently the query with hardcoded position came in around 40 ms while the conditional one came in around 160ms

Summary

It appears from this one test, generated queries that rely on an element’s fixed position are less taxing on the system.

Interestingly, positional queries are costed higher.

On the other hand, queries generated via Conditions are likely less performant.

 

 

XPath Query Tools – XmlToolBox

Background

Lately I have been working more and more with Extended Events and prior to that Cached Plans exploration.

And, has both are stored as XML, it makes sense to see what tools are available for accurately querying XML data.

 

Body

Here is the collected event.


<event name="sql_batch_completed" package="sqlserver" timestamp="2017-05-01T16:44:02.507Z">
  <data name="cpu_time">
    <value>250000</value>
  </data>
  <data name="duration">
    <value>226002957</value>
  </data>
  <data name="physical_reads">
    <value>16349</value>
  </data>
  <data name="logical_reads">
    <value>16197</value>
  </data>
  <data name="writes">
    <value>0</value>
  </data>
  <data name="row_count">
    <value>0</value>
  </data>
  <data name="result">
    <value>2</value>
    <text>Abort</text>
  </data>
  <data name="batch_text">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = 'A' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </data>
  <action name="sql_text" package="sqlserver">
    <value>SELECT "dbo"."basetblb"."base_social" FROM "dbo"."basetblb" WHERE (("base_payroll_status" = 'A' ) AND ("base_service_credit" &gt; 10 ) ) </value>
  </action>
  <action name="session_server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="session_id" package="sqlserver">
    <value>72</value>
  </action>
  <action name="server_principal_name" package="sqlserver">
    <value>tracie</value>
  </action>
  <action name="server_instance_name" package="sqlserver">
    <value>HRDBDEV</value>
  </action>
  <action name="is_system" package="sqlserver">
    <value>false</value>
  </action>
  <action name="database_name" package="sqlserver">
    <value>rbpivr1</value>
  </action>
  <action name="database_id" package="sqlserver">
    <value>10</value>
  </action>
  <action name="client_hostname" package="sqlserver">
    <value>WEBSERVER01</value>
  </action>
  <action name="client_app_name" package="sqlserver">
    <value>Microsoft® Windows® Operating System</value>
  </action>
  <action name="collect_system_time" package="package0">
    <value>2017-05-01T16:44:02.508Z</value>
  </action>
  <action name="attach_activity_id_xfer" package="package0">
    <value>E2EDC810-A11C-4C62-988D-2420F86D8EAD-0</value>
  </action>
  <action name="attach_activity_id" package="package0">
    <value>008E9A10-DF7E-4C85-9C85-95629D3B647F-1</value>
  </action>
</event>

 

Googled

Googled on XML Query XPath and found many tools.

In this post we will discuss XMLToolBox.

 

XMLToolBox

I liked XMLToolBox has unlike many other tools one does not have to start with a query, just paste the the XML body unto the canvas, and point at the XML element or attribute you want to generate the query on.

URL

Here is the Link for XMLToolbox.

Usage

Here is what happens when we :

  1. Copy and paste the XML noted above unto the XML field textarea
  2. Find the result element and click on the text element

Analysis

Here is the generated Xpath:

/event[@name=”sql_batch_completed”]/data[7]/text/text()

 

Interpretation

  1. Parse using event ( /event )
  2. Look for the attribute name matching sql_batch_completed
  3. Transverse to the 7th data element
  4. Find the text element within the the 7th element and return the text portion of that element

 

Summary

XMLToolBox is easy to use and capable.

Unfortunately, it lacks flexibility because it is based on the position of elements.

If the schema changes a bit, the XPath might return the wrong element as it would refer to the original position.

 

Sql Server – Extended Events – Creating in Later Edition and Applying Against 2008/2008R2

Background

Ungratefulness is a sad part of LIFE that it is hard to see and acknowledge.

 

Scenario

One of our databases there is a reporting table that contains aggregated data for transactions that occur each month.

Things are working, but since the person that designed the Application “walked“, we do not have an insight as when it is ran, who runs it, and where it is being ran.

The end of month was yesterday and I need to quickly see what I can find out.

 

Circumstances

Unfortunately, the SQL Instance is on v2008-R2 and that version does not have a GUI for Extended Event Management.

 

Client – SSMS

Object Explorer

Object Explorer Against v2014 Instance

 

 

Object Explorer Against v2008/R2 Instance

Comparison

When the targeted instance is on v2012 or higher SSMS, Extended Event Management functionality is visible under the SQL Instance \ Management node.

But when the SQL Instance is v2008 or v2008/R2, though Extended Event ( EE ) sub-component is available under the hood, it is not exposed via the SSMS GUI.

 

Work Around

Create Baseline

We created a simple package against our v2014 SQL Instance.

Once created, we asked SSMS to please script it for us.

To do so, please access “Management” \ “Extended Events” \ Sessions \ [session] \ “Script Session as” \ “Create To”

 

 

Generated Script


CREATE EVENT SESSION [thirdPartyAppRequest] ON SERVER 
ADD EVENT sqlserver.error_reported(
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)))),
ADD EVENT sqlserver.rpc_completed(
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')),
ADD EVENT sqlserver.sp_statement_completed(SET collect_object_name=(1)
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')),
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
    WHERE ([package0].[greater_than_uint64]([sqlserver].[database_id],(4)) AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) AND [sqlserver].[client_app_name]<>N'Report Server')) 
ADD TARGET package0.ring_buffer
WITH (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=ON,STARTUP_STATE=OFF)
GO



Apply Script Against v2008-R2 SQL Instance

Errors

 

Error # Error Text Response
 Msg 25623  The event action name, “sqlserver.database_name”, is invalid, or the object could not be found
 sql_server.database_name is not exposed in v2008/R2.
Please use sql_server.database_id
 Msg 25623  The event action name, “sqlserver.server_principal_name”, is invalid, or the object could not be found   sql_server.server_principal_name is not exposed in v2008/R2.
Please use sql_server.username
 Msg 25629  For event, “sqlserver.sp_statement_completed”, the customizable attribute, “collect_object_name”, does not exist.  Comment this out “SET collect_object_name=(1)

 

 

Cleaned Up Script For v2008-R2 SQL Instance

Script


declare @extendedEvent sysname

set @extendedEvent = 'thirdPartyAppRequestScripted'

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Drop XE ' + @extendedEvent

	DROP EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 

end



CREATE EVENT SESSION [thirdPartyAppRequestScripted] ON SERVER 
ADD EVENT sqlserver.error_reported
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
	--	, sqlserver.database_name
	--	, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0))
	)
)

, ADD EVENT sqlserver.rpc_completed
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)

)	

, ADD EVENT sqlserver.sp_statement_completed
   (
	
	--Msg 25629, Level 16, State 1, Line 2
	-- For event, "sqlserver.sp_statement_completed", the customizable attribute, "collect_object_name", does not exist
	--SET collect_object_name=(1)
    
	ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    
	WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)
	
)	


, ADD EVENT sqlserver.sql_statement_completed
	(
		
		--SET collect_statement=(1)
		
		ACTION
		(
			  package0.collect_system_time
			, sqlserver.client_app_name
			, sqlserver.client_hostname
			, sqlserver.client_pid
			, sqlserver.database_id
			--, sqlserver.database_name
			--, sqlserver.server_principal_name
			, sqlserver.session_id
			, sqlserver.sql_text
			, sqlserver.username
		)
		WHERE 
		(
				 [package0].[greater_than_uint64]([sqlserver].[database_id],(4))
			 AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
			 AND [sqlserver].[client_app_name]<>N'Report Server')
		) 


ADD TARGET package0.ring_buffer

WITH 
(
	  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=ON
	, STARTUP_STATE=OFF
)

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Created XE ' + @extendedEvent

end


For Persistency

Script

    ADD TARGET package0.event_file 
     ( 
          SET 
              filename='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance'
            , max_file_size=(100) 
            , max_rollover_files=(100) 
     )
 

 

Error Message

Error # Error Text Response
Msg 25623  The target name, “package0.event_file”, is invalid, or the object could not be found
 It seems package0.event_file is not supported.
Msg 25641  For target, “package0.asynchronous_file_target”, the parameter “filename” passed is invalid.
The operating system returned error 2 while creating the file ‘T:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xel’.
Verify that the path exists and that the SQL Server startup account has access to the location.
 Change targeted folder name to a directory that exists and that the Service Account has access to.
 Msg 25641  For target, “package0.asynchronous_file_target”, the parameter “metadatafile” passed is invalid.
The operating system returned error 2 while creating the file ‘J:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xem’.
Verify that the path exists and that the SQL Server startup account has access to the location.
 Change metadatafile’s directory to one that exists and SQL Server Account has access to.

 

 

Script ( Revised )



ADD TARGET package0.asynchronous_file_target

(
   SET 
             filename='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xel'
	   , metadatafile='E:\Microsoft\SQLServer\ExtendedEvent\Events\Performance\Performance.xem'
	   , max_file_size=(100)
 	   , max_rollover_files=(100)

)


 

Full SQL

Script


declare @extendedEvent sysname

set @extendedEvent = 'thirdPartyAppRequestScripted'

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Drop XE ' + @extendedEvent

	DROP EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 

end



CREATE EVENT SESSION [thirdPartyAppRequestScripted] ON SERVER 
ADD EVENT sqlserver.error_reported
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
	--	, sqlserver.database_name
	--	, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0))
	)
)

, ADD EVENT sqlserver.rpc_completed
(
    ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)

)	

, ADD EVENT sqlserver.sp_statement_completed
   (
	
	--Msg 25629, Level 16, State 1, Line 2
	-- For event, "sqlserver.sp_statement_completed", the customizable attribute, "collect_object_name", does not exist
	--SET collect_object_name=(1)
    
	ACTION
	(
		  package0.collect_system_time
		, sqlserver.client_app_name
		, sqlserver.client_hostname
		, sqlserver.client_pid
		, sqlserver.database_id
		--, sqlserver.database_name
		--, sqlserver.server_principal_name
		, sqlserver.session_id
		, sqlserver.sql_text
		, sqlserver.username
	)
    
	WHERE 
	(
		    [package0].[greater_than_uint64]([sqlserver].[database_id],(4)) 
		AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
		AND [sqlserver].[client_app_name]<>N'Report Server'
	)
	
)	


, ADD EVENT sqlserver.sql_statement_completed
	(
		
		--SET collect_statement=(1)
		
		ACTION
		(
			  package0.collect_system_time
			, sqlserver.client_app_name
			, sqlserver.client_hostname
			, sqlserver.client_pid
			, sqlserver.database_id
			--, sqlserver.database_name
			--, sqlserver.server_principal_name
			, sqlserver.session_id
			, sqlserver.sql_text
			, sqlserver.username
		)
		WHERE 
		(
				 [package0].[greater_than_uint64]([sqlserver].[database_id],(4))
			 AND [package0].[equal_boolean]([sqlserver].[is_system],(0)) 
			 AND [sqlserver].[client_app_name]<>N'Report Server')
		) 


ADD TARGET package0.ring_buffer

WITH 
(
	  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=ON
	, STARTUP_STATE=OFF
)

if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Created XE ' + @extendedEvent

end


if exists
(

	select *

	from    sys.server_event_sessions tblSSES

	where   tblSSES.[name] = @extendedEvent

)
begin

	print 'Start XE ' + @extendedEvent

	ALTER EVENT SESSION [thirdPartyAppRequestScripted] 
		ON SERVER 
			STATE=START;

end



Dedicated

Dedicated to ATL, I85 has enough going on already.

Have hard weeks and months ahead.

And, to Microsoft for making our lives a lot easier.

 

SQL Server – System Health thru Default Event Trace

Background

For a while here now, I have wanted to start looking at Event Trace Data to troubleshoot SQL Server System events.

 

Courtesy

Oren Bouni

Courtesy of code shared here by Oren Bouni, I am trying to make my way into a Stored Procedure.

 

Code

Why?

Why Stored Procedure (SP)?

Well, as a Stored Procedure I will likely hope for the following…

  1. Self Contained Code
  2. Better understanding and definition of the arguments / parameters
    • Parameter Sanity Check
      • How to treat missing parameter values
      • When to declare an error

Stored Procedure

Helper Modules

There are a couple of helper tools that we will employ.

They are saved in Github and available here.

Repository File Link
 DanielAdeniji/SQLServerSystemRegistryOSGet
 dbo.sp_getRegistryOSDirectory.sql  Link
 dbo.sp_getRegistryTimeZone.sql  Link

 

 

dbo.sp_SystemHealthIO

SP – Code



use [master]
go

if object_id('dbo.sp_SystemHealthIO') is null
begin

	exec('create procedure dbo.sp_SystemHealthIO as ');

end
go

alter procedure [dbo].[sp_SystemHealthIO]
(
	  @basePath			nvarchar(1000) = null
	, @timezone			varchar(10)	   = null
	, @dateStart		datetimeoffset = null
	, @dateEnd			datetimeoffset = null
	, @debug		    bit =0
)
as

begin

	/*

		Comment:

		a) 2017-01-19
		   Based on work identified below
		   Authored : Oren Bouni
		   Date :- March 24, 2013
		   Title :- SQL 2012 System health–fast analysis
		   URL  :- https://blogs.technet.microsoft.com/sqlpfeil/2013/03/24/sql-2012-system-healthfast-analysis/

	*/

	/*

		Parameters:

		a) @basePath
		   Folder name to the location of system_health_*.xel files
		   If not passed in, will use ErrorDumpDir specified for the SQL Instance

		a) @timezone
		   Datetime offset
		   For Tejuana will be '-08:00'

	*/

	set nocount on;
	set XACT_ABORT on;

	declare @basePathAsString	 nvarchar(4000)
	declare @fileExt			 nvarchar(1000)
	declare @pathToHealthSession nvarchar(1000) 


	declare @dateStartOffset datetimeOffset
	declare @dateEndOffset   datetimeOffset

	declare @fileExists		  tinyint

	declare @LOG_FORMAT_REGISTRY_READ_OPERATION_STARTED		nvarchar(4000)
	declare @LOG_FORMAT_REGISTRY_READ_OPERATION_COMPLETED	nvarchar(4000)

	declare @LOG_FORMAT_REGISTRY_READ_FAILED		nvarchar(4000)
	declare @LOG_FORMAT_FOLDER_DOES_NOT_EXIST		nvarchar(4000)

	declare @log nvarchar(4000)

	declare @errorDumpDir		   NVARCHAR(4000)	

	DECLARE @value				   NVARCHAR(1000)
	DECLARE @valueAsInt			   int --VARCHAR(1000)


	set @fileExt = 'system_health_*.xel'


	/*
		If Base Path is not specified, let us use the SQL Instance's error folder
	*/
	if (
			   (@basePath is null )
			or (@basePath = '' )
	   )
	begin
	

			exec [dbo].[sp_getRegistryOSDirectory]
					@errorDumpDir	=  @errorDumpDir output	

			--save base path
			set @basePath =  @errorDumpDir	

	end


	/*
		If @timezone is not specified, let us go get it
	*/
	if (
			   (@timezone is null )
			or (@timezone = '' )
	   )
	begin


		exec [dbo].[sp_getRegistryTimeZone]
				@timezone =@timezone output


	end


	/*
		Get Full Path
	*/
	set @pathToHealthSession = @basePath + '\' + @fileExt


	/*
		Get Date
	*/
	set @dateStartOffset = TODATETIMEOFFSET(@dateStart, @timezone)
	set @dateEndOffset = TODATETIMEOFFSET(@dateEnd, @timezone)

	set @basePathAsString = @basePath

	if (@basePathAsString is null)
	begin

		set @basePathAsString = ''

	end
	else
	begin

		set @basePathAsString = @basePath

	end


	/*
		Determine if folder exist!
	*/
	exec master.dbo.xp_fileexist 
			  @path = @basePath
			, @fileExists = @fileExists OUTPUT



	/*
		If folder does not exist, then exit
	*/
	if(@fileExists != 1)
	begin

		exec master.dbo.xp_sprintf
				  @log output
				, @LOG_FORMAT_FOLDER_DOES_NOT_EXIST
				, @basePathAsString

		raiserror(@log,1, 16)

	end


	/*
		Return result set
	*/
	; with cte
	as
	( 
		select 

			   [timestampUTC]
				= T.sdnodes.value('(event/@timestamp)[1]','datetime')
		 	
			 , [timestampLocale]
			    =  CONVERT
				(
					  datetime 
					, SWITCHOFFSET
					  (  
						CONVERT
					    (
							  datetimeoffset
							, T.sdnodes.value('(event/@timestamp)[1]','datetime')

						)
						, DATENAME(TzOffset, SYSDATETIMEOFFSET())
					)		
				)

			 , [componentName]
				= T.sdnodes.value
					(
						  '(event/data[@name="component"]/text)[1]'
						, 'varchar(100)'
					)

			 , [componentState]
				= T.sdnodes.value
					(
						  '(event/data[@name="state"]/text)[1]'
						, 'varchar(100)'
					)

			, [longestPendingRequestsFilePath]
				= T.sdnodes.value
					(
						 '(event/data[@name="data"]/value/ioSubsystem/longestPendingRequests/pendingRequest[1]/@filePath)[1]'
						,'nvarchar(500)'
					) 

			 , [ioLatchTimeouts]
				= T.sdnodes.value
					(
						 '(event/data[@name="data"]/value/ioSubsystem/@ioLatchTimeouts)[1]'
						,'int'
					)

			 , [intervalLongIos]
				= T.sdnodes.value
					(
						 '(event/data[@name="data"]/value/ioSubsystem/@intervalLongIos)[1]'
						,'int'
					)

			, [totalLongIos]
				= T.sdnodes.value
					(
						  '(event/data[@name="data"]/value/ioSubsystem/@totalLongIos)[1]'
						, 'int'
					)

			, [longestPendingRequestsDuration]
				= T.sdnodes.value
					(
						  '(event/data[@name="data"]/value/ioSubsystem/longestPendingRequests/pendingRequest[1]/@duration)[1]'
						, 'int'
					)

			, [longestPendingRequestsOffset]
				= T.sdnodes.value
					(
						 '(event/data[@name="data"]/value/ioSubsystem/longestPendingRequests/pendingRequest[1]/@offset)[1]'
						,'int'
					)

			, [longestPendingRequestsHandle]
				= T.sdnodes.value
					(
						 '(event/data[@name="data"]/value/ioSubsystem/longestPendingRequests/pendingRequest[1]/@handle)[1]'
						,'nvarchar(20)'
					)


		FROM
		(    
			SELECT bpr.query('.') as sdnodes
			FROM 
			(   
				select CAST(event_data AS XML)  as target_data,*
			
				from sys.fn_xe_file_target_read_file(@pathToHealthSession,NULL,NULL,NULL)
			
				where object_name like 'sp_server_diagnostics_component_result'

			) AS x
			CROSS APPLY target_data.nodes('/event') AS n(bpr)
		) as T

		WHERE T.sdnodes.value
				(
					  '(event/data[@name="component"]/text)[1]'
					, 'varchar(100)'
				) ='IO_SUBSYSTEM'

	)

	select *

	from   cte

	where  (
				   --Highlight records that are not clean
				   -- or have a file path 	
				   ( cte.[componentState] not in ( 'CLEAN') )

				or ( cte.[longestPendingRequestsfilePath] is not null ) 

				--or ( 1=1)

		  )


	and
		  (

		  	/*
				Date Range
			*/
			(
				 ( 
					cte.[timestampLocale] between 
						      isNull(@dateStart, '1900-01-01') 
						 and  isNull(@dateEnd, GETUTCDATE())
				)
			)

		  )

	order by 
			cte.[timestampLocale] desc

end
go


EXEC sys.sp_MS_marksystemobject '[dbo].[sp_SystemHealthIO]'
go


 

Invocation



use [master]
go

declare @basePath			nvarchar(1000)
declare @timezone			varchar(10) 
declare @dateStart			datetimeoffset
declare @dateEnd			datetimeoffset
DECLARE @debug				bit

--set datetime offset to PST
set @timezone	 = '-08:00'

--set date range
set @dateStart = '2017-01-16 20:00' 
set @dateEnd   = getdate()

set @debug	 = 1

exec [dbo].[sp_SystemHealthIO]
		  @basePath = @basePath
		, @timezone	 = @timezone	
		, @dateStart = @dateStart
		, @dateEnd = @dateEnd
		, @debug = @debug



 

Output

systemhealthio_20170119_0121pm

 

Explanation

In the screenshot above we can see a couple of things:

  1. timestampUTC
    • Everything is logged in UTC
  2. timestampLocale
    • Based on our timezone, converted things to localeTime
  3. componentName
    • Which component are we narrowing in on
  4. componentState
    • ComponentState Values
      • CLEAN is good
      • WARNING is not so good
  5. FilePath
    • The actual file that is being instrumented

 

Source Control

GitHub

Availed in Github here.

And, the Helper modules are here.