Lesson Learned #523: Measuring Import Time -Parsing SqlPackage Logs with PowerShell

This week I'm working on a service request who was experiencing long import times when restoring a large BACPAC into Azure SQL Database, I need to understand where time was being spent inside SqlPackage.exe. I rely on the diagnostics log and the PowerShell to analyze this time. The file contains valuable information that we can extract and summarize using PowerShell.

I developed a small PowerShell Script with the following idea: 

• Classifies every entry (Information, Verbose‑25, Verbose‑19, …).
• Tracks cumulative time for each class.
• Flags any operation whose delta exceeds 10 seconds with a warning.
• Produces two tables at the end:
  • Summary per Level (counts + total seconds).
  • Verbose‑25 Operations sorted by elapsed time. I used Verbose-25 (Verbose Operation plus operation ), because I identified that the lines contains the elapsed-time of the operation done. Those are usually the slowest parts.

How the Script Works

• Read the content 5000 lines at a time.
• Parser every line running Process‑Line function to obtain 3 variables Level, Id, Timestamp, Message.
• If the level is not Verbose-25 (operation finished), the time is measured against the previous timestamp otherwise for Perf: text Operation ended we use elapsed ms.
• I added a line that when the delta > 10 s triggers Write‑Warning.

$logPath = "C:\temp\Exampledf.txt"
$prevStamp = $null
$Salida    = $null
[int]$Lines= 0
$stats     = @{}
$Verbose25 = @{}

function Process-Line {
    param (
        [string]$line,
        [ref]$prevStamp
    )

    if ($line -notmatch 'Microsoft\.Data\.Tools\.Diagnostics\.Tracer') { return "" }

    $tail = $Line.Substring($Line.IndexOf('Tracer') + 6).Trim()
    $c1   = $tail.IndexOf(':')
    if ($c1 -lt 0) { return "" }
    $level = $tail.Substring(0, $c1).Trim()

    $rest = $tail.Substring($c1 + 1).Trim()
    $c2   = $rest.IndexOf(':')
    if ($c2 -lt 0) { return "" }
    $id   = $rest.Substring(0, $c2).Trim()

    $rest = $rest.Substring($c2 + 1).Trim()
    if ($rest.Length -lt 19) { return "" }
    $stamp = $rest.Substring(0, 19)
    $msg   = $rest.Substring(19).Trim()

    if ($msg.StartsWith(':')) { $msg = $msg.Substring(1).Trim() }


    If($Level -eq "Verbose")
    {
      $levelKey  = "$level-$id"                               # Verbose-25, Verbose-19…
    }
    else
    { 
      $levelKey=$level
    }
    $delta = 0
    if ($msg -like 'Perf: Operation ended*' -and $Level -eq "Verbose") {
        # Ej.: "...elapsed in ms): StartImportTable,[schema].[table],58"
        $elapsedMs = ($msg.Split(',')[-1]).Trim()
        if ($elapsedMs -match '^\d+$') { $delta = [double]$elapsedMs / 1000 }
        $Verbose25[$msg] = @{ ElapsedTime = [double]$elapsedMs / 1000 }
        $prevStamp.Value = [datetime]$stamp
    }
    else {
        $curr = [datetime]$stamp
        if ($prevStamp.Value) { $delta = ($curr - $prevStamp.Value).TotalSeconds }
        $prevStamp.Value = $curr
    }

    # ---- Update the summary  -----------------------------------------------
    if (-not $stats.ContainsKey($levelKey)) {
        $stats[$levelKey] = @{ Count = 0; Total = 0 }
    }
    $stats[$levelKey].Count++
    $stats[$levelKey].Total += $delta

    return "$levelKey $delta $($msg.Trim())"
}

# Read and show line (every 5000)

Get-Content -Path $logPath -ReadCount 5000 | ForEach-Object {
    foreach ($line in $_) {
        $Lines++
        $Salida = Process-Line -line $line -prevStamp ([ref]$prevStamp)

        if ($Salida) 
         { 
           $deltaToken = [double]($Salida.Split()[1])
           if ($deltaToken -gt 10) {
              Write-Warning "$Lines $Salida"
           }

           if ($Lines % 5000 -eq 0 -and $Salida) {
              Write-Output "$Lines Text: $Salida"
           }
         }
    }
}

Write-Output "`n--- Summary per Level -----------------------------------------"

Write-Output "Lines Read: $Lines"

$stats.GetEnumerator() |
    Sort-Object Name |
    ForEach-Object {
        [pscustomobject]@{
            Level        = $_.Name
            Operations   = $_.Value.Count
            TotalTimeSec = [math]::Round($_.Value.Total, 3)
        }
    } |
    Format-Table -AutoSize

Write-Output "`n--- Verbose-25 Operations -------------------------------------"

$Verbose25.GetEnumerator() |
    Sort-Object @{ Expression = { [double]$_.Value.ElapsedTime }; Descending = $true } |
    ForEach-Object {
        [pscustomobject]@{
            Operation       = $_.Name
            ElapsedTimeSec  = [double]$_.Value.ElapsedTime
        }
    } |
    Format-Table -AutoSize

Examples: