How to Improve the Performance of a PowerShell Event Log Query

How to Improve the Performance of a PowerShell Event Log Query

  • Comments 3
  • Likes

Summary: Learn how to improve the performance of a Windows PowerShell event log query.

Hey, Scripting Guy! Question Hey, Scripting Guy! I am a beginner when it comes to using Windows PowerShell, and I was inspired by your article yesterday about using Windows PowerShell to Query All Event Logs for Recent Events, and today I attempted to write a command to get all of the events generated by LANDESK in the application event log.

Here is the code I put together.

Get-WinEvent -Logname Application -EA silentlycontinue |

where-object { $_.providername.ToLower().contains("landesk") -AND $_.timecreated -gt [datetime]::today}

The code appears to work well, but it is very slow and CPU intensive. Am I missing something?

—MZ

Hey, Scripting Guy! AnswerHello MZ,

Microsoft Scripting Guy, Ed Wilson, here. It has been a really long time since I have had anything to do with the LANDESK product; therefore, I do not have it installed on my computer. However, that does not really matter, because what you are talking about is attempting to speed up the results of a query. I have talked about measuring the speed of Windows PowerShell commands in the past. In fact, it is one of my favorite topics.

The first thing I need to do is to obtain a baseline of query performance. As I mentioned earlier, I do not have LANDESK installed on my computer; therefore, I decided to query for events related to WMI. An example of such an event is shown here.

Image of Event Viewer

The command that I derived is very much like yours—in fact, it is identical, except for the name of the provider.

Get-WinEvent -LogName application -ea SilentlyContinue |

Where-Object { $_.providername.ToLower().Contains('wmi') -AND

$_.TimeCreated -gt [datetime]::today }

To measure the performance of the command, I use the Measure-Command Windows PowerShell cmdlet. It accepts a parameter called Expression which is where the Windows PowerShell command is placed. The command that is shown here is the command to time the Get-WinEvent command listed previously.

Measure-Command -Expression {

Get-WinEvent -LogName application -ea SilentlyContinue |

Where-Object { $_.providername.ToLower().Contains('wmi') -AND

$_.TimeCreated -gt [datetime]::today }

}

When I am working with commands that use more than one or two lines in the Windows PowerShell console, I tend to use the Windows PowerShell ISE because it makes it easier to keep track of the commands, and it makes it easier to modify those commands. The command and its associated output are shown in the following image.

Image of command output

On my computer, the previous command completes in just a little more than 21 seconds. In reality, that is not too horribly bad. After all, the application log on my computer consumes 20 megabytes of disk space, and it contains 21810 entries. I found the size by looking at the event log properties in the Event Viewer. I determined the number of entries in the log by using the Measure-Object cmdlet as shown here.

PS C:\> Get-WinEvent -LogName application | Measure-Object

Count : 21810

Average :

Sum :

Maximum :

Minimum :

Property :

MZ, I noticed that you posted a comment on yesterday’s Hey Scripting Guy! blog in addition to sending an email message to the scripter@microsoft.com alias. Bartek, one of our readers, suggested you were working too hard, and offered a revision to your command. I think it will be fun to test his revision, and see what happens. Here is the command with the modifications suggested by Bartek.

Measure-Command -Expression {

Get-WinEvent -LogName application -ea 0 |

Where-Object { $_.providername -match 'wmi' -AND

$_.TimeCreated -gt [datetime]::today }

}

The first change Bartek made was to change –ea SilentlyContinue to –ea 0. As it turns out, 0 is the enumeration value for SilentlyContinue. I found that out by using the Get-EnumAndValues.ps1 script from my Enumerations and Values Weekend Scripter article. The other enumerations and values from the "System.Management.Automation.ActionPreference" enumeration are shown here.

Name Value

---- -----

Inquire 3

Continue 2

Stop 1

SilentlyContinue 0

The next change he made was to remove tolower and contains from your query, and replace them with the –match operator. The resultant clause is shown here.

$_.providername -match 'wmi'

On my computer, when I measured the performance of the revised command, the results were a little more than 21 seconds. This is shown in the following image.

Image of command output

Bartek is correct MZ, you are doing too much work. As you can see, there was no advantage to converting to all lowercase and using the contains method.

The first thing I want to do is to quit searching for the provider and replace it with the proper provider name. I use the following command to find the WMI provider name.

PS C:\> (get-winevent -listlog Application).providernames | where { $_ -match 'wmi'}

WMI.NET Provider Extension

Microsoft-Windows-WMI

When I search for event log providers that match the string 'wmi', I found that there are two providers. I assumed that there was only one match, when there were actually two matches. This could skew the accuracy of my queries. I think I really want the Microsoft-Windows-WMI provider, but I check the event log in Event Viewer to be sure. This is illustrated in the following image.

