Search results for 'app:weblogs' matching tags 'WMI', 'scripting techniques', and 'performance'

Weekend Scripter: Measure the Performance of Using Wildcards in a WMI Query

Anonymous — Sat, 21 Jul 2012 05:00:00 GMT

Summary: Learn how to use the Windows PowerShell Measure-Command cmdlet to determine the performance of wildcard queries using WMI.

Microsoft Scripting Guy, Ed Wilson, is here. It is the weekend in Charlotte, North Carolina, and tomorrow I fly to Seattle, Washington where I speak at the Microsoft-only TechReady 15 conference. It is a great event, and I always have fun getting to see a lot of friends from all over the world. TechReady is a very international event, and it is the one time when Microsoftees have a chance to get together. Because the conference is held twice a year, it provides a chance for people to come to one session or the other, and for Microsoft to still be able to carry on with its normal activities.

This week, I had an idea based on a comment posted to one of my WMI articles, “What is the difference in performance between using the equality operator or using a wildcard character and the Like operator, when making a WMI query?” So I thought I would test it out.

Methodology

To measure the performance of different queries, the basic tool is the Measure-Command cmdlet. Because of potential caching issues, I reboot after each query. But before I do all that, I want to ensure that my WMI queries are working properly. For that, I do not need to reboot between commands. In addition, I want to ensure that my Measure-Command commands are working properly. So for that, I also test the commands. I ended up configuring three different query patterns. The patterns are listed here:

Use the equality operator.
Use the like operator and a wildcard character.
Use the like operator and multiple wildcard characters.

When I am certain that my queries and Measure-Command commands work properly, it is time to begin the multiple reboot process.

Using the equality operator to find a process

My laptop is back up from the first reboot. As a baseline, I query for the explorer.exe process by using the equality operator. My expectations are that this will be the fastest query because it looks through all the processes and I am using the Name property to find the specific process. This is a non-indexed operation because the key to the Win32_Process class is handle and not the Name property. Here is the basic query.

Get-WmiObject -Class win32_process -Filter "name = 'explorer.exe'"

The command to measure the performance of the WMI query is shown here.

measure-command {Get-WmiObject -Class win32_process -Filter "name = 'explorer.exe'"}

So what are the results from the Measure-Command? They are shown here.

PS C:\> measure-command {Get-WmiObject -Class win32_process -Filter "name = 'explorer.exe'"}

Days : 0

Hours : 0

Minutes : 0

Seconds : 0

Milliseconds : 351

Ticks : 3514032

TotalDays : 4.06716666666667E-06

TotalHours : 9.7612E-05

TotalMinutes : 0.00585672

TotalSeconds : 0.3514032

TotalMilliseconds : 351.4032

Using the Like operator and a wildcard to find a process

Now as a point of comparison, I use the percentage symbol ( % ), which is a wildcard character in WMI WQL that means zero or more instances of a character.

Get-WmiObject -Class win32_process -Filter "name LIKE 'explorer%'"

The command to measure the performance of the WMI wildcard query is shown here.

measure-command {Get-WmiObject -Class win32_process -Filter "name LIKE 'explorer%'"}

As I come out of my second reboot, I once again open the Windows PowerShell console and run the first of my wildcard comparison commands. The command and associated output are shown here.

PS C:\> measure-command {Get-WmiObject -Class win32_process -Filter "name LIKE 'explorer%'"}

Days : 0

Hours : 0

Minutes : 0

Seconds : 0

Milliseconds : 429

Ticks : 4298977

TotalDays : 4.97566782407407E-06

TotalHours : 0.000119416027777778

TotalMinutes : 0.00716496166666667

TotalSeconds : 0.4298977

TotalMilliseconds : 429.8977

Use the Like operator and multiple wildcards to find a process

Does the amount and type of wildcard characters make any difference? I would suspect it would; but then, one never really knows. So here is a wildcard pattern that uses a range of letters, a single letter, and the zero or more letters character.

Get-WmiObject -Class win32_process -Filter "name LIKE '[A-F]xplo_er%'"

measure-command {Get-WmiObject -Class win32_process -Filter "name LIKE '[A-F]xplo_er%'"}

Now, I have completed my last reboot. It is time to see if there is a difference using the “wilder” wildcard pattern. The command and associated output appears here.

