Microsoft Windows PowerShell and SQL Server 2005 WMI Providers - Part 2

Tuesday Jan 22nd 2008 by DatabaseJournal.com Staff
Share:

Part 2 of this series covers the WMI Provider for Server Events explaining how to monitor DDL and trace events in a SQL Server instance by leveraging this provider and Windows PowerShell.

by Yan Pan

In part 1 of this article series, we illustrated how to access one of the two SQL Server 2005 WMI Providers - WMI Provider for Configuration Management, using Window PowerShell. We also illustrated how to use the provider to perform administrative tasks.

In part 2 of this series, we are going to move on to the other SQL Server 2005 WMI provider - the WMI Provider for Server Events. We will show you how to monitor DDL and trace events in a SQL Server instance by leveraging this provider and Windows PowerShell.

The WMI Provider for Server Events provider lets you use the Windows Management Instrumentation (WMI) to monitor server events. The provider turns SQL Server into a managed WMI object and leverages event notification in SQL Server.

This provider manages a WMI namespace for each instance of SQL Server 2005. The name of the namespace is in the format root\Microsoft\SqlServer\ServerEvents\instance_name. For a default instance, the namespace is root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER. For a named instance Instance1, the namespace is root\Microsoft\SqlServer\ServerEvents\Instance1.

When WMI events in the namespace of a SQL Server instance are monitored for the first time, the provider creates a target service in the msdb database called SQL/Notifications/ProcessWMIEventProviderNotification/v1.0 and a queue for the target service WMIEventProviderNotificationQueue.

When a WMI management application issues a WMI Query Language (WQL) query to access SQL Server events, the WMI Provider for Server Events translates the query into an event notification. If events on the server level are queried, the provider creates a server event notification. If events in a database or on a particular database object are queried, the provider creates an event notification in the target database.

After the required event notification is created, it sends event data to the target service SQL/Notifications/ProcessWMIEventProviderNotification/v1.0 in the msdb database. The target service puts the event into the WMIEventProviderNotificationQueue queue in the msdb database. The provider reads the XML event data from this queue and transforms it into managed object format before returning it to the client application.

Because Service Broker services are used by the event notification to send messages about server events, Service Broker must be enabled in the msdb database and the target database wherever the events are generated. To check if the service brokers are enabled on a SQL Server instance, and to get the broker instance GUID in each database, run this query on the instance.

SELECT name, is_broker_enabled, service_broker_guid FROM sys.databases;

If the is_broker_enable column for a database has a value 0, it means that Service Broker is not enabled for the database. To enable Service Broker for a database, for example, the AdventureWorks database, use the ALTER DATABASE statement.

ALTER DATABASE AdventureWorks SET ENABLE_BROKER

The service_broker_guid column contains the service broker GUID in each database. The broker instance in the msdb database is the most useful because msdb hosts the target service and the service queue.

A complete list of server events classes can be found at

http://technet.microsoft.com/en-us/library/ms186449.aspx

WMI Query Language (WQL)

The WMI Query Language (WQL) is designed to perform queries against the CIM repository to retrieve WMI information. WQL is a subset of ANSI SQL with minor semantic changes to support WMI. Therefore, it is very straightforward to write WQL queries.

WQL queries can be divided into three types:  data, event and schema.

Data queries are used to retrieve class instances and data associations. Every Get-WmiObject command we have seen in Part 1 of this series can be mapped to a data query - a Select statement with the "-filter" parameter being mapped to a "where" clause.

Event queries are used to subscribe to WMI events and will be used in this article. Event providers use event queries to register to one or more events. Event queries are not supported in Windows PowerShell v1. For now, we need to use Windows PowerShell in conjunction with .NET classes to monitor WMI events.

Schema queries are used to retrieve class definitions and schema associations. We are not going to cover this kind of queries in this series.

Event Handling with .NET and Windows PowerShell

Since Windows PowerShell v1 does not support event queries, we need to create a temporary event consumer in .NET from the System.Management.ManagementEventWatcher class. The constructor of this class accepts two objects - a System.Management.WQLEventQuery object specifies a WQL query to retrieve events of interest, and a System.Management.ManagementScope object specifies a namespace to watch.

For example, to subscribe to the DDL_DATABASE_LEVEL_EVENTS event class in the AdventureWorks database on the default instance on a computer PowerPC, the WQL query is:

$wqlQuery = "SELECT * FROM DDL_DATABASE_LEVEL_EVENTS WHERE DatabaseName= 'AdventureWorks'"

To create a System.Management.WQLEventQuery object associated with this WQL query, execute this command:

$objWql = New-Object System.Management.WQlEventQuery $wqlQuery

The events of the default instance on a computer named PowerPC are available under the namespace \\PowerPC\root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER. We create a System.Management.ManagementScope object to specify this namespace for monitoring.

$namespace = "\\PowerPC\root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$objScope = New-Object System.Management.ManagementScope $namespace

After both the WQLEventQuery and ManagementScope objects are created, we construct a new System.Management.ManagementEventWatcher object and start the watcher. The watcher therefore subscribes to events through the given query and delivers them.

