Skimming a Hyper-V Service Event log with PowerShell

We are all used to opening up our friend the EventLog Viewer GUI.

But what do you do when you don’t have the GUI (Server Core or Hyper-V Server for example)?  How do you get to those trusted events?

Well, PowerShell of course!  And there are even two different cmdlets to get there.

Get-EventLog and Get-WinEvent

Get-EventLog focuses on the top level event logs; Application, System, PowerShell, Security.

Get-WinEvent can get you anything, any event log.  the hardest part is identifying the Event Logs for Get-WinEvent.

Recently I have been focused on disk conversion, so lets focus on that.  VHD conversion events are in the Hyper-V Image Management event log under the Operational log.

The Hyper-V Image Management service manages VHDs (disk images) and this is also an event provider. 

If you type; get-winevent -ProviderName "Microsoft-Windows-Hyper-V-Image-Management-Service"

you will get all events, Admin and Operational.  In my case I just want Operational events, so I can do direct to the log.

get-winevent -LogName Microsoft-Windows-Hyper-V-Image-Management-Service-Operational

I cheated when I went looking for the logs, you can’t browse them like the tree view in the GUI.  I used the GUI on one server to locate the log I needed and I inferred its name from the Properties screen.

The series of EventIds that I even care about are:

15110 - creating a VHD

15111 - successfully created (finished creating)

15106 - converting a VHD from dynamic to fixed

15107 - successfully converted (finished converting)

And any fails, but didn’t find any

What I know is that I have a VM name in the SCVMM job log that I want to find the corresponding Hyper-V event(s).  That should give me something to filter on.  In the GUI I see the information in the General TAB, in the event object this is in the Message property.

get-winevent -LogName Microsoft-Windows-Hyper-V-Image-Management-Service-Operational | where {$_.Message -match "Xd1kD0229"}

In my case the name of the VM is “Xd1kD0229” and in searching the message of the Event this gives me any instance where this string of characters occurs.  In most of the events it is a folder in the Literal Path of the VHD file.

Now, how might you get PowerShell enabled on Server Core or Hyper-V Server?

At the Command prompt you can add the PowerShell and .Net features:

DISM /Online /Enable-Feature /FeatureName: NetFx2-ServerCore

DISM /Online /Enable-Feature /FeatureName: NetFx3-ServerCore

DISM /Online /Enable-Feature /FeatureName: MicrosoftWindowsPowerShell

You can then launch PowerShell in the same shell session:

C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe

Grouping and averaging time to execute execute SCVMM 2012 Jobs with PowerShell

In my previous post I ended with a large array of System Center Job Objects.

I need to now determine how long each job took to execute.  And since these are many jobs over time, I want to see if the time to execute changes over time.

So, I need to sort.  I have my array from the previous post.  To sort I do this:

$vhdConvertJobs = $vhdConvertJobs | Sort StartTime

This will sort all Job objects in the Array ( $vhdConvertJobs )using the StartTime property of the Job object. 

Nice and conveniently each job has a StartTime and EndTime, so I just need to subtract those.  The subtraction part is easy:

Foreach ($job in $vhdConvertJobs) {
    ($job.EndTime - $job.StartTime).seconds
}

Now the interesting part.  I have a huge list of numbers.  Great.  I could graph them. No.

I had this great idea to group them into groups of ten and then average them.  So my averages are the first ten, then the second ten, and so on.  That is a bit easier to look at.

$i = $vhdConvertJobs.Count
$arrayTick = 0

While ($arrayTick -lt $i){
    $loopTick = 0
    While ($loopTick -ne 10){
        $timeToConvert = $timeToConvert + ($vhdConvertJobs[$arrayTick].EndTime - $vhdConvertJobs[$arrayTick].StartTime).seconds
        $loopTick++
        $arrayTick++
        if ($arrayTick -eq $i){break}
    }
    "Average of " + $loopTick + " jobs: " + ($timeToConvert / $loopTick) + " seconds"
    $TimeToConvert = 0
}

