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 rootMicrosoftSqlServerServerEventsinstance_name. For a default instance, the namespace is rootMicrosoftSqlServerServerEventsMSSQLSERVER. For a named instance Instance1, the namespace is rootMicrosoftSqlServerServerEventsInstance1.
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 \PowerPCrootMicrosoftSqlServerServerEventsMSSQLSERVER. We create a System.Management.ManagementScope object to specify this namespace for monitoring.
$namespace = "\PowerPCrootMicrosoftSqlServerServerEventsMSSQLSERVER" $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 DocumentsWindowsPowerShellMicrosoft.PowerShell_profile.ps1 or %UserProfile%DocumentsWindowsPowerShellMicrosoft.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:UsersYanDocumentsWindowsPowerShellMicrosoft.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 = "rootMicrosoftSqlServerServerEventsMSSQLSERVER" $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 : PowerPCYan
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 : PowerPCYan
StartTime : 20071020113337.000563+000
ApplicationName : Microsoft SQL Server Management Studio - Query
We can see from the output, the login PowerPCYan 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 = "rootMicrosoftSqlServerServerEventsMSSQLSERVER" $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>
 <deadlock victim="processfc9
108">
 <process-list>
 <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
="PowerPCYan" isolationlevel="read committed (2)" xactid="3
74968" currentdb="5" lockTimeout="4294967295" clientoption1=
671090784 clientoption2="390200">
 <executionStack
>
 <frame procname="adhoc" line="4" stmtstart="16"
sqlhandle="0x02000000c1081407296ca08140bec8aa7e80cbe6b1ce361
9">
UPDATE [Test] set [i] = @1 </frame>
 <
frame procname="adhoc" line="4" stmtstart="130" stmtend="176
sqlhandle=0x02000000aff0ee1498c966053682b747a4a0dc11f0c21
422">
UPDATE Test SET i = 1 </frame>
 </exe
cutionStack>
 <inputbuf>
BEGIN TRAN 
UPDAT
E Test2 SET i = 1 
WAITFOR DELAY '00:00:30' &
#x0A;UPDATE Test SET i = 1 
WAITFOR DELAY '00:02:0
0' 
COMMIT 

DROP TABLE Test2 </input
buf>
 </process>
 <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
werPCYan" isolationlevel="read committed (2)" xactid="37496
4" currentdb="5" lockTimeout="4294967295" clientoption1="671
090784" clientoption2="390200">
 <executionStack>
0A; <frame procname="adhoc" line="4" stmtstart="16" sqlh
andle="0x02000000d754ba259586cc023c12b6e68ced80a43710ab21">&
#x0A;UPDATE [Test2] set [i] = @1 </frame>
 <fra
me procname="adhoc" line="4" stmtstart="128" stmtend="176" s
qlhandle="0x02000000a3018011483afc00dc68f3e5f814c5effa45d23b
>
UPDATE Test2 SET i = 1 </frame>
 </execu
tionStack>
 <inputbuf>
BEGIN TRAN 
UPDATE
Test SET i = 1 
WAITFOR DELAY '00:00:30' �
A;UPDATE Test2 SET i = 1 
WAITFOR DELAY '00:02:00'

COMMIT 

DROP TABLE Test





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

<waiter-list>
 <waiter id="processfc9108" mode="U"
requestType="wait"></waiter>
 </waiter-list>

</ridlock>
 <ridlock fileid="1" pageid="20959" dbid
="5" objectname="AdventureWorks.dbo.Test" id="lock4104a00" m
ode="X" associatedObjectId="72057594055294976">
 <ow
ner-list>
 <owner id="processfc9108" mode="X"></own
Er>
 </owner-list>
 <waiter-list>

<waiter id="processd7aa78" mode="U" requestType="wait"></wai
Ter>
 </waiter-list>
 </ridlock>
 </res
ource-list>
 </deadlock>
</deadlock-list>
</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 PowerPCYan 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 = "rootMicrosoftSqlServerServerEventsMSSQLSERVER" $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">

<blocked-process>
 <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="PowerPCYan" isolationlevel="read committed (2)" xactid
="376835" currentdb="5" lockTimeout="4294967295" clientoptio
n1="671090784" clientoption2="390200">
 <executionSta
ck>
 <frame line="1" sqlhandle="0x02000000c108140729
6ca08140bec8aa7e80cbe6b1ce3619"></frame>
 <frame lin
e="1" sqlhandle="0x02000000d23ece356580584d556122d374fd5800e
6db89cc"></frame>
 </executionStack>
 <inputbu
f>
UPDATE Test SET i = 1 </inputbuf>
 </process
>
 </blocked-process>
 <blocking-process>
 <
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="PowerPCYan" isolationlevel=
"read committed (2)" xactid="376815" currentdb="5" lockTimeo
ut="4294967295" clientoption1="671090784" clientoption2="390
200">
 <executionStack>
 <frame line="3" stmt
start="74" stmtend="126" sqlhandle="0x02000000e5894c26453323
77f3e6f1dc1ede42b80ee97f18"></frame>
 </executionStac
k>
 <inputbuf>
BEGIN TRAN 
UPDATE Test SET
i = 1 
WAITFOR DELAY '00:01:00' 
COMMIT


DROP TABLE Test




&#x
0A; </inputbuf>
 </process>
 </blocking-process
>
</blocked-process-report>
</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.
