{"id":13351,"date":"2011-07-11T00:01:00","date_gmt":"2011-07-11T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2011\/07\/11\/use-date-types-to-filter-event-trace-logs-in-powershell\/"},"modified":"2011-07-11T00:01:00","modified_gmt":"2011-07-11T00:01:00","slug":"use-date-types-to-filter-event-trace-logs-in-powershell","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/use-date-types-to-filter-event-trace-logs-in-powershell\/","title":{"rendered":"Use Date Types to Filter Event Trace Logs in PowerShell"},"content":{"rendered":"

Summary<\/strong>: Learn how to use date types to filter event trace logs in Windows PowerShell.<\/p>\n

 <\/p>\n

\"Hey,Hey, Scripting Guy! I am wondering, oh great scripting master: can I use Windows PowerShell to parse an ETW log file?<\/p>\n

—JM<\/p>\n

 <\/p>\n

\"Hey,Hello JM,<\/p>\n

Microsoft Scripting Guy Ed Wilson here. It is “oh dark thirty” in the Piedmont region of the United States<\/a>. 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<\/a>. 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<\/a>. My last coffee day occurred back in January when I was talking about scheduling Windows PowerShell scripts that require input values<\/a>.<\/p>\n

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<\/a>). Now all you need is a robot lawn mower.<\/p>\n

In Saturday’s Weekend Scripter article<\/a>, 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<\/b> cmdlet to find and to read the trace.<\/p>\n

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>. 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.<\/p>\n

\"Image<\/a><\/p>\n

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

$wmiLog = (Get-WinEvent -ListLog *wmi*trace -force).logname<\/p>\n

Get-WinEvent -LogName $wmilog -Oldest | select message<\/p>\n

The two commands and associated output are shown in the following figure.<\/p>\n

\"Image<\/a><\/p>\n

In the previous figure, the output of the message<\/b> 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<\/b> property. To expand the message<\/b> property, use the expandproperty<\/b> <\/i>property from the Select-Object<\/b> cmdlet. Here is the syntax of this command:<\/p>\n

Get-WinEvent -LogName $wmilog -Oldest | select -ExpandProperty message <\/p>\n

The command and associated output are shown in the following figure.<\/p>\n

\"Image<\/a><\/p>\n

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<\/b> object, and use it with a Where-Object<\/b> filter. Unfortunately, no records are returned from the query. The two commands are shown here:<\/p>\n

$date = [datetime]”7\/6\/2011 6:03:51 PM”<\/p>\n

Get-WinEvent -LogName $wmilog -Oldest | where-object { $_.timecreated -eq $date }<\/p>\n

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

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

 <\/p>\n

TimeCreated<\/span>                    ProviderName<\/span>                            Id Message<\/span><\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   2 ProviderInfo for…<\/p>\n

7\/6\/2011 6:04:01 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:04:42 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:04:42 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

 <\/p>\n

The reason the equality operator does not return any objects is because the timecreated<\/b> property is an instance of a system.datetime<\/b> object, and as such the property is more complex than a simple string. The following command explores the timecreated<\/b> property. Both the command and associated output are shown here (the command is broken at the pipeline character for the sake of readability; in reality, it is normally typed on a single line):<\/p>\n

PS C:\\> Get-WinEvent -LogName $wmilog -Oldest -MaxEvents 1 |<\/p>\n

Get-Member -Name timecreated<\/p>\n

 <\/p>\n

   TypeName: System.Diagnostics.Eventing.Reader.EventLogRecord<\/p>\n

 <\/p>\n

Name<\/span>               MemberType<\/span>                 Definition<\/span><\/p>\n