Put this all together and it looks like this:

<#
.SYNOPSIS
   This script is dump the time to convert VHDs form Dynamic to Fixed from SCVMM 2012
.DESCRIPTION
   It first finds the VMs using the name match pattern (or you can leave that commented to simply get all VMs)
   Then It finds the virtual disk and the latest job on the virtual disks.
   The jobs are sorted from first started to last started.
   The different from StartTime to EndTime is output.
   Then the Jobs are averaged as groups of 10 and groups of 100 from first started to last started.
.AUTHOR
    Brian Ehlert, MSFT VM MVP

.KNOWN ISSUES
   In SCVMM Jobs age and the last job on an object changes.  So there is a timeliness to running this script.  If you
   wait too long you will get an incorrect number of jobs back.
#>

Import-Module VirtualMachineManager

$vhdConvertJobs = @()

$scVMs = Get-SCVirtualMachine | where {$_.Name -match "Xd1K"}

Foreach ($scVM in $scVMs){
    $vhdConvertJobs += [Microsoft.SystemCenter.VirtualMachineManager.Task]( Get-SCVirtualDiskDrive -VM $scVM | where {$_.MostRecentTask -match "convert"} ).MostRecentTask
}

$vhdConvertJobs = $vhdConvertJobs | Sort StartTime

""
"Disk Conversion Jobs"
"Listed first are the jobs started earlier, listed last are the jobs started later"

Foreach ($job in $vhdConvertJobs) {
    ($job.EndTime - $job.StartTime).seconds
}

""
# Break the sorted list of jobs into groups of 10, Average the seconds to convert per group
"Disk Conversion Job Average per 10 conversions"
"Sorted by StartTime.  First are the first jobs started, last are the later jobs started"

$i = $vhdConvertJobs.Count
$arrayTick = 0

While ($arrayTick -lt $i){
    $loopTick = 0
    While ($loopTick -ne 10){
        $timeToConvert = $timeToConvert + ($vhdConvertJobs[$arrayTick].EndTime - $vhdConvertJobs[$arrayTick].StartTime).seconds
        $loopTick++
        $arrayTick++
        if ($arrayTick -eq $i){break}
    }
    "Average of " + $loopTick + " jobs: " + ($timeToConvert / $loopTick) + " seconds"
    $TimeToConvert = 0
}

""
# Break the sorted list of jobs into groups of 100, Average the seconds to convert per group
"Disk Conversion Job Average per 100 conversions"
"Sorted by StartTime.  First are the first jobs started, last are the later jobs started"

$i = $vhdConvertJobs.Count
$arrayTick = 0

While ($arrayTick -lt $i){
    $loopTick = 0
    While ($loopTick -ne 100){
        $timeToConvert = $timeToConvert + ($vhdConvertJobs[$arrayTick].EndTime - $vhdConvertJobs[$arrayTick].StartTime).seconds
        $loopTick++
        $arrayTick++
        if ($arrayTick -eq $i){break}
    }
    "Average of " + $loopTick + " jobs: " + ($timeToConvert / $loopTick) + " seconds"
    $TimeToConvert = 0
}

Getting convert VHD jobs per VM from SCVMM 2012

I have been running some tests recently and one of the things that was brought into question is if a disk conversion job is taking longer to run as the number of VMs increases in the environment.

Now, you might think this is relatively easy.  Just issue a query with Get-SCJob and filter.

Well, I did begin that way, thinking I would get just what I wanted.

Get-SCJob | where { $_.Name -eq "convert virtual hard disk" } | where { $_.Status -eq "Completed" }

But I never got the right number of VHD conversion jobs returned back.  This obviously needed more complex scripting.

So, I tried using Get-SCVirtualDiskDrive   That cmdlet requires a VM object to be tossed in, I can’t just get a list of all the VHD like I could through a CIM call to a hypervisor.

