Multithreaded Analyze Scheduled Task Run Durations (Windows Powershell, DevOps)

multi-analyze-task-run-durations.ps1

<# Analyze normal run duration of scheduled tasks.
 # Gathers insight into how long tasks run, analyzes
 # which tasks run shorter or longer than normal,
 # reports back to console, and writes out its report
 # as a CSV (spreadsheet).
 #
 # The script assumes that the user account running it
 # has access to the computer and is allowed to read 
 # its event log.
 #
 # Author: A.E.Veltstra
 # Version: 2.21.927.1051
 #>

clear;
$safeDateTimeFormat = "%Y%m%dT%H%M%S";

$gather = {
    Param (
        $h,
        $logName,
        $eventFilter,
        $propertySelector,
        $taskNameStartsWith
    )
    
    $hostTaskRuns = New-Object System.Collections.ArrayList;

    # Gather the events.
    Get-WinEvent -ComputerName $h -FilterHashtable $eventFilter -ea SilentlyContinue | foreach {
        # Filter by name,
        $instanceId,$taskName = $_.GetPropertyValues($propertySelector);
        if ($taskName.StartsWith($taskNameStartsWith)) {
            $getEndTimeFilter = @{
                LogName = $logName 
                Id = 102
                Data = $instanceId
            };
            $taskEndTime = $(Get-WinEvent -ComputerName $h -FilterHashtable $getEndTimeFilter -ea SilentlyContinue).TimeCreated;
            if($null -ne $taskEndTime) {
                # Create and return custom objects.
                [void]$hostTaskRuns.Add([pscustomobject]@{
                    Host = $h
                    TaskName = $taskName
                    StartTime = $_.TimeCreated
                    EndTime = $taskEndTime
                });
            }
        }
    }

    # Return to invoker.
    Return $hostTaskRuns;
};


<#
 # Supply the host names of the Windows-operated API servers to query.
 #>
$hosts = @(
    "localhost"
)

$logName = 'Microsoft-Windows-TaskScheduler/Operational';
# PropertySelector for the Correlation id (the InstanceId) and task name
[string[]]$props = @(
    'Event/EventData/Data[@Name="InstanceId"]'
    'Event/EventData/Data[@Name="TaskName"]'
);
$propertySelector = New-Object System.Diagnostics.Eventing.Reader.EventLogPropertySelector @(,$props);
# Specify which tasks to profile.
$taskNameStartsWith = "\Microsoft";
[int32]$daysBack = 7;
$maxThreads = $hosts.Count;
$threads = New-Object System.Collections.ArrayList;
$threadPool = [RunspaceFactory]::CreateRunspacePool(1, $maxThreads);
$threadPool.Open();

$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
Write-Output "$now : Creating $maxThreads threads for gathering info...";
foreach ($h in $hosts) {
    # Event filter for the initial query for all "Start" events in the last week.
    # My localhost has no log with ProviderName = 'TaskScheduler'
    $eventFilter = @{
        LogName = $logName
        Id = 100
        Level = 4
        StartTime = [datetime]::Now.AddDays(-1 * $daysBack)
        #EndTime = [datetime]::Now.AddDays(-1 * $to) #adding this filter criterium causes the return of no events at all.
    };
    Write-Output "$now : Starting work on host $h, from $daysBack days back.";
    $f = [powershell]::Create().
                          AddScript($gather).
                          AddArgument($h).
                          AddArgument($logName).
                          AddArgument($eventFilter).
                          AddArgument($propertySelector).
                          AddArgument($taskNameStartsWith);
    $f.RunspacePool = $threadPool;
    [void]$threads.Add([pscustomobject]@{
        Host = $h
        DaysBack = [int32]$daysBack
        Function = $f
        Invocation = $f.BeginInvoke()
    });
}

Do {
   Write-Host "." -NoNewline
   Start-Sleep -Seconds 30
} While ( $threads.Invocation.IsCompleted -contains $false );
Write-Host ".";


$taskRuns = @();
foreach ($t in $threads) {
   $taskRuns += $t.Function.EndInvoke($t.Invocation);
};

$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
$amount = $taskRuns.Count;
Write-Output "$now : All $amount tasks gathered.";

[int32]$zero = 0;
if ($zero -eq $taskRuns.Count) {
    Write-Output "$now : Found no qualifying tasks. Exiting.";
    exit 0;
}

# Specify which durations to discard. This affects how many runs get flagged as outliers.
# Supply an amount in minutes. Short run durations are for when no input data exists or
# when the network goes down.
$lowerDurationThreshold = 2.5;
Write-Output "`r`n`r`n$now : Sorting, grouping, and calculating durations in minutes. Runs with no end time will be reported separately. Runs with duration times shorter than $lowerDurationThreshold minutes will get ignored.";

