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>
 <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
="PowerPC\Yan" 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
werPC\Yan" 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 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">

<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="PowerPC\Yan" 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="PowerPC\Yan" 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.