Now I have to go to the VM level.  I have to query for the VMs, then find each virtual disk, then get the most recent job object on that virtual disk.

$scVMs = Get-SCVirtualMachine | where {$_.Name -match "Xd1K"}

In a long hand way that looks like this:

Foreach ($scVM in $scVMs){
    $vmVhd = Get-SCVirtualDiskDrive -VM $scVM | where {$_.MostRecentTask -match "convert"} 
    $vhdJob = $vmVhd.MostRecentTask
    $vhdConvertJobs += [Microsoft.SystemCenter.VirtualMachineManager.Task]$vhdJob
}

Take notice of that object cast; [Microsoft.SystemCenter.VirtualMachineManager.Task].  If you don’t do this you get an error that the Task cannot be converted to int32.  Don’t ask me why PowerShell is trying to convert the Task object into an integer, but that is what the default is trying to do.

In a nice tight shorthand way it looks like this:

Foreach ($scVM in $scVMs){
    $vhdConvertJobs += [Microsoft.SystemCenter.VirtualMachineManager.Task]( Get-SCVirtualDiskDrive -VM $scVM | where {$_.MostRecentTask -match "convert"} ).MostRecentTask
}

Next time, calculating the average time to execute the jobs, and making it useful to quickly check.

Traversing time with PowerShell

My first title for this was “the PowerShell time machine” because the article is about TimeSpan and managing time using TimeSpan.

Most folks are familiar with Get-Date.  Get-Date is all about ‘now’ – it is always now. 

Which is great, if you are running a script and want to know at some point in the script what the time is ‘now’, such as before entering a loop of some type.

Frequently I need to calculate the difference between then and now.  Or the difference between then and then.  This is where the TimeSpan comes into play.

My current project involves trudging through entries in a log file and finding a start time for a series of steps, and then the end time for the series of steps.  The whole point is that I need to know how long the series of steps took so that we can see if we made it any faster.

I don’t know about you but I have a hard time with determining the minutes in between 09:54:53 and 14:13:33.  That isn’t something I can look at and do in my head.

This is not the most elegant script and I know it can be improved.  However, this is where I began taking basic keyboard text entry and turning it into time.

If you run the script it asks you for the start time, entering HH, then MM, then SS.  Then the end time, again. HH, then MM, then SS.  Then it calculates the difference.

do {
    Clear-Host
   
    $startTime = New-TimeSpan -Hours (read-host -prompt "Enter Start hour HH") -Minutes (read-host -prompt "Enter Start minutes MM") -Seconds (read-host -prompt "Enter Start seconds SS")

    $endTime = New-TimeSpan -Hours (read-host -prompt "Enter End hour HH") -Minutes (read-host -prompt "Enter End minutes MM") -Seconds (read-host -prompt "Enter End seconds SS")

    $timeToExecute = $endTime - $startTime

    ""
    "   The task took: _" + $timeToExecute.TotalMinutes + "_ minutes"
    ""
   
    $quit = Read-Host -Prompt "press Enter to continue or 00 Enter to quit"
   
    Clear-Variable -Name startTime
    Clear-Variable -Name endTime

   
} until ($quit -eq "00")

psbase.gettext(1) I love you

I have had many cases to do things in PowerShell where I am manipulating CIM or WMI objects.
Getting CIM/WMI objects and querying information from them is never a big deal, however modifying an object and then trying to send it back to a method to cause some setting change has always been a pain.
When you get a CIM/WMI object with PowerShell, PowerShell treats it as an object, where in actuality it is XML.  It is a representation of am object.  It has a path and properties.
Over time I have treated this all kinds of ways to get it to format properly for the receiving CIM/WMI.
You can deal with it as InnerText, you can convert it to XML, you can deal with is as a complex string @” <stuff in there with intact formatting> ”@
When PowerShell sees the WMI as an object you can manipulate it in an easy object type of way.  But you can’t send it back to a WMI method.
When PowerShell sees the CIM as a string, you can manipulate it in a painful way, but you can easily send it back to a CIM method.
As a consumer who uses both Windows CIM (WMI) and Linux CIM (CIM) this is a royal pain.  Especially when PowerShell automatic object handling does not recognize the return properly (which I have had happen with CIM lots of times).  Now, I know that PowerShell 3 (in the Win8 Developer Preview) will make this all much better, but I am not there yet.
Lets just take a quick look at the object and return.
When you perform a query against WMI you get a single object or an array of objects back.  But PowerShell treats them like objects.  You can “.” the properties and methods.  This is powerful.

