Often when troubleshooting we come across log files that have tons of data. It can be hard to digest properly, so we look for tools that can break it down and provide some insight into what is happening. Last week, I shared a blog post on parsing System Center logs with PowerShell. If we use that function to convert the log lines into objects, we can now manipulate them and add calculated fields to provide even more data to assist in troubleshooting.
One of the important angles when troubleshooting is "How long did each task in the process take?". To answer this question, we need to take a look at each line in the logs and compare it to the following one. With PowerShell, the pipeline processes each object one at a time, so how do we accomplish this with code?
The method that I came up with was to include a stutter-step for the pipeline. Capture the first log line in a variable and hold onto it until the pipeline moves to the next entry. We can then calculate the difference in the date/time fields and add it as a new property. The second entry in the log then overwrites the first entry as the stored variable and we continue until the last entry in the log. As it is the last entry in the log, we have nothing to compare it to, so we simply set it as a dash.
As you can see above, the Add-Duration function reads in the output of Get-CMLog, selects the UTCTime property for comparison, and adds the results to a property called TotalMilliseconds.
Depending on the duration of your logs, you may want to use one of the other options for duration such as Days, Hours, Minutes, or Seconds. This is useful when troubleshooting long-running tasks such as OSD, or even when you just want to figure out what is taking a long time in the process so that you can track, trend, and reduce it.
And this function is not just for System Center logs. It should work on any time-based object as long as you specify the property containing a [DateTime] field that New-TimeSpan can parse.
The full code is available below and on Github.