Skip to content

Commit

Permalink
Implement script to parse provisioners duration from packer diagnosti…
Browse files Browse the repository at this point in the history
…c logs (actions#2137)

* testing

* Update image-generation.yml

* Update image-generation.yml

* fix comments

* Update measure-provisioners-duration.ps1
  • Loading branch information
maxim-lobanov authored Nov 27, 2020
1 parent 3100bc2 commit 8d6d64a
Show file tree
Hide file tree
Showing 5 changed files with 164 additions and 14 deletions.
6 changes: 1 addition & 5 deletions .vscode/settings.json
Original file line number Diff line number Diff line change
@@ -1,7 +1,3 @@
{
// When enabled, will trim trailing whitespace when you save a file.
"files.trimTrailingWhitespace": true,
"[markdown]": {
"files.trimTrailingWhitespace": false
},
"files.trimTrailingWhitespace": false
}
32 changes: 28 additions & 4 deletions images.CI/linux-and-win/azure-pipelines/image-generation.yml
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,10 @@

jobs:
- job:
pool: ci-agent-pool
displayName: Image Generation (${{ parameters.image_type }})
timeoutInMinutes: 600
cancelTimeoutInMinutes: 30
pool: ci-agent-pool
variables:
- group: Image Generation Variables

Expand All @@ -21,6 +22,18 @@ jobs:
filePath: ./images.CI/download-repo.ps1
arguments: -RepoUrl $(CUSTOM_REPOSITORY_URL) `
-RepoBranch $(CUSTOM_REPOSITORY_BRANCH)

- task: PowerShell@2
displayName: 'Set image template variables'
inputs:
targetType: 'inline'
script: |
$ImageType = "${{ parameters.image_type }}"
$TemplateDirectoryName = if ($ImageType.StartsWith("ubuntu")) { "linux" } else { "win" }
$TemplateDirectoryPath = Join-Path "images" $TemplateDirectoryName | Resolve-Path
$TemplatePath = Join-Path $TemplateDirectoryPath "$ImageType.json"
Write-Host "##vso[task.setvariable variable=TemplateDirectoryPath;]$TemplateDirectoryPath"
Write-Host "##vso[task.setvariable variable=TemplatePath;]$TemplatePath"
- task: PowerShell@2
displayName: 'Build VM'
Expand All @@ -30,7 +43,7 @@ jobs:
arguments: -ResourcesNamePrefix $(Build.BuildId) `
-ClientId $(CLIENT_ID) `
-ClientSecret $(CLIENT_SECRET) `
-Image ${{ parameters.image_type }} `
-TemplatePath $(TemplatePath) `
-ResourceGroup $(AZURE_RESOURCE_GROUP) `
-StorageAccount $(AZURE_STORAGE_ACCOUNT) `
-SubscriptionId $(AZURE_SUBSCRIPTION) `
Expand All @@ -40,14 +53,25 @@ jobs:
-VirtualNetworkRG $(BUILD_AGENT_VNET_RESOURCE_GROUP) `
-VirtualNetworkSubnet $(BUILD_AGENT_SUBNET_NAME) `
-GitHubFeedToken $(GITHUB_TOKEN)
env:
PACKER_LOG: 1
PACKER_LOG_PATH: $(Build.ArtifactStagingDirectory)/packer-log.txt

- task: PowerShell@2
displayName: 'Output Readme file content'
inputs:
targetType: 'inline'
script: |
$docsPath = Get-ChildItem -Path "images" -Include ${{ parameters.image_readme_name }} -Recurse -Depth 1 | Select-Object -First 1
Get-Content -Path $docsPath
Get-Content -Path (Join-Path "$(TemplateDirectoryPath)" "${{ parameters.image_readme_name }}")
- task: PowerShell@2
displayName: 'Print provisioners duration'
inputs:
targetType: 'filePath'
filePath: ./images.CI/measure-provisioners-duration.ps1
arguments: -PackerLogPath "$(Build.ArtifactStagingDirectory)/packer-log.txt" `
-PrefixToPathTrim "$(TemplateDirectoryPath)" `
-PrintTopNLongest 25

- task: PowerShell@2
displayName: 'Create release for VM deployment'
Expand Down
5 changes: 2 additions & 3 deletions images.CI/linux-and-win/build-image.ps1
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
param(
[String] [Parameter (Mandatory=$true)] $Image,
[String] [Parameter (Mandatory=$true)] $TemplatePath,
[String] [Parameter (Mandatory=$true)] $ClientId,
[String] [Parameter (Mandatory=$true)] $ClientSecret,
[String] [Parameter (Mandatory=$true)] $GitHubFeedToken,
Expand All @@ -14,8 +14,7 @@ param(
[String] [Parameter (Mandatory=$true)] $VirtualNetworkSubnet
)

$TemplatePath = (Get-ChildItem -Path "images" -Include "$Image.json" -Recurse -Depth 2).FullName
if (-not $TemplatePath)
if (-not (Test-Path $TemplatePath))
{
Write-Error "'-Image' parameter is not valid. You have to specify correct image type."
exit 1
Expand Down
13 changes: 11 additions & 2 deletions images.CI/macos/azure-pipelines/image-generation.yml
Original file line number Diff line number Diff line change
Expand Up @@ -87,9 +87,10 @@ jobs:
$sensitiveString -eq $null
}
displayName: 'Build VM'
env:
PACKER_LOG: 0
workingDirectory: 'images/macos'
env:
PACKER_LOG: 1
PACKER_LOG_PATH: $(Agent.TempDirectory)/packer-log.txt
- bash: |
echo "Copy image output files"
Expand All @@ -112,6 +113,14 @@ jobs:
ArtifactName: 'Built_VM_Artifacts'
displayName: Publish Artifacts

- task: PowerShell@2
displayName: 'Print provisioners duration'
inputs:
targetType: 'filePath'
filePath: ./images.CI/measure-provisioners-duration.ps1
arguments: -PackerLogPath "$(Agent.TempDirectory)/packer-log.txt" `
-PrintTopNLongest 25

- task: PublishTestResults@2
inputs:
testResultsFiles: '*.xml'
Expand Down
122 changes: 122 additions & 0 deletions images.CI/measure-provisioners-duration.ps1
Original file line number Diff line number Diff line change
@@ -0,0 +1,122 @@
param(
[Parameter(Mandatory=$true)]
[string]$PackerLogPath,
[string]$PrefixToPathTrim,
[int]$PrintTopNLongest = 25
)

$DateTimeRegex = "(\d+\/\d+\/\d+ \d+:\d+:\d+)"
$TelemetryLineRegex = "\[INFO\] \(telemetry\)"
$StartProvisionerRegex = "^${DateTimeRegex} ${TelemetryLineRegex} Starting provisioner (.+)$"
$EndProvisionerRegex = "^${DateTimeRegex} ${TelemetryLineRegex} ending (.+)$"
$ShellScriptSubItemRegex = "${DateTimeRegex} ui: ==> .+: Provisioning with \w+ script: (.+)"
$DownloadUploadSubItemRegex = "${DateTimeRegex} ui: ==> .+: (Downloading .+|Uploading .+)"

function Start-ProvisionerItem {
param([string]$ProvisionerType, [string]$StartTime)

return @{
ProvisionerType = $ProvisionerType
StartTime = [DateTime]::Parse($StartTime)
SubItems = @()
}
}

function End-ProvisionerItem {
param([object]$Provisioner, [string]$EndTime)

$Provisioner.EndTime = [DateTime]::Parse($EndTime)
$Provisioner.Duration = New-TimeSpan -Start $Provisioner.StartTime -End $Provisioner.EndTime
}

function Add-ProvisionerSubItem {
param([object]$Provisioner, [string]$Command, [string]$DateTime)

$lastItem = $Provisioner.SubItems | Select-Object -Last 1
if ($lastItem) {
$lastItem.EndTime = [DateTime]::Parse($DateTime)
$lastItem.Duration = New-TimeSpan -Start $lastItem.StartTime -End $lastItem.EndTime
}

if ($Command) {
if ($PrefixToPathTrim) { $Command = $Command.Replace($PrefixToPathTrim, ".") }
$Provisioner.SubItems += @{
Command = $Command
StartTime = [DateTime]::Parse($DateTime)
}
}
}

function Invoke-TryFindProvisionerSubItem {
param([object]$Provisioner, [string] $Line)

if ($Provisioner.ProvisionerType -in "powershell", "shell", "windows-shell") {
if ($Line -match $ShellScriptSubItemRegex) {
Add-ProvisionerSubItem -Provisioner $Provisioner -Command $Matches[2] -DateTime $Matches[1]
}
} elseif ($Provisioner.ProvisionerType -eq "file") {
if ($Line -match $DownloadUploadSubItemRegex) {
Add-ProvisionerSubItem -Provisioner $Provisioner -Command $Matches[2] -DateTime $Matches[1]
}
}
}

function Assert-StartProvisioner {
param([object]$Provisioner, [string]$ProvisionerType)
if ($null -ne $Provisioner) {
throw "New provisioner '$ProvisionerType' has been started but previous '$($Provisioner.ProvisionerType)' was not finished yet"
}
}

function Assert-EndProvisioner {
param([object]$Provisioner, [string]$ProvisionerType)
if (($null -ne $Provisioner) -and ($Provisioner.ProvisionerType -ne $ProvisionerType)) {
throw "Expected end of '$($Provisioner.ProvisionerType)' provisioner but found end of '$ProvisionerType'"
}
}

$provisionersList = @()
$currentProvisioner = $null

if ((Get-Content $PackerLogPath -Raw) -notmatch $TelemetryLineRegex) {
throw "Packer log doesn't contain diagnostic information. Env PACKER_LOG must be set to 1"
}

Get-Content $PackerLogPath | ForEach-Object {
if ($_ -match $StartProvisionerRegex) {
Assert-StartProvisioner -Provisioner $currentProvisioner -ProvisionerType $Matches[2]

$currentProvisioner = Start-ProvisionerItem -ProvisionerType $Matches[2] -StartTime $Matches[1]
} elseif (($_ -match $EndProvisionerRegex) -and $currentProvisioner) {
Assert-EndProvisioner -Provisioner $currentProvisioner -ProvisionerType $Matches[2]

End-ProvisionerItem -Provisioner $currentProvisioner -EndTime $Matches[1]
Add-ProvisionerSubItem -Provisioner $currentProvisioner -Command $null -DateTime $Matches[1]
$provisionersList += $currentProvisioner
$currentProvisioner = $null
} elseif ($currentProvisioner) {
Invoke-TryFindProvisionerSubItem -Provisioner $currentProvisioner -Line $_
}
}
$totalProvisionersTime = New-TimeSpan
$provisionersList | ForEach-Object { $totalProvisionersTime = $totalProvisionersTime.Add($_.Duration) }

# Print information about provisioners in order of execution
Write-Host "Build timeline:"
$provisionersList | ForEach-Object {
Write-Host "- $($_.Duration) | $($_.ProvisionerType)"
$_.SubItems | ForEach-Object {
Write-Host " $($_.Duration) | $($_.Command)"
}
Write-Host ""
}
Write-Host "Total provisioners time: $totalProvisionersTime"

if ($PrintTopNLongest -gt 0) {
Write-Host "`n`nTop longest provisioners:"
$provisionersList | ForEach-Object {
if ($_.SubItems.Length -gt 0) { $_.SubItems } else { @{ Command = $_.ProvisionerType; Duration = $_.Duration } }
} | Sort-Object { $_.Duration } | Select-Object -Last $PrintTopNLongest | ForEach-Object {
Write-Host "- $($_.Duration) | $($_.Command)"
}
}

0 comments on commit 8d6d64a

Please sign in to comment.