PS C:\Users\Public\Documents\> $vsmssd

__GENUS                    : 2
__CLASS                    : Msvm_VirtualSystemManagementServiceSettingData
__SUPERCLASS               : CIM_SettingData
__DYNASTY                  : CIM_ManagedElement
__RELPATH                  : Msvm_VirtualSystemManagementServiceSettingData.InstanceID="Microsoft:BJEDAR2"
__PROPERTY_COUNT           : 13
__DERIVATION               : {CIM_SettingData, CIM_ManagedElement}
__SERVER                   : BJEDAR2
__NAMESPACE                : root\virtualization
__PATH                     : \\BJEDAR2\root\virtualization:Msvm_VirtualSystemManagementServiceSettingData.InstanceID="Microsoft:BJEDAR2"
BiosLockString             :
Caption                    : Hyper-V Virtual System Management Service
DefaultExternalDataRoot    : C:\Users\Public\VMs\
DefaultVirtualHardDiskPath : C:\Users\Public\VMs\
Description                : Settings for the Virtual System Management Service
ElementName                : Hyper-V Virtual System Management Service
InstanceID                 : Microsoft:BJEDAR2
MaximumMacAddress          : 00155D748DFF
MinimumMacAddress          : 00155D680A00
NumaSpanningEnabled        : True
PrimaryOwnerContact        :
PrimaryOwnerName           : Administrators
ScopeOfResidence           :

But when I modify that object and send it back to the WMI provider I need to adhere to the CIM standard and I cannot just send back $vsmssd.   That is where this little, wonderful, psbase.gettext method comes into play.  Lets take this object and turn it back into its CIM text so that I can send it back to the WMI provider.
When I type that out to the screen I get something very different, not an object, but useful for sending the message.