TimeCreated Property   System.Nullable`1[[System.DateTime, mscorlib, Version…<\/p>\n

 <\/p>\n

I can use the maxevents<\/b> property to help retrieve a single record for exploration. In the following command, I store the eventlogrecord<\/b> object in a variable named $record<\/b>.<\/i> I then display the timecreated<\/b> property. The commands and output follow:<\/p>\n

PS C:\\> $record = Get-WinEvent -LogName $wmilog -Oldest -MaxEvents 1<\/p>\n

PS C:\\> $record.TimeCreated<\/p>\n

 <\/p>\n

Wednesday, July 06, 2011 6:03:51 PM<\/p>\n

 <\/p>\n

To get a better idea of what is involved in the datetime<\/b> object, I send the results from the TimeCreated<\/b> property across the pipeline to the Format-List<\/b> cmdlet. I use the force<\/i> parameter to ensure that any hidden properties display. The command and associated output are shown here.<\/p>\n

PS C:\\> $record.TimeCreated | Format-List -Force<\/p>\n

 <\/p>\n

Date        : 7\/6\/2011 12:00:00 AM<\/p>\n

Day         : 6<\/p>\n

DayOfWeek   : Wednesday<\/p>\n

DayOfYear   : 187<\/p>\n

Hour        : 18<\/p>\n

Kind        : Local<\/p>\n

Millisecond : 776<\/p>\n

Minute      : 3<\/p>\n

Month       : 7<\/p>\n

Second      : 51<\/p>\n

Ticks       : 634455722317760648<\/p>\n

TimeOfDay   : 18:03:51.7760648<\/p>\n

Year        : 2011<\/p>\n

DateTime    : Wednesday, July 06, 2011 6:03:51 PM<\/p>\n

 <\/p>\n

If I hone in on the timeofday<\/b> property from the timecreated<\/b> <\/i>property, I see that another object is returned. The command and associated output are shown here.<\/p>\n

PS C:\\> $record.TimeCreated.TimeOfDay<\/p>\n

 <\/p>\n

Days              : 0<\/p>\n

Hours             : 18<\/p>\n

Minutes           : 3<\/p>\n

Seconds           : 51<\/p>\n

Milliseconds      : 776<\/p>\n

Ticks             : 650317760648<\/p>\n

TotalDays         : 0.752682593342593<\/p>\n

TotalHours        : 18.0643822402222<\/p>\n

TotalMinutes      : 1083.86293441333<\/p>\n

TotalSeconds      : 65031.7760648<\/p>\n

TotalMilliseconds : 65031776.0648<\/p>\n

 <\/p>\n

When I am only interested in the type of object contained in a property, I use the gettype<\/b> method directly. The use of the gettype<\/b> method and associated output are shown here:<\/p>\n

PS C:\\> ($record.TimeCreated.TimeOfDay).gettype()<\/p>\n

 <\/p>\n

IsPublic<\/span>              IsSerial<\/span>              Name<\/span>               BaseType<\/span><\/p>\n

True                  True                  TimeSpan          System.ValueType<\/p>\n

 <\/p>\n

It is possible to use the ticks to filter records. There are a couple of ticks available for this use. The first is a tick associated with the timespan<\/b> object. This tick<\/a> represents 100 nanoseconds since midnight. The tick is the smallest unit of time. In the code that follows, the ticks<\/b> property from the timespan<\/b> object contained in the timeofday<\/b> property is displayed. Next, I store the tick in the $ticks<\/b> <\/i>variable, and use it to display event log entries that occur at the same time of day. The commands and associated output are shown here.<\/p>\n

PS C:\\> $record.TimeCreated.TimeOfDay.Ticks<\/p>\n

650317760648<\/p>\n

PS C:\\> $ticks = $record.TimeCreated.TimeOfDay.Ticks<\/p>\n

PS C:\\> Get-WinEvent -LogName $wmilog -Oldest |<\/p>\n

? { $_.timecreated.timeofday.ticks -eq $ticks }<\/p>\n

 <\/p>\n

TimeCreated<\/span>                   ProviderName<\/span>                            Id Message<\/span><\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   1 GroupOperationId…<\/p>\n

7\/6\/2011 6:03:51 PM      Microsoft-Window…                   3 Stop OperationId…<\/p>\n

 <\/p>\n

The other ticks<\/b> <\/i>property that is available is the one directly on the system.datetime<\/b> object stored in the timecreated<\/b> property. This ticks<\/b> property<\/a> represents the number of 100-nanosecond intervals that have elapsed since 12:00:00 midnight, January 1, 0001. The value of ticks<\/b> from the datetime<\/b> object is shown here:<\/p>\n

PS C:\\> $record.TimeCreated.Ticks<\/p>\n

634455722317760648<\/p>\n

 <\/p>\n

JM, that is all there is to filtering ETW logs in the Get-WinEvent<\/b> cmdlet using time stamps. Troubleshooting Windows Week will continue tomorrow when I will talk about searching the message results. <\/p>\n

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

Ed Wilson, Microsoft Scripting Guy<\/b><\/p>\n

 <\/p>\n

 <\/p>\n","protected":false},"excerpt":{"rendered":"

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 […]<\/p>\n","protected":false},"author":596,"featured_media":87096,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[97,98,31,60,3,4,134,61,45,6],"class_list":["post-13351","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-event-logs","tag-logs-and-monitoring","tag-operating-system","tag-performance","tag-scripting-guy","tag-scripting-techniques","tag-troubleshooting","tag-weekend-scripter","tag-windows-powershell","tag-wmi"],"acf":[],"blog_post_summary":"

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 […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/13351","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/users\/596"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/comments?post=13351"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/13351\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media\/87096"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media?parent=13351"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=13351"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=13351"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}