$objWatcher = New-Object System.Management.ManagementEventWatcher $objScope, $objWql
$options = New-Object System.Management.EventWatcherOptions 
$timespan = New-Object System.TimeSpan(0, 0, 10) # Default monitoring interval is set to 10 seconds
$options.TimeOut = $timespan
$objWatcher.Options = $options
$objWatcher.Start()

The WaitForNextEvent method of the watcher waits for the next event that matches the specified query to arrive, and then returns it. An event object is different from a data object. You cannot use * to select all of its properties. You need to select the properties explicitly by their names. For example,

$objEvent=$objWatcher.WaitForNextEvent()
$objEvent | Select-Object ObjectType, SPID, SQLInstance, TSQLCommand

To retrieve different events, we only need to change the particular WQL query, the namespace and the selected properties of the events. Therefore, we encapsulate the above steps in a function, and reuse the function to create a watcher to monitor different events throughout this article. The complete function Get-WMIEvent.ps1 is shown here.

function Get-WMIEvent([string] $wqlQuery, [string] $namespace, [string[]] $properties)
{

$ESCkey = 27 # 27 is the key number for the Esc button. 

$objWql = New-Object System.Management.WqlEventQuery $wqlQuery

$objScope = New-Object System.Management.ManagementScope $namespace

$objWatcher = New-Object System.Management.ManagementEventWatcher $objScope, $objWql

$options = New-Object System.Management.EventWatcherOptions 
$timespan = New-Object System.TimeSpan(0, 0, 10) # Default interval is set to 10 seconds
$options.TimeOut = $timespan
$objWatcher.Options = $Options

$objWatcher.Start()

while ($true) {

	trap [System.Management.ManagementException] {continue}
	$objEvent=$objWatcher.WaitForNextEvent()
	if ($objEvent) {
		$objEvent | Select-Object $properties
		Clear-Variable -name objEvent
	}

	# Press Esc to stop the watcher and exit this function
	if ($host.ui.RawUi.KeyAvailable) { 
		$key = $host.ui.RawUI.ReadKey("NoEcho,IncludeKeyUp")
		if ($key.VirtualKeyCode -eq $ESCkey) { 

			$objWatcher.Stop()
			break
		}
	}
	
} 
}

In this function, we create a watcher object based on the given WQL query and namespace. Then we catch the events in an infinite loop. We also allow the function to exit by pressing the Esc key. The default time interval of monitoring is set to 10 seconds.

To reuse a function, the easy way is to put it in your profile. Let's include the function in the user-specific, shell-specific profile - %UserProfile%\My Documents\WindowsPowerShell\Microsoft.PowerShell_profile.ps1 or %UserProfile%\Documents\WindowsPowerShell\Microsoft.PowerShell_profile.ps1 on Windows Vista. By default, the built-in variable $profile stores the path and file name of the profile. To see the value of the $profile variable, type:

PS > $profile
C:\Users\Yan\Documents\WindowsPowerShell\Microsoft.PowerShell_profile.ps1

To determine if the user profile already exists, type:

PS > test-path $profile

If the profile exists, the command returns True. Otherwise, we need to create the profile file using this command:

PS > new-item -path $profile -type file -force

After the profile specified in the $profile variable has been created, you can enter aliases, functions, and scripts in the profile to customize your shell. To run the scripts in this article, put the Get-WMIEvent function in the profile. All the scripts included here only print out event information in the console for demonstration purposes. In real practice, you can save the output in a tracing table, notify support personnel through e-mail or page based on the output, or send an alert to an event management system such as Netcool.

Monitoring errors from the SQL Server error log