PS C:\Users\Public\Documents\> $vsmssd.psbase.gettext(1)
<INSTANCE CLASSNAME="Msvm_VirtualSystemManagementServiceSettingData"><QUALIFIER NAME="dynamic" PROPAGATED="true" TYPE="boolean" TOSUBCLASS="false" TOINSTANCE="true"><VALUE>TRUE</VALU
E></QUALIFIER><PROPERTY NAME="__PATH" CLASSORIGIN="___SYSTEM" TYPE="string"><VALUE>\\BJEDAR2\root\virtualization:Msvm_VirtualSystemManagementServiceSettingData.InstanceID="Microsoft:
BJEDAR2"</VALUE></PROPERTY><PROPERTY NAME="__NAMESPACE" CLASSORIGIN="___SYSTEM" TYPE="string"><VALUE>root\virtualization</VALUE></PROPERTY><PROPERTY NAME="__SERVER" CLASSORIGIN="___S
YSTEM" TYPE="string"><VALUE>BJEDAR2</VALUE></PROPERTY><PROPERTY.ARRAY NAME="__DERIVATION" CLASSORIGIN="___SYSTEM" TYPE="string"><VALUE.ARRAY><VALUE>CIM_SettingData</VALUE><VALUE>CIM_
ManagedElement</VALUE></VALUE.ARRAY></PROPERTY.ARRAY><PROPERTY NAME="__PROPERTY_COUNT" CLASSORIGIN="___SYSTEM" TYPE="sint32"><VALUE>13</VALUE></PROPERTY><PROPERTY NAME="__RELPATH" CL
ASSORIGIN="___SYSTEM" TYPE="string"><VALUE>Msvm_VirtualSystemManagementServiceSettingData.InstanceID="Microsoft:BJEDAR2"</VALUE></PROPERTY><PROPERTY NAME="__DYNASTY" CLASSORIGIN="___
SYSTEM" TYPE="string"><VALUE>CIM_ManagedElement</VALUE></PROPERTY><PROPERTY NAME="__SUPERCLASS" CLASSORIGIN="___SYSTEM" TYPE="string"><VALUE>CIM_SettingData</VALUE></PROPERTY><PROPER
TY NAME="__CLASS" CLASSORIGIN="___SYSTEM" TYPE="string"><VALUE>Msvm_VirtualSystemManagementServiceSettingData</VALUE></PROPERTY><PROPERTY NAME="__GENUS" CLASSORIGIN="___SYSTEM" TYPE=
"sint32"><VALUE>2</VALUE></PROPERTY><PROPERTY NAME="BiosLockString" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="t
rue" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER></PROPERTY><PROPERTY NAME="Caption" CLASSORIGIN="CIM_ManagedElement" TYPE="string"><QUALIFIER NAME="CIMTYPE" PRO
PAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>Hyper-V Virtual System Management Service</VALUE></PROPERTY><PROPERTY NAME="DefaultExternalData
Root" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QU
ALIFIER><VALUE>C:\Users\Public\VMs\</VALUE></PROPERTY><PROPERTY NAME="DefaultVirtualHardDiskPath" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIE
R NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>C:\Users\Public\VMs\</VALUE></PROPERTY><PROPERTY NAME="Description" CLASSOR
IGIN="CIM_ManagedElement" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>Settings for the Virtual S
ystem Management Service</VALUE></PROPERTY><PROPERTY NAME="ElementName" CLASSORIGIN="CIM_ManagedElement" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINS
TANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>Hyper-V Virtual System Management Service</VALUE></PROPERTY><PROPERTY NAME="InstanceID" CLASSORIGIN="CIM_SettingData" TYPE="strin
g"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><QUALIFIER NAME="key" PROPAGATED="true" TYPE="boolean" OVERRIDABLE="fa
lse" TOINSTANCE="true"><VALUE>TRUE</VALUE></QUALIFIER><VALUE>Microsoft:BJEDAR2</VALUE></PROPERTY><PROPERTY NAME="MaximumMacAddress" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSe
ttingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>00155D748DFF</VALUE></PROPERTY><PROPERTY
NAME="MinimumMacAddress" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE
>string</VALUE></QUALIFIER><VALUE>00155D680A00</VALUE></PROPERTY><PROPERTY NAME="NumaSpanningEnabled" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="boolean"><QUA
LIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>boolean</VALUE></QUALIFIER><VALUE>TRUE</VALUE></PROPERTY><PROPERTY NAME="PrimaryOwnerContact" CLASSORIG
IN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>
</VALUE></PROPERTY><PROPERTY NAME="PrimaryOwnerName" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSettingData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="stri
ng" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER><VALUE>Administrators</VALUE></PROPERTY><PROPERTY NAME="ScopeOfResidence" CLASSORIGIN="Msvm_VirtualSystemManagementServiceSetti
ngData" TYPE="string"><QUALIFIER NAME="CIMTYPE" PROPAGATED="true" TYPE="string" TOINSTANCE="true"><VALUE>string</VALUE></QUALIFIER></PROPERTY></INSTANCE>

The actual object is the same thing, in spite of this last looking like a bunch of XML.
If you try to manipulate CIM from a Linux provider with PowerShell you will see lots of this type of output and dealing with it properly is the pain.
Just thought I would share.  Eventually I will get back to Linux CIM interfaces, but I hope I can wait until PowerShell 3 comes out, with handling for CIM, not just WMI.