PS C:\Users\administrator> measure-command {Get-WmiObject -Class win32_process -Filter "name LIKE '[A-F]xplo_er%'"}

Days : 0

Hours : 0

Minutes : 0

Seconds : 0

Milliseconds : 339

Ticks : 3391294

TotalDays : 3.9251087962963E-06

TotalHours : 9.42026111111111E-05

TotalMinutes : 0.00565215666666667

TotalSeconds : 0.3391294

TotalMilliseconds : 339.1294

Conclusions

Drawing conclusions from this little experiment is a little dangerous. The reason is that the Measure-Command cmdlet is not really accurate when it comes to measuring millisecond results. Therefore, making a hard and fast conclusion based upon millisecond results is not a best practice. Nevertheless, as a way of summarizing the results, following is a comparison table.

The equality operator found the information and returned results in 351 milliseconds, and that was faster than using the Like operator with a single wildcard. If the results had remained like that, I would have said, “Cool, it proves my point.” However, the Like operator with multiple wildcards returned in 339 milliseconds, and that is completely counter intuitive. Therefore, additional testing is indicated. To prove the point, the results need to take multiple seconds to return so we move into the area that is more accurate for the Measure-Command. At this stage of my testing, I would have to say, there is no difference between using the equality operator and using one or more wildcards. The following table illustrates the results.

Test	Time in Milliseconds
Equality operator	351
Like operator with single wildcard	429
Like operator with multiple wildcards	339

I invite you to follow me on Twitter and Facebook. If you have any questions, send email to me at scripter@microsoft.com, or post your questions on the Official Scripting Guys Forum. See you tomorrow. Until then, peace.

Ed Wilson, Microsoft Scripting Guy

Parse Windows Trace Logs by Using PowerShell

Anonymous — Tue, 12 Jul 2011 05:00:00 GMT

Summary: Learn how to use Windows PowerShell to parse Windows trace logs.

Hey, Scripting Guy! Is it possible to filter the results from an ETW log?

—DK

Hello DK,

Microsoft Scripting Guy Ed Wilson here. Sure there is.

In Saturday’s Weekend Scripter article, I talked about working with Event Tracing for Windows (ETW) logs. I discussed how to enable and disable the logs, and how to use the Get-WinEvent cmdlet to find and to read the trace. Yesterday, I continued the ETW discussion by examining the datetime stamp that is generated for each event.

In this article, I will continue exploring the WMI activity trace log. By way of a quick review, the first thing I need to remember is to use the force parameter when searching for trace logs—it will not be visible otherwise. I also should remember that I do not need to type the entire log name because I can use wildcard characters to assist. After I have found the proper log name, I can store the log name in a variable for quick access. When reading a trace log, I must remember to use the Oldest switched parameter. The commands that follow illustrate these techniques.

Get-WinEvent -ListLog *wmi*trace* -force

(Get-WinEvent -ListLog *wmi*trace* -force).logname

$WmiLog = (Get-WinEvent -ListLog *wmi*trace* -force).logname

Get-WinEvent -LogName $wmiLog -Oldest

To parse a trace log, you monkey around with the message portion of the trace log entry. This means that any of the parse text type of articles, or regular expression type of articles will be extremely useful when it comes to examining these logs. I am not going to repeat all that type of information here.

After I have the reference to the WMI trace log stored in the $wmiLog variable, I use it in my query to the Get-WinEvent cmdlet. The command returns all the entries (remember the Oldest switched parameter is required in these types of queries). I pipe the resulting trace log contents to the Where-Object cmdlet (? Is an alias for the Where-Object cmdlet), and I look for entries that contain the word execquery, which is one of the commands used by WMI when performing a query. I use the Select-Object cmdlet (select is an alias for the Select-Object cmdlet) to choose only the message property, and I expand the property so I can see all the information contained in the particular entry. The command (broken into two lines at the pipe character for clarity) and associated output are shown here:

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'execquery' } | select -ExpandProperty message

GroupOperationId = 486; OperationId = 487; Operation = Start IWbemServices::Exe

cQuery - select * from win32_bios; ClientMachine = NEWMRED; User = IAMMRED\Admi

nistrator; ClientProcessId = 4392; NamespaceName = \\.\root\cimv2

I like this view because it makes it rather easy to look at related entries. It is much faster than clicking entries in Event Viewer. In the entry above, the WMI query, namespace, computer name, and username all appear in the entry. This makes it easy to troubleshoot WMI failures.