$sorted = $taskRuns | select Host, TaskName, StartTime, EndTime | sort-object -Property Host, TaskName, StartTime;
$taskRuns = $null;
$groups = [ordered]@{};
$name = '';
$lastGroupName = '';
$taskRuns = $null;
$unfinished = New-Object System.Collections.ArrayList;

foreach($record in $sorted) {
  $name = $record.Host + $record.TaskName;
  if ($name -ne $lastGroupName) {
     $lastGroupName = $name;
     $groups[$name] = New-Object System.Collections.ArrayList;
  }
  # some events have no end time recorded. It is not yet clear why.
  if ($null -eq $record.EndTime) {
    [void]$unfinished.Add(@{
        Task = $name
        Start = $record.StartTime
    })
  } else {
    # negative durations indicate that the task hasn't ended yet.
    $duration = $record.EndTime.Subtract($record.StartTime).TotalMinutes
    if ($duration -lt $zero) {
        [void]$unfinished.Add(@{
            Task = $name
            Start = $record.StartTime
        })
    }
    # durations shorter than the threshold are for when no data exists or 
    # when the network is down.
    elseif ($lowerDurationThreshold -lt $duration) {
        [void]$groups[$name].Add([pscustomobject]@{
            Start = $record.StartTime
            Duration = $duration
        });
    }
  }
}

$amount = $unfinished.Count;
$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
if ($zero -ne $amount) {
    Write-Output "$now : Found $amount unfinished tasks. Exporting as file.";
    $outputPath = "$HOME\Documents\api-task-run-unfinished-$now.csv";
    Write-Output "`r`n`r`n$now : Creating CSV: '$outputPath'...";
    $unfinished | ForEach-Object {
        $_ | Select Task, Start | Export-CSV -Path $outputPath -NoTypeInformation -NoClobber -Append;
    };
    $unfinished.Clear();
    $unfinished = $null;
}

$amount = $groups.Count;
$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
if ($zero -eq $amount) {
    Write-Output "$now : Done sorting and grouping. 0 groups remain. Exiting.";
    exit 0;
}


Write-Output "$now : Done sorting and grouping. $amount groups remain. Durations calculated. Calculating outliers...";

# Outliers will be a list of records with named values, so it can be exported as CSV.
$outliers = New-Object System.Collections.ArrayList;
$lastGroup = '';
$timeFormat = "{0:hh\:mm\:ss}";
$differenceThreshold = 1;

foreach($group in $groups.Keys) {
    #$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
    #Write-Output "$now : Calculating outliers for task $group...";
    $records = $groups[$group];
    
    # calculate the mean
    $n = 0;
    $sumDuration = 0;
    foreach($record in $records) {
        $n += 1;
        $sumDuration += $record.Duration;
    }

    #correct the amount for follow-up divisions
    $n = if ($n -lt 1) { 1 } else { $n };

    $μ = $sumDuration / $n;

    # calculate the standard deviation
    $sumDifference = 0;
    foreach($record in $records) {
        $diff = [math]::Pow([math]::Abs($record.Duration - $μ), 2);
        $sumDifference += $diff;
    }
    $α = [math]::Sqrt($sumDifference / $n);

    # outliers: all records whose duration is further from μ than 2 α.
    foreach($record in $records) {
        $diff = $record.Duration - $μ;
        if ([math]::Abs($diff) -gt $differenceThreshold) {
            $isOutlier = [math]::Abs($diff) -gt (2*$α);
            if ($isOutlier) {
                [void]$outliers.Add([pscustomobject]@{
                    Task = $group
                    Start = $record.Start
                    Difference = ($timeFormat -f [timespan]::FromMinutes($diff))
                    Duration = ($timeFormat -f [timespan]::FromMinutes($record.Duration))
                    Mean = ($timeFormat -f [timespan]::FromMinutes($μ))
                    StandardDeviation = ($timeFormat -f [timespan]::FromMinutes($α))
                    DoubleDeviation = ($timeFormat -f [timespan]::FromMinutes(2*$α))
                });
            }
        }
    }

}

$groups = $null;

$amount = $outliers.Count;
$now = Get-Date -DisplayHint DateTime -UFormat $safeDateTimeFormat;
if ($zero -eq $amount) {
    Write-Output "`r`n`r`n$now : No outliers found. Exiting.";
    Exit 0;
}

$outliers = $outliers | Sort-Object -Property Difference -Descending;

$outputPath = "$HOME\Documents\api-task-run-outliers-$now.csv";
Write-Output "`r`n`r`n$now : Creating CSV: '$outputPath'...";
$outliers | ForEach-Object {
    $_ | Select Task, Start, Difference, Duration, Mean, StandardDeviation, DoubleDeviation | Export-CSV -Path $outputPath -NoTypeInformation -NoClobber -Append;
};

This is a multi-threading upgrade from analyze-scheduled-task-run-durations.ps1.

Instead of analyzing each host one at a time, this script creates a separate process for each host. If your hosts log a lot of task starts, this can drastically cut the script's runtime.