Search results for 'app:weblogs' matching tags 'troubleshooting' and 'performance'

Use PowerShell to Troubleshoot Software Installation

Anonymous — Wed, 13 Jul 2011 05:00:00 GMT

Summary: Use Windows PowerShell to troubleshoot software installation.

Hey, Scripting Guy! I am having a problem troubleshooting the installation of an MSI package. I am using Group Policy to deploy the MSI package, and on some computers, it seems to work, but on other computers it fails. After having read your most recent series of articles about troubleshooting Windows, I thought I could use a trace log, but after spending more than an hour trying to click all of those little folders (why is there no search on the log name?), I could not find a trace log that seemed to make sense. Anyway, I guess I am asking you how to troubleshoot remote installation of a MSI package. Hope you can help.

—LT

Hello LT,

Microsoft Scripting Guy Ed Wilson here. This morning, the Scripting Wife and I got to do something we have been looking forward to for nearly two months. When we were at Tech∙Ed 2011 in Atlanta, we got to meet a couple of scripters that work for a company that has a headquarters in the Charlotte area. We exchanged email, and this morning the Scripting Wife and I went to their office and made a three-hour “Introduction to Windows PowerShell” presentation. It was a lot of fun. One of the questions they had was related to troubleshooting remote systems.

LT, you are not alone in your queries. In addition to the customer I was talking to this morning, there was also a comment on Monday’s blog post from Klaus Schulte (winner of the Beginner division of the 2011 Scripting Games) asking about troubleshooting installation packages.

LT, there is a search for trace logs. It is called Windows PowerShell. I have given up attempting to navigate through the hundreds of logs in all the different folders (there are 492 logs on my Windows 7 Ultimate workstation). Instead, if I am searching for a log related to something, I use Windows PowerShell.

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. Monday, I continued the ETW discussion by examining the datetime stamp that is generated for each event. Yesterday, I explored parsing the message property of the WMI Activity Trace log.

If I do not supply a value to the listlog parameter, an error appears. If I provide the name of a specific log, certain information about the log returns. If I use the * wildcard character, information about every log on the system is displayed in the Windows PowerShell console. If I use a more comprehensive wildcard character pattern, I can limit the number of logs that return. An example of searching for trace logs that relate to install is shown here:

PS C:\Windows\system32> Get-WinEvent -ListLog *install* -force | select logname

LogName

-------

Microsoft-Windows-AxInstallService/Log

Microsoft-Windows-WPD-ClassInstaller/Analytic

Microsoft-Windows-WPD-ClassInstaller/Operational

I can use the same technique to search for logs that relate to msi. In the following output, only one log relates to MSI, but it is associated with AppLocker. Therefore, it will not pick up any trace information from a generic MSI installation:

PS C:\Windows\system32> Get-WinEvent -ListLog *msi* -force | select logname

LogName

-------

Microsoft-Windows-AppLocker/MSI and Script

At times, either I cannot find a trace log that I like, or I grow impatient from the search and then use one of my favorite tricks: query all the logs at once. Sure, it is inefficient, but if I am working locally, it is not a big deal. However, it can take a very long time for the command to complete (on my workstation, it takes nearly four minutes to complete the command). The thing to keep in mind is that after the first portion of time—it might be seconds or a minute or so depending on how much data you are returning and how recent your time filter is—new information will no longer be returned to the screen. This is the time when the command is continuing to process log files, but there is no longer any data to return even though the filter coming after the command to return all the event logs is still working. The (inefficient) command to return log files that have a timestamp that occurs later than "7/11/11 10:35:08 pm" follows this paragraph. To make the information display a bit better, I send the information to a table. In the following command the Get-WinEvent cmdlet returns all information from all log files. The returned entries are piped to the Where-Object cmdlet (? Is an alias for the Where-Object cmdlet), which filters log entries after a specific time. The results are piped to the Format-Table cmdlet (ft is an alias for Format-Table cmdlet), and three properties are selected. The command is shown here:

Get-WinEvent | ? {$_.TimeCreated -gt "7/11/11 10:35:08 pm" } | ft logname, id, message

The following figure illustrates running the command in the Windows PowerShell ISE and displays the associated output.

If I want to tighten up the output and create a more efficient use of the space in my output pane in the Windows PowerShell ISE, I can add the autosize parameter to the Format-Table cmdlet. In addition, I can display the entire message if I use the wrap parameter. However, when I add these parameters to the previous command, it will take the most of the time (five minutes or so) the command runs before displaying output. This is because to calculate the amount of space to allocate for the columns, Windows PowerShell needs to look at all of the data. This reduces the efficiency of the streaming behavior that I took advantage of earlier. The revised command is shown here:

Get-WinEvent | ? {$_.TimeCreated -gt "7/11/11 10:35:08 pm" } | ft logname, id, message -AutoSize –wrap

Clearly, a more efficient method of working with log files is required.

For more information about using the FilterHashTable parameter, see Use a PowerShell Cmdlet to Filter Event Log for Easy Parsing and Use PowerShell to Parse Saved Event Logs for Errors. For more information about improving the performance of event log queries, see How to Improve the Performance of a PowerShell Event Log Query. For issues surrounding working remotely with Windows Vista and Windows XP event logs, refer to Discover How to Filter Remote Event Log Entries in Windows Vista.

The following table is copied from my Use PowerShell to Parse Saved Event Logs for Errors Hey, Scripting Guy! Blog post from January 2011.

Event Log Viewer name	FilterHashTable parameter key name
Log Name	LogName
Source	ProviderName
Event ID	ID
Level	Level
User	UserID
Op Code	*
Logged	*
Task Category	*
Keywords	*
Computer	N/A use –ComputerName parameter
Details	Data

If I attempt to use my trick of using the Get-Winevent cmdlet to list all log entries, and I use a FilterHashTable to attempt to filter based on time at the Get-Winevent cmdlet instead of on the other side of the pipeline, an error returns that states I must specify either a log, provider, or path. The command and associated error appear here:

PS C:\Windows\system32> Get-WinEvent -FilterHashTable @{StartTime = "7/11/11 10:35:08 pm"}

Get-WinEvent : You must specify at least one Log, Provider or Path key-value pair.

At line:1 char:13

+ Get-WinEvent <<<< -FilterHashTable @{StartTime = "7/11/11 10:35:08 pm"}

+ CategoryInfo : InvalidArgument: (:) [Get-WinEvent], Exception

+ FullyQualifiedErrorId : LogProviderOrPathNeeded,Microsoft.PowerShell.Commands.GetWinEventCommand

I decide to modify the command to use a wildcard character for the logname key for the FilterHashTable. The command works great and returns data nearly immediately:

Get-WinEvent -FilterHashtable @{StartTime = "7/11/11 10:35:08 pm"; LogName = "*"}

The nice thing about the above command is it returns information from multiple logs and multiple providers. This is useful, for example, when troubleshooting installation problems that may be unrelated to the actual installer. To check a specific installation, it may be useful to filter based on not only the time, but also on the provider. For MSI installed software, the provider is the msiInstaller provider. The following command is broken at the pipe character for readability purposes. In reality it is a single command:

Get-WinEvent -FilterHashtable @{StartTime = "7/11/11 10:35:08 pm"; ProviderName = "msiInstaller"} |

ft logname, id, message -AutoSize –wrap

The command and associated output appear in the following figure.

LT, that is all there is to using Windows PowerShell to look at Windows Installer logging. Troubleshooting Windows week will continue tomorrow.

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...