Monday, April 8, 2013

Most efficient remote event log query

Recently I wanted to go through and modernize an old method I had come up for checking last patch install dates on a remote windows machine. In the past, I had done some OS identification to determine if the system was <=2003 or >=vista, then performed an appropriate WMI query against the system log to find events of the correct event ID and source. This method is fine, but I started thinking of the other methodologies that are available with powershell, so I wanted to play around with Get-Winevent to see how they all worked. Basically I broke down event log filtering into 3 possibilities: 1) Xpath filter, 2) Filter hashtable, 3) pipe to |where. The results were interesting between methods #1 and #2, #3 was expected. I know there are a lot of beginner examples for #3 for people who just love pipelining, but when dealing with eventlogs, this is not good. Get-winevent with no parameters will dump all events from all eventlogs, which even running locally is horrible, therefore running on a remote machine is a no-no.


Lets look at the baseline old WMI style query that will get our desired results:


Get-WmiObject -query "Select timewritten from win32_ntlogevent where logfile='system' and sourcename='Microsoft-Windows-WindowsUpdateClient' and eventcode=19" -computername ServerA|select -first 1 -Property timewritten
TotalMinutes      : 0.460832901666667
TotalSeconds      : 27.6499741
TotalMilliseconds : 27649.9741

Here we have 3 criteria in a where statement which helps with the run time. When doing WMI filtering on a remote machine for event logs, you can get quite fast results with a really tight query (especially if you can restrict the timeframe you are looking at). Our result was 27 sec on a machine that has a 250ms response time. The one problem with this method is it will pull all of the records for this event type, even though we are just looking for the most recent.


Next, we have our first two methods of filtering:


get-winevent -FilterHashtable @{logname="system"; providername="Microsoft-Windows-WindowsUpdateClient"; id=19} -computername ServerA -maxevents 1 |select timewritten
TotalMinutes      : 0.05561672
TotalSeconds      : 3.3370032
TotalMilliseconds : 3337.0032

get-winevent -filterxpath "*[System[Provider[@Name='Microsoft-Windows-WindowsUpdateClient']][EventID=19]]" -maxevents 1 -computer ServerA |select timewritten
TotalMinutes      : 1.56868183833333
TotalSeconds      : 94.1209103
TotalMilliseconds : 94120.9103

We can see here a clear disadvantage in Xpath queries in comparison to filterhashtables. Based on this result, I would suspect FilterXPath is doing more work on the local side than the remote side. So lets compare these two with them running "locally" via invoke-command


invoke-command -computername ServerA -ScriptBlock { get-winevent -filterxpath "*[System[Provider[@Name='Microsoft-Windows-WindowsUpdateClient']][EventID=19]]" -maxevents 1}}
TotalMinutes      : 0.143230653333333
TotalSeconds      : 8.5938392
TotalMilliseconds : 8593.8392
invoke-command -computer ServerA -scriptblock {get-winevent -FilterHashtable @{logname="system"; providername="Microsoft-Windows-WindowsUpdateClient"; id=19} -maxevents 1}}
TotalMinutes      : 0.0724750433333333
TotalSeconds      : 4.3485026
TotalMilliseconds : 4348.5026

We have a clear difference here, though we still see a big difference between the two. Also very interestingly we see that the FilterHashTable takes more time to run through invoke-command than it would have to just run it against a remote machine.


So, one to method #3. I'm not even going to run that against a remote machine, so I'll just give what happens locally in two ways. First if we remember to use the -logname parameter to somewhat restrict our results before the pipeline, and one without any filtering before the pipe.

get-winevent -LogName system |where {$_.providername -eq "Microsoft-Windows-WindowsUpdateClient"}|select -first 1
TotalMinutes      : 0.4716362
TotalSeconds      : 28.298172
TotalMilliseconds : 28298.172

Here we can see it takes a pretty long time on just the local machine. How about if we run it with no filtering to start with?

get-winevent |where {$_.providername -eq "Microsoft-Windows-WindowsUpdateClient"}|select -first 1
TotalMinutes      : 23.5320746883333
TotalSeconds      : 1411.9244813
TotalMilliseconds : 1411924.4813

Really really bad idea :)