Image of Event Viewer

Now that I know the provider name, I can use it directly with the Get-WinEvent cmdlet. The first thing to remember is that I cannot use the ProviderName parameter and the LogName parameter in the same command. It seems like a major limitation; but in reality, it is not. This is because an event log provider can only be registered with one event log. The revised command and associated output are shown here.

PS C:\Users\ed.NWTRADERS> Get-WinEvent -ea SilentlyContinue `

-ProviderName "Microsoft-Windows-WMI"|

Where-Object { $_.TimeCreated -gt [datetime]::today }

TimeCreated ProviderName Id Message

----------- ------------ -- -------

3/7/2011 6:42:46 AM Microsoft-Windows-WMI 5617 Windows Management In...

3/7/2011 6:42:46 AM Microsoft-Windows-WMI 5615 Windows Management In...

Just watching the command run, I could see that there was a significant improvement in speed. In fact, the results took less than a second. The modification and the output are shown here.

Image of command output

The big reason for the big performance improvement is reducing the number of event log entries that are identified by the Get-WinEvent cmdlet prior to shipping the events over the pipeline to be filtered by the Where-Object cmdlet. It is always faster to filter before sending to the Where-Object than to filter afterwards.

It is possible to remove the Where-Object cmdlet completely. To do this requires using the FilterHashTable parameter. The hash table will let you filter on LogName, ProviderName, Path, Keywords, Id, Level, StartTime, EndTime, and UserId. For more information about using FilterHashTable, see the Use a PowerShell Cmdlet to Filter Event Log for Easy Parsing Hey! Scripting Guy article.

In using the FilterHashTable parameter, I am able to completely remove the Where-Object cmdlet. The revised command is shown here.

Get-WinEvent -ea SilentlyContinue `

-FilterHashtable @{ProviderName= "Microsoft-Windows-WMI";

LogName = "application"; StartTime = [datetime]::today}

When I run the command, it returns quickly. To see how quickly, I added it to the Measure-Command command as shown here.

Measure-Command -Expression {

Get-WinEvent -ea SilentlyContinue `

-FilterHashtable @{ProviderName= "Microsoft-Windows-WMI";

LogName = "application"; StartTime = [datetime]::today}

}

On my system, this command results in only a slight improvement over the previous command. This is shown in the following image.

Image of command output

MZ, that is all there is to using Get-WinEvent parameters and the Measure-Command cmdlet to improve query performance. I invite you to join me tomorrow for more Windows PowerShell goodness.

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

Your comment has been posted.   Close
Thank you, your comment requires moderation so it may take a while to appear.   Close
Leave a Comment
  • I had the same reaction as Bartek that $_.providername.ToLower().Contains('wmi') is just "wrong" , and "must" be less efficient than using -match. And since -MATCH uses regular expression, it "must"  be less efficient than using -LIKE "*wmi*" . A quick test showed they were all pretty much the same. "MUST" indeed! Another optimisation - replacing the work of finding the date by putting [datetime]::today into a variable and using that instead also gives no noticable improvement.

    Using the example above I had roughly 23 seconds worth of WMI events to process, none of which came from today. So when I ran it with  both WHERE conditions it gave me no results at all. This led to a new test: if I get no results, then how much more quickly do things run if I just write WHERE {$false}. It saved about 1 second.

    Using WHERE is great at the command line - especially when you're working with a type of object you are not very familiar with. But this example shows very well that when you move something to being a production script, (or if you filter the same type of object in lots of commands) you should investigate how their GET-  command can apply a filter it's different for events , WMI Objects, Processes, Files etc.  

    I hesitate to give examples which use -MATCH in the way it is used here for fear that someone will enter something which means something that they hadn't intended to regex parser.

    I'd also be very cautious about writing a script with -ea 0 in it, because that's not readable. Great for least keystrokes typing in the shell, from the PoV of being self documenting, not so much.

    -ErrorAction [Management.Automation.ActionPreference]::SilentlyContinue  

    gives the most information, but probably doesn't add any more to understanding than just writing SilentlyContinue. (You can discover the enum type with $errorActionPreference | get-member)

  • Oh one more thing. I always want to find out how long a command took to run after I've run it. I found the information was in the history, so I put this quick and dirty function into my profle

    function howLongWasthat {(get-history ($MyInvocation.HistoryId -1)).endexecutiontime.subtract((get-history ($MyInvocation.HistoryId -1)).startexecutiontime).totalseconds}

    So now I just type howl [tab] to find out.

  • in security event log many events with Event ID 4688 won't be applications started by the user. Most of these events are generated by background processes and services .how can we differ these events?