If I have a trace log with a large number of entries (even a large number of entries that may match my query), I add a more command to the end of the command. The revised command appears here (I break the command at the pipe character for display on the blog; I do not break the command inside the Windows PowerShell console):

Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match 'execquery' } |

select -ExpandProperty message | more

Rather than using the Select-Object cmdlet, at times I like to use the Format-Table cmdlet (ft is an alias for the Format-Table cmdlet) with the wrap switched parameter. This is particularly true if I want to use two or more properties. (I will use Format-Table for 2–5 properties. If I have more than 5 properties, I generally use Format-List). In the following query, I query the WMI trace log and look for entries that have the word reference in the message property. The word reference appears in referencesof types of WMI queries. In general, these referencesof types of queries are used by WMI in preparation for performing the actual Select command (although, it is perfectly valid—if advanced—for a user to write a referencesof type of query directly). All of the matching entries from the logs are then displayed in a table with the ID in the first position, and the message wrapped for readability. The autosize switched parameter tightens up the display and makes for better output. The command and associated output are shown here.

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'reference' } | ft id, message -Wrap -AutoSize

Id Message

1 GroupOperationId = 490; OperationId = 494; Operation = Start IWbemServices::

ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

= \\.\root\CIMV2

1 GroupOperationId = 490; OperationId = 496; Operation = Start IWbemServices::

ExecQuery - references of {__Win32Provider.Name="CIMWin32"}; ClientMachine =

Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName = \

\.\root\CIMV2

1 GroupOperationId = 490; OperationId = 498; Operation = Start IWbemServices::

ExecQuery - references of {__Win32Provider.Name="CIMWin32"}; ClientMachine =

Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName = \

\.\root\CIMV2

1 GroupOperationId = 501; OperationId = 504; Operation = Start IWbemServices::

ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

= \\.\root\CIMV2

1 GroupOperationId = 501; OperationId = 506; Operation = Start IWbemServices::

ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

= \\.\root\CIMV2

When troubleshooting WMI, one of my favorite techniques is to search the trace log for the specific WMI class name. This allows me to trace the operations related to a particular search or WMI query. As shown in the query and results below, the WMI provider for a specific class must be located before executing the actual Select * win32_bios WMI query:

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'win32_bios' } | ft id, message -Wrap -AutoSize

Id Message

1 GroupOperationId = 490; OperationId = 491; Operation = Start IWbemServices::

ExecQuery - select * from win32_bios; ClientMachine = NEWMRED; User = IAMMRE

D\Administrator; ClientProcessId = 4392; NamespaceName = \\.\root\cimv2

2 ProviderInfo for GroupOperationId = 490; Operation = Provider::CreateInstanc

eEnum - Win32_BIOS; ProviderName = CIMWin32; ProviderGuid = {d63a5850-8f16-1

1cf-9f47-00aa00bf345c}; Path = %systemroot%\system32\wbem\cimwin32.dll

1 GroupOperationId = 490; OperationId = 499; Operation = Start IWbemServices::

GetObject - win32_bios; ClientMachine = Local; User = IAMMRED\Administrator;

ClientProcessId = 0; NamespaceName = \\.\root\CIMV2

The two-column output from the previous command is pretty decent from a readability perspective. As discussed in yesterday’s Hey Scripting Guy! Blog post, the ETW log provider is such a high performer that many entries have exactly the same time stamp (down to the tick); therefore, filtering (or even displaying) the time stamp does little to aid understanding. This is illustrated in the following output (where I add the time stamp to the previous output):

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match 'win32_bio

s' } | ft TimeCreated, id, message -Wrap -AutoSize

TimeCreated Id Message

7/11/2011 3:23:47 PM 1 GroupOperationId = 490; OperationId = 491; Operation =

Start IWbemServices::ExecQuery - select * from win32_bi

os; ClientMachine = NEWMRED; User = IAMMRED\Administrat

or; ClientProcessId = 4392; NamespaceName = \\.\root\ci

mv2

7/11/2011 3:23:47 PM 2 ProviderInfo for GroupOperationId = 490; Operation = Pr

ovider::CreateInstanceEnum - Win32_BIOS; ProviderName =

CIMWin32; ProviderGuid = {d63a5850-8f16-11cf-9f47-00aa

00bf345c}; Path = %systemroot%\system32\wbem\cimwin32.d

