Skip to content

Commit ccf6357

Browse files
KelvinTegelaarKelvinTegelaar
committed
add stopwatches for checking timings
1 parent bbd4241 commit ccf6357

File tree

1 file changed

+52
-0
lines changed

1 file changed

+52
-0
lines changed

‎Modules/CIPPCore/Public/Entrypoints/Activity Triggers/Webhooks/Push-AuditLogIngestion.ps1‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,9 @@ function Push-AuditLogIngestion {
99
$TenantId = $Item.TenantId
1010
$ContentTypes = $Item.ContentTypes
1111

12+
$Timings = @{}
13+
$TotalStopwatch = [System.Diagnostics.Stopwatch]::StartNew()
14+
1215
try {
1316
if (!$ContentTypes -or $ContentTypes.Count -eq 0) {
1417
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message 'No content types specified' -sev Warn
@@ -17,19 +20,26 @@ function Push-AuditLogIngestion {
1720

1821
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message 'Starting Management API ingestion for tenant' -sev Info
1922

23+
$SwInit = [System.Diagnostics.Stopwatch]::StartNew()
2024
$AuditLogStateTable = Get-CippTable -TableName 'AuditLogState'
2125
$CacheWebhooksTable = Get-CippTable -TableName 'CacheWebhooks'
26+
$SwInit.Stop()
27+
$Timings['Initialization'] = $SwInit.Elapsed.TotalMilliseconds
2228

29+
$SwStateLoad = [System.Diagnostics.Stopwatch]::StartNew()
2330
$StateCache = @{}
2431
$StateUpdates = @{}
2532
foreach ($ContentType in $ContentTypes) {
2633
$StateRowKey = "$TenantFilter-$ContentType"
2734
$StateEntity = Get-CIPPAzDataTableEntity @AuditLogStateTable -Filter "PartitionKey eq 'AuditLogState' and RowKey eq '$StateRowKey'"
2835
$StateCache[$ContentType] = $StateEntity
2936
}
37+
$SwStateLoad.Stop()
38+
$Timings['StateLoad'] = $SwStateLoad.Elapsed.TotalMilliseconds
3039

3140
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Content types to process: $($ContentTypes -join ', ')" -sev Info
3241

42+
$SwSubscriptionCheck = [System.Diagnostics.Stopwatch]::StartNew()
3343
$ContentTypesNeedingSubscription = [System.Collections.Generic.List[string]]::new()
3444
$EnabledContentTypes = [System.Collections.Generic.List[string]]::new()
3545

@@ -44,7 +54,10 @@ function Push-AuditLogIngestion {
4454

4555
$ContentTypesNeedingSubscription.Add($ContentType)
4656
}
57+
$SwSubscriptionCheck.Stop()
58+
$Timings['SubscriptionCheck'] = $SwSubscriptionCheck.Elapsed.TotalMilliseconds
4759

60+
$SwSubscriptionSetup = [System.Diagnostics.Stopwatch]::StartNew()
4861
foreach ($ContentType in $ContentTypesNeedingSubscription) {
4962
$StateRowKey = "$TenantFilter-$ContentType"
5063
$StateEntity = $StateCache[$ContentType]
@@ -113,6 +126,8 @@ function Push-AuditLogIngestion {
113126
}
114127
}
115128
}
129+
$SwSubscriptionSetup.Stop()
130+
$Timings['SubscriptionSetup'] = $SwSubscriptionSetup.Elapsed.TotalMilliseconds
116131

117132
if ($EnabledContentTypes.Count -eq 0) {
118133
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message 'No enabled content types to process' -sev Warn
@@ -126,6 +141,11 @@ function Push-AuditLogIngestion {
126141
$TotalProcessedRecords = 0
127142
$Now = Get-Date
128143

144+
$SwContentList = 0
145+
$SwContentFilter = 0
146+
$SwBlobDownload = 0
147+
$SwRecordCache = 0
148+
129149
foreach ($ContentType in $EnabledContentTypes) {
130150
try {
131151
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Processing content type: $ContentType" -sev Debug
@@ -145,18 +165,23 @@ function Push-AuditLogIngestion {
145165
TenantId = $TenantFilter
146166
}
147167

168+
$SwList = [System.Diagnostics.Stopwatch]::StartNew()
148169
try {
149170
$ContentList = New-GraphGetRequest @ContentParams -ErrorAction Stop
150171
} catch {
151172
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Failed to list content for $ContentType : $($_.Exception.Message)" -sev Error
152173
continue
153174
}
175+
$SwList.Stop()
176+
$SwContentList += $SwList.Elapsed.TotalMilliseconds
154177

155178
if (!$ContentList -or ($ContentList | Measure-Object).Count -eq 0) {
156179
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "No new content available for $ContentType" -sev Debug
157180
continue
158181
}
159182
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Found $($ContentList.Count) content blobs for $ContentType" -sev Info
183+
184+
$SwFilter = [System.Diagnostics.Stopwatch]::StartNew()
160185
$NewContentItems = if ($StateEntity -and $StateEntity.LastContentId) {
161186
$LastContentCreated = [DateTime]$StateEntity.LastContentCreatedUtc
162187
$LastContentId = $StateEntity.LastContentId
@@ -171,6 +196,8 @@ function Push-AuditLogIngestion {
171196
} else {
172197
$ContentList
173198
}
199+
$SwFilter.Stop()
200+
$SwContentFilter += $SwFilter.Elapsed.TotalMilliseconds
174201

175202
if (($NewContentItems | Measure-Object).Count -eq 0) {
176203
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "No new content items for $ContentType (all already processed)" -sev Debug
@@ -187,6 +214,7 @@ function Push-AuditLogIngestion {
187214
try {
188215
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Downloading content blob for $ContentType" -sev Debug
189216

217+
$SwBlob = [System.Diagnostics.Stopwatch]::StartNew()
190218
$BlobParams = @{
191219
scope = 'https://manage.office.com/.default'
192220
Uri = $ContentItem.contentUri
@@ -200,6 +228,8 @@ function Push-AuditLogIngestion {
200228
} else {
201229
$AuditRecords = $BlobResponse
202230
}
231+
$SwBlob.Stop()
232+
$SwBlobDownload += $SwBlob.Elapsed.TotalMilliseconds
203233

204234
if (!$AuditRecords) {
205235
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "No records in blob for $ContentType" -sev Warn
@@ -208,6 +238,7 @@ function Push-AuditLogIngestion {
208238

209239
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Caching $($AuditRecords.Count) audit records for $ContentType" -sev Debug
210240

241+
$SwCache = [System.Diagnostics.Stopwatch]::StartNew()
211242
$CacheEntities = [System.Collections.Generic.List[hashtable]]::new()
212243
foreach ($Record in $AuditRecords) {
213244
$CacheEntities.Add(@{
@@ -227,6 +258,8 @@ function Push-AuditLogIngestion {
227258
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Failed to batch cache records for $ContentType : $($_.Exception.Message)" -sev Error
228259
}
229260
}
261+
$SwCache.Stop()
262+
$SwRecordCache += $SwCache.Elapsed.TotalMilliseconds
230263

231264
$ContentCreated = [DateTime]$ContentItem.contentCreated
232265
if (!$LatestContentCreated -or $ContentCreated -gt $LatestContentCreated) {
@@ -264,11 +297,30 @@ function Push-AuditLogIngestion {
264297
continue
265298
}
266299
}
300+
301+
$Timings['ContentList'] = $SwContentList
302+
$Timings['ContentFilter'] = $SwContentFilter
303+
$Timings['BlobDownload'] = $SwBlobDownload
304+
$Timings['RecordCache'] = $SwRecordCache
267305

306+
$SwStateWrite = [System.Diagnostics.Stopwatch]::StartNew()
268307
if ($StateUpdates.Count -gt 0) {
269308
$UpdateEntities = @($StateUpdates.Values)
270309
Add-CIPPAzDataTableEntity @AuditLogStateTable -Entity $UpdateEntities -Force
271310
}
311+
$SwStateWrite.Stop()
312+
$Timings['StateWrite'] = $SwStateWrite.Elapsed.TotalMilliseconds
313+
314+
$TotalStopwatch.Stop()
315+
$TotalMs = $TotalStopwatch.Elapsed.TotalMilliseconds
316+
317+
$TimingReport = "AUDITLOG: Total: $([math]::Round($TotalMs, 2))ms"
318+
foreach ($Key in ($Timings.Keys | Sort-Object)) {
319+
$Ms = [math]::Round($Timings[$Key], 2)
320+
$Pct = [math]::Round(($Timings[$Key] / $TotalMs) * 100, 1)
321+
$TimingReport += " | $Key : $Ms ms ($Pct %)"
322+
}
323+
Write-Host $TimingReport
272324

273325
Write-LogMessage -API 'AuditLogIngestion' -tenant $TenantFilter -message "Completed ingestion: $TotalProcessedRecords total records cached" -sev Info
274326

0 commit comments

Comments
 (0)