aev-mambro2/multi-analyze-task-run-durations.ps1

## 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;
};
	<# 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;
	};