The errors from the SQL Server error log help us detect any current or potential problems, including data file growth problems, backup device problems, failed logins, insufficient lock resources, and so on. The trace event class for the SQL Server error log is ERRORLOG. In the script that follows, called MonitorErrorLog.ps1, errors from the SQL Server error log are captured and printed out. The backstroke characters (`) are used to concatenate the script lines.

$query = "SELECT * FROM ERRORLOG"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "LoginSid","PostTime","SQLInstance","IsSystem","DatabaseID", `
"ComputerName","SessionLoginName","SPID","TransactionID","EventSequence", `
"HostName","ClientProcessID","NTUserName","RequestID","DatabaseName", `
"Error","Severity","TextData","NTDomainName","LoginName","StartTime","ApplicationName"

Get-WMIEvent $query $sqlnamespace $selections

This script prints out all the properties that are available for the ERRORLOG class. Let's test it by executing a large query against the default instance on the local computer. The tempdb database cannot allocate enough space for the temporary objects used in the query execution and thus SQL Server writes an error in the error log. The script captures the error and prints it out.

PS > C:\MonitorErrorLog.ps1


LoginSid         	:	{1, 5, 0, 0...}
PostTime         	:	20071020113337.000877+000
SQLInstance      	:	MSSQLSERVER
IsSystem         	:	0
DatabaseID       	:	5
ComputerName     	:	POWERPC
SessionLoginName 	:	PowerPC\Yan
SPID             	:	55
TransactionID    	:	248152
EventSequence    	:	1700
HostName         	:	POWERPC
ClientProcessID  	:	5808
NTUserName       	:	Yan
RequestID        	:	0
DatabaseName     	:	AdventureWorks
Error            	:	1105
Severity         	:	17
TextData         	:	2007-10-20 11:33:37.55 spid55      Error: 1105, Severity: 17, State: 2.

			2007-10-20 11:33:37.55 spid55      Could not allocate space for object 
			'<temporary system object: 469194410688512>' in database 'tempdb' 
			because the 'PRIMARY' filegroup is full. Create disk space by deleting 
			unneeded files, dropping objects in the filegroup, adding additional files to 
			the filegroup, or setting autogrowth on for existing files in the filegroup.
		
NTDomainName     	:	 PowerPC
LoginName        	:	 PowerPC\Yan
StartTime        	:	 20071020113337.000563+000
ApplicationName  	:	 Microsoft SQL Server Management Studio - Query

We can see from the output, the login PowerPC\Yan executed a query against the AdventureWorks database. The query caused the primary filegroup of the tempdb database to grow and exceed its maximum size. The Error, Severity, and TextData columns provided us the complete error information. After we are notified of the error, we can either adjust the settings of the tempdb data files or work with users to improve the query. In real practice, you might want to capture only errors with severity levels 17 and higher that indicate software or hardware errors. You can achieve this easily by adding a where condition on severity to the WQL query.

Monitoring Deadlocks

A deadlock occurs when two or more sessions permanently block each other by each session having a lock on a resource, which the other sessions are trying to lock. SQL Server Database Engine has a lock monitor thread that periodically initiates a search through all of the tasks to detect deadlocks. After a deadlock is detected, the Database Engine ends a deadlock by choosing one of the threads as a deadlock victim, and a 1205 error will be thrown by SQL Server. To collect the information about the threads and the resources involved in the deadlock, we can monitor the DEADLOCK_GRAPH trace event class.  The MonitorDeadlocks.ps1 script shown here collects the deadlock information.

$query = "SELECT * FROM DEADLOCK_GRAPH"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "LoginSid", "SQLInstance", "IsSystem", "PostTime", "ComputerName", `
"SessionLoginName", "SPID", "StartTime", "TransactionID", "EventSequence", "TextData", "LoginName"

Get-WMIEvent $query $sqlnamespace $selections

Let's test this script. In a connection using spid 53, we run this query:

CREATE TABLE Test (i int)

INSERT Test SELECT 1 

GO 
BEGIN TRAN 
UPDATE Test SET i = 1 
WAITFOR DELAY '00:00:30' 
UPDATE Test2 SET i = 1 

WAITFOR DELAY '00:02:00' 
COMMIT 

DROP TABLE Test

This spid holds exclusive locks on the Test table, and tries to update the Test2 table.

In another connection using spid 54, we run this query.

CREATE TABLE Test2 (i int)

INSERT Test2 SELECT 1 
GO 
BEGIN TRAN 
UPDATE Test2 SET i = 1 

WAITFOR DELAY '00:00:30' 
UPDATE Test SET i = 1 
WAITFOR DELAY '00:02:00' 
COMMIT 

DROP TABLE Test2

This spid holds exclusive locks on the Test2 table, and tries to update the Test table. We have a deadlock situation here since spid 53 and spid 54 are blocking each other and trying to update the table the other process is holding. Our script detects the deadlock and prints out the deadlock graph.

PS > C:\ MonitorDeadlocks.ps1


LoginSid         		{1}
SQLInstance      	:	MSSQLSERVER
IsSystem         	:	1
PostTime         	:	20071021210014.000157+000
ComputerName     	:	POWERPC
SessionLoginName 	:	

SPID             	:	21
StartTime        	:	20071021210014.000120+000
TransactionID    	:	0
EventSequence    	:	19929
TextData         	:	<TextData><deadlock-list>&#x0A; <deadlock victim="processfc9
			108">&#x0A;  <process-list>&#x0A;   <process id="processd7aa

			78" taskpriority="0" logused="116" waitresource="RID: 5:1:20
			959:0" waittime="4461" ownerId="374968" transactionname="use
			r_transaction" lasttranstarted="2007-10-21T20:59:39.650" XDE
			S="0x46b28c8" lockMode="U" schedulerid="1" kpid="3788" statu
			s="suspended" spid="54" sbid="0" ecid="0" priority="0" trans
			count="2" lastbatchstarted="2007-10-21T20:59:39.650" lastbat
			chcompleted="2007-10-21T20:59:39.633" lastattention="2007-10
			-21T20:55:26.197" clientapp="Microsoft SQL Server Management
			 Studio - Query" hostname="POWERPC" hostpid="5808" loginname
			="PowerPC\Yan" isolationlevel="read committed (2)" xactid="3
			74968" currentdb="5" lockTimeout="4294967295" clientoption1=
			671090784 clientoption2="390200">&#x0A;    <executionStack
			>&#x0A;     <frame procname="adhoc" line="4" stmtstart="16"

			sqlhandle="0x02000000c1081407296ca08140bec8aa7e80cbe6b1ce361
			9">&#x0A;UPDATE [Test] set [i] = @1     </frame>&#x0A;     <
			frame procname="adhoc" line="4" stmtstart="130" stmtend="176
		 	sqlhandle=0x02000000aff0ee1498c966053682b747a4a0dc11f0c21
			422">&#x0A;UPDATE Test SET i = 1     </frame>&#x0A;    </exe

			cutionStack>&#x0A;    <inputbuf>&#x0A;BEGIN TRAN &#x0A;UPDAT
			E Test2 SET i = 1 &#x0A;WAITFOR DELAY '00:00:30' &
			#x0A;UPDATE Test SET i = 1 &#x0A;WAITFOR DELAY '00:02:0
			0' &#x0A;COMMIT &#x0A;&#x0A;DROP TABLE Test2    </input

			buf>&#x0A;   </process>&#x0A;   <process id="processfc9108"
			taskpriority="0" logused="116" waitresource="RID: 5:1:20977:
			0" waittime="6193" ownerId="374964" transactionname="user_tr
			ansaction" lasttranstarted="2007-10-21T20:59:37.917" XDES="0
			x65b2250" lockMode="U" schedulerid="2" kpid="3520" status="s
			uspended" spid="53" sbid="0" ecid="0" priority="0" transcoun
			t="2" lastbatchstarted="2007-10-21T20:59:37.917" lastbatchco
			mpleted="2007-10-21T20:59:37.853" lastattention="2007-10-21T
			20:55:28.340" clientapp="Microsoft SQL Server Management Stu
			dio - Query" hostname="POWERPC" hostpid="5808" loginname="Po
			werPC\Yan" isolationlevel="read committed (2)" xactid="37496
			4" currentdb="5" lockTimeout="4294967295" clientoption1="671
			090784" clientoption2="390200">&#x0A;    <executionStack>

			0A;     <frame procname="adhoc" line="4" stmtstart="16" sqlh
			andle="0x02000000d754ba259586cc023c12b6e68ced80a43710ab21">&
			#x0A;UPDATE [Test2] set [i] = @1     </frame>&#x0A;     <fra
			me procname="adhoc" line="4" stmtstart="128" stmtend="176" s
			qlhandle="0x02000000a3018011483afc00dc68f3e5f814c5effa45d23b
			>&#x0A;UPDATE Test2 SET i = 1     </frame>&#x0A;    </execu

			tionStack>&#x0A;    <inputbuf>&#x0A;BEGIN TRAN &#x0A;UPDATE
			Test SET i = 1 &#x0A;WAITFOR DELAY '00:00:30' �
			A;UPDATE Test2 SET i = 1 &#x0A;WAITFOR DELAY '00:02:00' 
			&#x0A;COMMIT &#x0A;&#x0A;DROP TABLE Test&#x0A;&#x0A;&#x0A;&#x0A;&#x0A;	

			</inputbuf>&#x0A;   </process>&#x0A;  </process-list>&#x0A;  <resource-
			list>&#x0A;   <ridlock fileid=1" pageid="20977" dbid="5" 
			objectname="AdventureWorks.dbo.
			Test2" id="lock4104980" mode="X" associatedObjectId="7205759
			4055229440">&#x0A;    <owner-list>&#x0A;     <owner id="proc

			essd7aa78" mode="X"></owner>&#x0A;    </owner-list>&#x0A;
			<waiter-list>&#x0A;     <waiter id="processfc9108" mode="U"
			requestType="wait"></waiter>&#x0A;    </waiter-list>&#x0A;
		  	</ridlock>&#x0A;   <ridlock fileid="1" pageid="20959" dbid

			="5" objectname="AdventureWorks.dbo.Test" id="lock4104a00" m
			ode="X" associatedObjectId="72057594055294976">&#x0A;    <ow
			ner-list>&#x0A;     <owner id="processfc9108" mode="X"></own
			Er>&#x0A;    </owner-list>&#x0A;    <waiter-list>&#x0A;
			<waiter id="processd7aa78" mode="U" requestType="wait"></wai
			Ter>&#x0A;    </waiter-list>&#x0A;   </ridlock>&#x0A;  </res

			ource-list>&#x0A; </deadlock>&#x0A;</deadlock-list>&#x0A;</T
			extData>
LoginName        	:	Sa

Spid 21 shown in the SPID property was the lock detection thread initiated by SQL Server and was run under the sa login. The XML text in the TextData property might look cryptic. However, if you examine it carefully, the first <process> tag showed you the winner in this deadlock situation - spid 54, and the login PowerPC\Yan owned this spid. The <frame> tag inside the process tag showed you the statement spid 54 was executing at the time of deadlock. The <inputbuf> tag showed you the entire input buffer from spid 54. The second <process> tag showed you the victim - spid 53. Again, the <frame> tag showed you the statement spid 53 was executing at the time of deadlock and its entire input buffer. The <resource-list> tag showed you the resources each process was holding exclusively on and the resources it was waiting for. Although only process ids, processd7aa78 and processfc9108, were included in the <resource-list> tag, you can match them easily with spid in the <process> tag.

Monitoring Blockings

The trace event class BLOCKED_PROCESS_REPORT can be used to monitor blocked processes. However, by default, this event class is disabled. You need to run sp_configure to reconfigure the blocked process threshold option. This option specifies the threshold, in seconds, at which blocked process reports are generated. For example, if you want a blocked process report to be generated for each task that is blocked for 30 seconds, run this query on the SQL Server.

sp_configure 'show advanced options', 1 
GO
RECONFIGURE
GO
sp_configure 'blocked process threshold', 30
GO
RECONFIGURE
GO

Please note that each report only contains two connections of a blocking. Unlike the DEADLOCK_GRAPH event, which shows you a deadlock chain, this event class doesn't show you the complete chain. You have to work through all the reports you gather at the same time to figure out which process is the head of the chain.

The MonitorBlockings.ps1 script, shown here, collects blocked process reports.

$query = "SELECT * FROM BLOCKED_PROCESS_REPORT"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "LoginSid","PostTime","SQLInstance","IsSystem","DatabaseID","ComputerName", `
"SessionLoginName","SPID","TransactionID","EventSequence","IndexID","ObjectID","TextData", `
"EndTime","Duration","Mode"

Get-WMIEvent $query $sqlnamespace $selections

Let's run a test. In a connection using spid 53, run this query:

CREATE TABLE Test (i int)

INSERT Test SELECT 1 
GO 
BEGIN TRAN 
UPDATE Test SET i = 1 
WAITFOR DELAY '00:01:00' 

COMMIT 

DROP TABLE Test

This spid holds exclusive locks on the Test table.

In another connection using spid 54, run this query:

UPDATE Test SET i = 1

Spid 54 is blocked by spid 53 for 1 minute. The script detects the blocking and picks up the process report.

PS > C:\ MonitorBlockings.ps1


LoginSid         	:	{1}
PostTime         	:	20071021211855.000770+000
SQLInstance      	:	MSSQLSERVER
IsSystem         	:	1
DatabaseID       	:	5
ComputerName     	:	POWERPC
SessionLoginName 	:	

SPID             	:	5
TransactionID    	:	376835
EventSequence    	:	20202
IndexID          	:	0
ObjectID         	:	1207675350
TextData         	:	<TextData><blocked-process-report monitorLoop="72730">&#x0A;
			<blocked-process>&#x0A;  <process id="processd7a898" taskpr

			iority="0" logused="0" waitresource="OBJECT: 5:1207675350:0
			" waittime="25084" ownerId="376835" transactionname="sqlsour
			ce_transform" lasttranstarted="2007-10-21T21:18:40.683" XDES
			="0x4668d50" lockMode="Sch-S" schedulerid="1" kpid="3696" st
			atus="suspended" spid="54" sbid="0" ecid="0" priority="0" tr
			anscount="0" lastbatchstarted="2007-10-21T21:18:40.683" last
			Batchcompleted="2007-10-21T21:14:59.227" lastattention="2007
			-10-21T20:55:26.197" clientapp="Microsoft SQL Server Managem
			ent Studio - Query" hostname="POWERPC" hostpid="5808" login
			ame="PowerPC\Yan" isolationlevel="read committed (2)" xactid
			="376835" currentdb="5" lockTimeout="4294967295" clientoptio
			n1="671090784" clientoption2="390200">&#x0A;   <executionSta
			ck>&#x0A;    <frame line="1" sqlhandle="0x02000000c108140729

			6ca08140bec8aa7e80cbe6b1ce3619"></frame>&#x0A;    <frame lin
			e="1" sqlhandle="0x02000000d23ece356580584d556122d374fd5800e
			6db89cc"></frame>&#x0A;   </executionStack>&#x0A;   <inputbu
			f>&#x0A;UPDATE Test SET i = 1   </inputbuf>&#x0A;  </process
			>&#x0A; </blocked-process>&#x0A; <blocking-process>&#x0A;  <

			process status="suspended" waittime="26754" spid="53" sbid="
			0" ecid="0" priority="0" transcount="2" lastbatchstarted="20
			07-10-21T21:18:38.993" lastbatchcompleted="2007-10-21T21:18:
			38.917" lastattention="2007-10-21T21:13:48.467" clientapp="M
			icrosoft SQL Server Management Studio - Query" hostname="POW
			ERPC" hostpid="5808" loginname="PowerPC\Yan" isolationlevel=
			"read committed (2)" xactid="376815" currentdb="5" lockTimeo
			ut="4294967295" clientoption1="671090784" clientoption2="390
			200">&#x0A;   <executionStack>&#x0A;    <frame line="3" stmt
			start="74" stmtend="126" sqlhandle="0x02000000e5894c26453323
			77f3e6f1dc1ede42b80ee97f18"></frame>&#x0A;   </executionStac

			k>&#x0A;   <inputbuf>&#x0A;BEGIN TRAN &#x0A;UPDATE Test SET
			i = 1 &#x0A;WAITFOR DELAY '00:01:00' &#x0A;COMMIT
			&#x0A;&#x0A;DROP TABLE Test&#x0A;&#x0A;&#x0A;&#x0A;&#x0A;&#x

			0A;   </inputbuf>&#x0A;  </process>&#x0A; </blocking-process
			>&#x0A;</blocked-process-report>&#x0A;</TextData>
EndTime          	:	20071021211905.000770+000
Duration         	:	25084000
Mode             	:	1

Similar to the deadlock graph we have seen in the last section, spid 5 shown in the SPID property was the blocking detection thread initiated by SQL Server. The XML text in the TextData property showed you the blocked process in the <blocked-process> tag, and the blocking process in the <blocking-process> tag. Each of these two tags showed you the login owned the session and the input buffer of the spid. The ObjectID property identified the ID of the resource that the waiter waited for - 1207675350. To determine the database the resource belonged to, look at the currentdb id inside the <process> tag. In this case, the currentdb id was 5, which corresponded to the AdventureWorks database. To determine the resource, run this in the AdventureWorks database.

Select * from Object_name(1207675350)

The Test table is returned. Therefore, the output showed us that spid 54 was waiting for the Test table to be released by spid 53.

by Yan Pan

Monitoring login changes and failed login attempts

As a DBA working at a financial company, I often face questions from BU on security auditing. They usually concern about unauthorized server access or malicious security exploitation. To help them meet the auditing requirements, I can create SQL Server traces using extended procedures, such as sp_trace_create and sp_trace_setevent, to monitor login events in the background. However, I am going to show you another approach to monitor login changes and failed login attempts with the WMI Provider for Server Events, which is easier and cleaner.

DDL_LOGIN_EVENTS is the DDL event class for login events. It has three child classes.

  • ALTER_LOGIN: Captures changes to properties of SQL Server logins and Windows logins.
  • CREATE_LOGIN: Captures new account creations.
  • DROP_LOGIN: Captures account deletions.

The MonitorLogins.ps1 script shown here monitors login changes.

$query = "SELECT * FROM DDL_LOGIN_EVENTS"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "__CLASS", "SID", "ObjectName", "ObjectType", "PostTime", 
	"ComputerName", `
"DefaultLanguage", "DefaultDatabase", "SPID", "LoginName", "SQLInstance", 
	"LoginType"

Get-WMIEvent $query $sqlnamespace $selections

In this script, we added a general property __CLASS to identify if a login is altered, created or dropped. This is necessary because the three child classes don't return any class-specific properties to identify the type of action, except that DROP_LOGIN returns the TSQLCommand executed to drop the login.

Let's run this query on the default instance.

CREATE LOGIN sqluser WITH PASSWORD='Welcome123' 
ALTER LOGIN sqluser WITH PASSWORD='Er34jkOio'
DROP LOGIN sqluser

As you can see, the query creates a SQL Server login sqluser, changes its password, and then drops the login. Our script MonitorLogins.ps1 captures all three login events.

PS > C:\ MonitorLogins.ps1


__CLASS         	:	CREATE_LOGIN
SID             	:	{1, 170, 39, 34...}
ObjectName      	:	Sqluser
ObjectType      	:	LOGIN
PostTime        	:	20071104214028.000507+000
ComputerName    	:	POWERPC
DefaultLanguage 	:	us_english
DefaultDatabase 	:	Master
SPID            	:	51
LoginName       	:	PowerPC\Yan
SQLInstance     	:	MSSQLSERVER
LoginType       	:	SQL Login
		
__CLASS         	:	ALTER_LOGIN
SID             	:	{1, 170, 39, 34...}
ObjectName      	:	Sqluser
ObjectType      	:	LOGIN
PostTime        	:	20071104214028.000557+000
ComputerName    	:	POWERPC
DefaultLanguage 	:	us_english
DefaultDatabase 	:	Master
SPID            	:	51
LoginName       	:	PowerPC\Yan
SQLInstance     	:	MSSQLSERVER
LoginType       	:	SQL Login
		
__CLASS         	:	DROP_LOGIN
SID             	:	{1, 170, 39, 34...}
ObjectName      	:	Sqluser
ObjectType      	:	LOGIN
PostTime        	:	20071104214028.000850+000
ComputerName    	:	POWERPC
DefaultLanguage 	:	us_english
DefaultDatabase 	:	Master
SPID            	:	51
LoginName       	:	PowerPC\Yan
SQLInstance     	:	MSSQLSERVER
LoginType       	:	SQL Login

The script prints out the type of events that happened, the login that was changed, and the login that issued the change. From the information, we can track down unplanned or malicious changes.

In addition to login changes, we also want to audit failed login attempts. The trace event class AUDIT_LOGIN_FAILED is for this purpose.  The MonitorFailedLoginAttempts.ps1 script shown here captures failed login attempts.

$query = "SELECT * FROM AUDIT_LOGIN_FAILED"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "HostName","NTUserName","SQLInstance","Success","IsSystem","RequestID", `
"DatabaseID","DatabaseName","ComputerName","SessionLoginName","SPID","NTDomainName", `
"LoginName","StartTime","ApplicationName","EventSequence","PostTime","ClientProcessID", `
"Error","TextData"

Get-WMIEvent $query $sqlnamespace $selections

Let's run a test. Open SQL Server Management Studio. Try to login as the sqluser we dropped in the last section. You should get a pop-up message like this

Look at the output from our script.

PS > C:\ MonitorFailedLoginAttempts.ps1


HostName         	:	POWERPC
NTUserName       	:	
SQLInstance      	:	MSSQLSERVER
Success          	:	0
IsSystem         	:	0
RequestID        	:	0
DatabaseID       	:	1
DatabaseName     	:	Master
ComputerName     	:	POWERPC
SessionLoginName 	:	Sqluser
SPID             	:	53
NTDomainName     	:	
LoginName        	:	Sqluser
StartTime        	:	20071104220123.000600+000
ApplicationName  	:	Microsoft SQL Server Management Studio
EventSequence    	:	1744
PostTime         	:	20071104220123.000667+000
ClientProcessID  	:	5808
Error            	:	18452
TextData         	:	Login failed for user 'sqluser'. The user is not associated
			with a trusted SQL Server connection. [CLIENT: <local machin
			e>]

The TextData property showed you the same message as in the pop-up window. The ComputerName property showed you which workstation the login was attempted from. By capturing all the failed login attempts, we can track down malicious security exploitation.

Monitoring database changes

On the server level, we need to audit database events to ensure no accidental database deletions. In a shared database environment, we also need to monitor additions of new databases in order to manage backups and disk space effectively. 

Database events are included in the DDL_SERVER_LEVEL_EVENTS class. Three child classes of this class associated with database changes are listed below. 

  • ALTER_DATABASE: Captures changes to properties of databases.
  • CREATE_DATABASE: Captures new database creations.
  • DROP_DATABASE: Captures database deletions.

There are other child classes under the DDL_SERVER_LEVEL_EVENTS class. To retrieve only events from the above three child classes, we need to use the identifier __CLASS to filter the events from the DDL_SERVER_LEVEL_EVENTS class. The sample script MonitorDatabases.ps1 is shown here.

$query = "SELECT * FROM DDL_SERVER_LEVEL_EVENTS `
WHERE __CLASS = 'CREATE_DATABASE' or __CLASS = 'ALTER_DATABASE' `
or __CLASS = 'DROP_DATABASE'"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections= "SQLInstance","PostTime","ComputerName","SPID","LoginName", `
"TSQLCommand","DatabaseName"

Get-WMIEvent $query $sqlnamespace $selections

Let's run a test. Execute this query against the default instance.

CREATE DATABASE testDB
ALTER DATABASE testDB modify file (name=testDB, size=10MB)
DROP DATABASE testDB

This script creates a testDB database, changes the size of the data file of the database, and then drops the database. The MonitorDatabases.ps1 script captures all three events.

PS > C:\MonitorDatabases.ps1


SQLInstance  	:	MSSQLSERVER
PostTime     	:	20071106215551.000750+000
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
			ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
			Options><CommandText>CREATE DATABASE testDB&#x0D;&#x0A;</Command
			Text></TSQLCommand>
DatabaseName 	:	testDB
		
SQLInstance  	:	MSSQLSERVER
PostTime     	:	20071106215552.000000+000
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
			ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
			Options><CommandText>ALTER DATABASE testDB modify file (name=tes
			tDB, size=10MB)&#x0D;&#x0A;</CommandText></TSQLCommand>
DatabaseName 	:	 testDB
		
SQLInstance  	:	MSSQLSERVER
PostTime     	:	20071106215552.000013+000
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
			ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
			Options><CommandText>DROP DATABASE testDB&#x0D;&#x0A;</CommandTe
			xt></TSQLCommand>
DatabaseName 	:	testDB

The DatabaseName property showed the database that was being changed. The TSQLCommand property showed the actual T-SQL statement that was run against the server. You can also see the details of the sessions that made the changes.

Monitoring database objects

In a development team where each developer can make their own changes to database schema, a developer might make unplanned changes and thus overwrite the work done by another developer. To ensure the change processes transparent and manageable, we should be able to track down planned and unplanned changes to minimize the risk of improper changes causing database outage. This problem magnifies itself in dealing with stored procedures since SQL Server does not keep track of the last time a stored procedure was modified and the login that made the modifications.

The DDL_PROCEDURE_EVENTS class is the event class for stored procedure events. It has three child classes.

  • ALTER_ PROCEDURE: Captures changes to properties of stored procedures.
  • CREATE_ PROCEDURE: Captures creations of new stored procedures.
  • DROP_ PROCEDURE: Captures deletions of existing stored procedures.

The MonitorStoredProcs.ps1 script shown here monitors stored procedure changes.

$query = "SELECT * FROM DDL_PROCEDURE_EVENTS WHERE DatabaseName='AdventureWorks'"
$sqlnamespace = "root\Microsoft\SqlServer\ServerEvents\MSSQLSERVER"
$selections = "SchemaName","TSQLCommand","PostTime","SQLInstance","ObjectName", `
"ObjectType","DatabaseName","ComputerName","SPID","LoginName","UserName"
 
Get-WMIEvent $query $sqlnamespace $selections

Let's run a test. Execute this query in the AdventureWorks database on the default instance.

CREATE PROCEDURE getBlockedProcessesDetails
AS 
SELECT session_id, blocking_session_id 
FROM sys.dm_exec_requests
WHERE blocking_session_id > 0
GO
 
ALTER PROCEDURE getBlockedProcessesDetails
AS
SELECT a.session_id, a.command as blocked_session_command, 
a.blocking_session_id, b.command as blocking_session_command
FROM sys.dm_exec_requests a JOIN sys.dm_exec_requests b
ON a.blocking_session_id = b.session_id
WHERE a.blocking_session_id > 0
GO
 
DROP PROCEDURE getBlockedProcessesDetails

The query first creates a stored proc called getBlockedProcessesDetails. This stored proc gets a list of blocked and blocking sessions. Then the stored proc is modified to include the T-SQL command from each sesssion. Finally, the stored proc is dropped.

The MonitorStoredProcs.ps1 script captures all three events.

PS > C:\MonitorStoredProcs.ps1
 
 
SchemaName   	:	Dbo
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
	 	 	ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
 		 	Options><CommandText>CREATE PROCEDURE getBlockedProcessesDetails
 	 		&#x0D;&#x0A;AS &#x0D;&#x0A;SELECT session_id, blocking_session_i
	 	 	d &#x0D;&#x0A;FROM sys.dm_exec_requests&#x0D;&#x0A;WHERE blockin
 		 	g_session_id > 0&#x0D;&#x0A;</CommandText></TSQLCommand>
PostTime     	:	 20071107211501.000790+000
SQLInstance  	:	 MSSQLSERVER
ObjectName   	:	 getBlockedProcessesDetails
ObjectType   	:	 PROCEDURE
DatabaseName 	:	AdventureWorks
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
UserName     	:	Dbo
 	 	 
SchemaName   	:	Dbo
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
 	 		ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
	 	 	Options><CommandText>&#x0D;&#x0A;ALTER PROCEDURE getBlockedProce
 		 	ssesDetails&#x0D;&#x0A;AS&#x0D;&#x0A;SELECT a.session_id, a.comm
 	 		and as blocked_session_command, &#x0D;&#x0A;a.blocking_session_i
	 	 	d, b.command as blocking_session_command&#x0D;&#x0A;FROM sys.dm_
 		 	exec_requests a JOIN sys.dm_exec_requests b&#x0D;&#x0A;ON a.bloc
 	 		king_session_id = b.session_id&#x0D;&#x0A;WHERE a.blocking_sessi
	 	 	on_id > 0&#x0D;&#x0A;</CommandText></TSQLCommand>
PostTime     	:	20071107211502.000173+000
SQLInstance  	:	MSSQLSERVER
ObjectName   	:	getBlockedProcessesDetails
ObjectType   	:	PROCEDURE
DatabaseName 	:	AdventureWorks
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
UserName     	:	Dbo
 	 	 
SchemaName   	:	Dbo
TSQLCommand  	:	<TSQLCommand><SetOptions ANSI_NULLS="ON" ANSI_NULL_DEFAULT="ON"
	 	 	ANSI_PADDING="ON" QUOTED_IDENTIFIER="ON" ENCRYPTED="FALSE"></Set
 		 	Options><CommandText>DROP PROCEDURE getBlockedProcessesDetails&#
 	 		x0D;&#x0A;&#x0D;&#x0A;&#x0D;&#x0A;</CommandText></TSQLCommand>
PostTime     	:	20071107211502.000450+000
SQLInstance  	:	MSSQLSERVER
ObjectName   	:	getBlockedProcessesDetails
ObjectType   	:	PROCEDURE
DatabaseName 	:	AdventureWorks
ComputerName 	:	POWERPC
SPID         	:	52
LoginName    	:	PowerPC\Yan
UserName     	:	Dbo

The ObjectName property showed which stored procedure was changed. The TSQLCommand property showed the actual T-SQL statement that was run against the database to change the stored procedure. The LoginName property showed the login that made the changes.

Conclusion

We have illustrated above the power of Windows PowerShell in conjunction with the WMI Provider for Server Events. SQL Server 2005 WMI providers have changed and improved a lot from SQL Server 2000. The providers can be very useful in your daily work as a DBA. The scripts from this series can be easily expanded to deal with more difficult tasks.

Yan Pan is certified in Microsoft database certifications, including MCTS in SQL Server 2005 and MCDBA. She has more than 5 years of experience in SQL Server administration and Analysis Server. Currently, Yan is the primary SQL Server DBA in one of the top finance companies on Wall Street.

Share:
Home
Mobile Site | Full Site
Copyright 2017 © QuinStreet Inc. All Rights Reserved