7/11/2011 3:23:47 PM 1 GroupOperationId = 490; OperationId = 499; Operation =

Start IWbemServices::GetObject - win32_bios; ClientMach

ine = Local; User = IAMMRED\Administrator; ClientProces

sId = 0; NamespaceName = \\.\root\CIMV2

As is shown in the previous output, all three entries happened at the same time, so the time stamp does not improve output (in fact, it reduces readability by causing additional wrapping of the message output).

DK, that is all there is to using the Get-WinEvent cmdlet to parse WMI activity/trace logs. I encourage you to take some time to review the last couple of articles as well as this one, and play around with querying the message property. After all, you know what you need to find. Troubleshooting Windows Week will continue tomorrow when I will show you a really cool technique for automating the enabling and disabling of trace logs. Stay tuned: same batch time, same batch channel.

Ed Wilson, Microsoft Scripting Guy

Use Date Types to Filter Event Trace Logs in PowerShell

Anonymous — Mon, 11 Jul 2011 05:00:00 GMT

Summary: Learn how to use date types to filter event trace logs in Windows PowerShell.

Hey, Scripting Guy! I am wondering, oh great scripting master: can I use Windows PowerShell to parse an ETW log file?

—JM

Hello JM,

Microsoft Scripting Guy Ed Wilson here. It is “oh dark thirty” in the Piedmont region of the United States. For some reason, I woke up early. It is Thursday as I write this article, and the Scripting Wife and I were up late last night listening to the PowerScripting Podcast. I thought Spencer Brown did a great job as the guest, and as usual, Hal Rottenberg was in top form as he played the suave and debonair talk show host. Jonathan Walz was grooving in the background—audiophile extraordinaire. The Scripting Wife loves the chat room conversation because it gives her a chance to hang out with her friends from all over the world. Anyway, because I was up late, and then again up early, I decided it would make for a great excuse to have a coffee day. My last coffee day occurred back in January when I was talking about scheduling Windows PowerShell scripts that require input values.

Anyway, JM, the “standard answer” is that Windows PowerShell can do anything. The other day on Twitter, someone asked if Windows PowerShell could be made to mow the grass. I believe it could be (here is a cool article about using Windows PowerShell to control robots). Now all you need is a robot lawn mower.

The first thing to do is to obtain the name of the log and to store it in a variable. I do this because it makes working interactively from the Windows PowerShell line easier to do. The actual log name I want to work with today is Microsoft-Windows-WMI-Activity/Trace. I can find the log name from one of the trace entries when I look in Event Viewer. Such an entry appears in the following figure.

After I have the log name stored in a variable, I can use the Get-WinEvent cmdlet to retrieve the message property (or other properties as appropriate). The following two commands store the Microsoft-Windows-WMI-Activity/Trace log name in a variable, and return the message property from each of the entries in the WMI Activity trace ETW log:

$wmiLog = (Get-WinEvent -ListLog *wmi*trace -force).logname

Get-WinEvent -LogName $wmilog -Oldest | select message

The two commands and associated output are shown in the following figure.

In the previous figure, the output of the message property appears truncated. At times, a truncated output provides enough information to allow for quick identification of a particular problem. In the case of the above output, there is not enough detailed information to allow for much exploration. The solution is to expand the message property. To expand the message property, use the expandproperty property from the Select-Object cmdlet. Here is the syntax of this command:

Get-WinEvent -LogName $wmilog -Oldest | select -ExpandProperty message

The command and associated output are shown in the following figure.

In attempting to work with individual event entries, it would be logical to use the date timestamp in a filter. I therefore take the time, cast it to a system.datetime object, and use it with a Where-Object filter. Unfortunately, no records are returned from the query. The two commands are shown here:

$date = [datetime]"7/6/2011 6:03:51 PM"

Get-WinEvent -LogName $wmilog -Oldest | where-object { $_.timecreated -eq $date }

If I change the operator from equals to greater than, the command produces output. The revised command and associated output are shown here (the ? character is an alias for Where-Object).

PS C:\> Get-WinEvent -LogName $wmilog -Oldest | ? { $_.timecreated -gt $date }

TimeCreated ProviderName Id Message

7/6/2011 6:03:51 PM Microsoft-Window... 1 GroupOperationId...

7/6/2011 6:03:51 PM Microsoft-Window... 3 Stop OperationId...