Skip to content

Commit 145560b

Browse files
rpdomerpdome
committed
wip
1 parent 5b97214 commit 145560b

File tree

1 file changed

+116
-92
lines changed

1 file changed

+116
-92
lines changed

‎common4j/src/main/com/microsoft/identity/common/java/opentelemetry/DefaultBenchmarkSpanPrinter.kt‎

Lines changed: 116 additions & 92 deletions
Original file line numberDiff line numberDiff line change
@@ -106,80 +106,97 @@ class DefaultBenchmarkSpanPrinter(
106106
val file = getFile(spanName)
107107

108108
FileWriter(file, true).use { writer ->
109-
// Write statistics for the spans (averages, percentiles, etc.)
110-
val statisticalData = calculateStatistics(spans)
111-
112-
if (statisticalData.isEmpty()) {
113-
val timestamp = DATE_FORMAT.format(Date())
114-
writer.appendLine("| $timestamp | N/A | No status entries recorded (batch size: ${spans.size})")
115-
return@use
116-
}
109+
// Separate spans into two groups: with exceptions and without exceptions
110+
val spansWithExceptions = spans.filter { it.getException() != null }
111+
val spansWithoutExceptions = spans.filter { it.getException() == null }
117112

118113
// Write session header
119114
val formattedTimestamp = DATE_FORMAT.format(Date(System.currentTimeMillis()))
115+
writer.appendLine("")
116+
writer.appendLine("=== Statistical Benchmark Session: $formattedTimestamp | Batch Size: ${spans.size} | With Exceptions: ${spansWithExceptions.size} | Without Exceptions: ${spansWithoutExceptions.size} ===")
117+
writer.appendLine("")
120118

121-
// Calculate total duration using dedicated end times (convert nanoseconds to milliseconds)
122-
val totalDurationFormatted = spans.mapNotNull { span ->
123-
val spanStartTime = span.getStartTimeInNanoSeconds()
124-
val spanEndTime = span.getEndTimeInNanoSeconds()
125-
if (spanEndTime > 0) { // Only include spans that have been ended
126-
TimeUnit.NANOSECONDS.toMillis(spanEndTime - spanStartTime)
127-
} else null
128-
}.let { durations ->
129-
if (durations.isNotEmpty()) {
130-
val avgDuration = durations.average().toLong()
131-
"${avgDuration}ms"
132-
} else {
133-
"N/A"
134-
}
119+
// Write statistics for spans WITHOUT exceptions
120+
if (spansWithoutExceptions.isNotEmpty()) {
121+
writeSpanGroupStatistics(writer, spansWithoutExceptions, "SUCCESS FLOWS (No Exceptions)")
135122
}
136123

137-
// Calculate average concurrent size
138-
val avgConcurrentSize = spans.map { it.getConcurrentSilentRequestSize() }.average()
139-
val avgConcurrentSizeFormatted = String.format(Locale.US, "%.2f", avgConcurrentSize)
124+
// Write statistics for spans WITH exceptions
125+
if (spansWithExceptions.isNotEmpty()) {
126+
writeSpanGroupStatistics(writer, spansWithExceptions, "ERROR FLOWS (With Exceptions)")
140127

141-
writer.appendLine("")
142-
writer.appendLine("=== Statistical Benchmark Session: $formattedTimestamp | Avg Total Duration: $totalDurationFormatted | Avg Concurrent Size: $avgConcurrentSizeFormatted | Batch Size: ${spans.size} ===")
143-
writer.appendLine("")
128+
// Also write the slowest exceptions for this group
129+
writeSlowestExceptions(writer, spansWithExceptions)
130+
}
144131

145-
writer.appendLine("| Status Entry | Metric | Time Since Previous | Time Since Start |")
146-
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
132+
writer.flush()
133+
}
134+
} catch (e: IOException) {
135+
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)
136+
}
137+
}
147138

148-
statisticalData.forEach { statsData ->
149-
val paddedStatus = statsData.statusName.take(48).padEnd(48)
139+
/**
140+
* Write statistical data for a specific group of spans
141+
*/
142+
private fun writeSpanGroupStatistics(writer: FileWriter, spans: List<IBenchmarkSpan>, groupTitle: String) {
143+
val statisticalData = calculateStatistics(spans)
150144

151-
// Print only the configured metrics
152-
metricsToDisplay.forEach { metricType ->
153-
val metricLabel = metricType.displayName.padEnd(6)
154-
val sincePrevValue = getMetricValue(statsData.timeSincePreviousStats, metricType).padEnd(19)
155-
val sinceStartValue = getMetricValue(statsData.timeSinceStartStats, metricType).padEnd(16)
145+
if (statisticalData.isEmpty()) {
146+
writer.appendLine("=== $groupTitle ===")
147+
writer.appendLine("No status entries recorded for this group (${spans.size} spans)")
148+
writer.appendLine("")
149+
return
150+
}
156151

157-
val statusColumn = if (metricType == metricsToDisplay.first()) {
158-
paddedStatus
159-
} else {
160-
"".padEnd(48)
161-
}
152+
// Calculate group-specific metrics
153+
val totalDurationFormatted = spans.mapNotNull { span ->
154+
val spanStartTime = span.getStartTimeInNanoSeconds()
155+
val spanEndTime = span.getEndTimeInNanoSeconds()
156+
if (spanEndTime > 0) {
157+
TimeUnit.NANOSECONDS.toMillis(spanEndTime - spanStartTime)
158+
} else null
159+
}.let { durations ->
160+
if (durations.isNotEmpty()) {
161+
val avgDuration = durations.average().toLong()
162+
"${avgDuration}ms"
163+
} else {
164+
"N/A"
165+
}
166+
}
162167

163-
writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue | $sinceStartValue |")
164-
}
168+
val avgConcurrentSize = spans.map { it.getConcurrentSilentRequestSize() }.average()
169+
val avgConcurrentSizeFormatted = String.format(Locale.US, "%.2f", avgConcurrentSize)
165170

166-
// Separator line between status entries
167-
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
168-
}
171+
writer.appendLine("=== $groupTitle ===")
172+
writer.appendLine("Avg Total Duration: $totalDurationFormatted | Avg Concurrent Size: $avgConcurrentSizeFormatted | Spans: ${spans.size}")
173+
writer.appendLine("")
169174

170-
writer.appendLine("")
175+
writer.appendLine("| Status Entry | Metric | Time Since Previous |")
176+
writer.appendLine("|--------------------------------------------------|--------|---------------------|")
177+
178+
statisticalData.forEach { statsData ->
179+
val paddedStatus = statsData.statusName.take(48).padEnd(48)
171180

172-
// Check if any status contains "recordException" and print slowest exceptions
173-
val hasExceptions = statisticalData.any { it.statusName == "recordException" }
174-
if (hasExceptions) {
175-
writeSlowestExceptions(writer, spans)
181+
// Print only the configured metrics
182+
metricsToDisplay.forEach { metricType ->
183+
val metricLabel = metricType.displayName.padEnd(6)
184+
val sincePrevValue = getMetricValue(statsData.timeSincePreviousStats, metricType).padEnd(19)
185+
186+
val statusColumn = if (metricType == metricsToDisplay.first()) {
187+
paddedStatus
188+
} else {
189+
"".padEnd(48)
176190
}
177191

178-
writer.flush()
192+
writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue |")
179193
}
180-
} catch (e: IOException) {
181-
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)
194+
195+
// Separator line between status entries
196+
writer.appendLine("|--------------------------------------------------|--------|---------------------|")
182197
}
198+
199+
writer.appendLine("")
183200
}
184201

185202
/**
@@ -263,31 +280,42 @@ class DefaultBenchmarkSpanPrinter(
263280
* Note: If the same status name appears multiple times, each occurrence is tracked separately
264281
* with an enumeration (e.g., "status [1]", "status [2]").
265282
*
283+
* The "Time Since Previous" column shows the statistical timing for how long each status
284+
* typically takes to execute relative to the previous status within individual spans.
285+
* When aggregated across spans, these represent independent timing measurements.
286+
*
266287
* @param spans List of spans to analyze (all spans should have the same span name)
267288
*
268289
* @return List of statistical data for each status occurrence, sorted by the first configured metric's time since start
269290
*/
270291
private fun calculateStatistics(spans: List<IBenchmarkSpan>): List<StatisticalStatusData> {
271292
if (spans.isEmpty()) return emptyList()
272293

273-
// Build a map of status position -> (display name, list of timing data)
274-
// We need to track each occurrence separately across all spans
275-
data class StatusOccurrence(val statusName: String, val occurrenceIndex: Int)
276-
val statusOccurrencesMap = mutableMapOf<StatusOccurrence, MutableList<Pair<Long, Long>>>() // Pair<timeSincePrevious, timeSinceStart>
294+
// Build a map of status name -> list of timing data
295+
// Status names are already occurrence-specific (e.g., "[2] SetStatus:ERROR" for second occurrence)
296+
val statusOccurrencesMap = mutableMapOf<String, MutableList<Long>>() // timeSincePrevious values
297+
298+
// Track the chronological positions of each status occurrence across spans
299+
val statusPositions = mutableMapOf<String, MutableList<Int>>()
277300

278301
for (span in spans) {
279302
val statuses = span.getStatuses()
280303
val startTime = span.getStartTimeInNanoSeconds()
281304

282-
// Track how many times we've seen each status name in this span
283-
val statusCounts = mutableMapOf<String, Int>()
305+
// Track how many times we've seen each status name in this specific span
306+
val spanStatusCounts = mutableMapOf<String, Int>()
284307

285308
statuses.forEachIndexed { statusIndex, (statusName, timestamp) ->
286-
// Determine which occurrence this is (1st, 2nd, 3rd, etc.)
287-
val occurrenceIndex = statusCounts.getOrDefault(statusName, 0) + 1
288-
statusCounts[statusName] = occurrenceIndex
309+
// Determine which occurrence this is within this span (1st, 2nd, 3rd, etc.)
310+
val spanOccurrenceIndex = spanStatusCounts.getOrDefault(statusName, 0) + 1
311+
spanStatusCounts[statusName] = spanOccurrenceIndex
289312

290-
val timeSinceStartMs = TimeUnit.NANOSECONDS.toMillis(timestamp - startTime)
313+
// Create the occurrence-specific status name if this is not the first occurrence
314+
val occurrenceStatusName = if (spanOccurrenceIndex > 1) {
315+
"[$spanOccurrenceIndex] $statusName"
316+
} else {
317+
statusName
318+
}
291319

292320
val previousTime = if (statusIndex > 0) {
293321
statuses[statusIndex - 1].second
@@ -296,40 +324,37 @@ class DefaultBenchmarkSpanPrinter(
296324
}
297325
val timeSincePreviousMs = TimeUnit.NANOSECONDS.toMillis(timestamp - previousTime)
298326

299-
val occurrence = StatusOccurrence(statusName, occurrenceIndex)
300-
statusOccurrencesMap.getOrPut(occurrence) { mutableListOf() }
301-
.add(Pair(timeSincePreviousMs, timeSinceStartMs))
327+
// Use the occurrence-specific status name as the key (no need for StatusOccurrence data class)
328+
statusOccurrencesMap.getOrPut(occurrenceStatusName) { mutableListOf() }
329+
.add(timeSincePreviousMs)
330+
331+
// Track the position of this status occurrence within the span
332+
statusPositions.getOrPut(occurrenceStatusName) { mutableListOf() }.add(statusIndex)
302333
}
303334
}
304335

305336
val result = mutableListOf<StatisticalStatusData>()
306337

307-
for ((occurrence, timingPairs) in statusOccurrencesMap) {
308-
val timeSincePreviousValues = timingPairs.map { it.first }
309-
val timeSinceStartValues = timingPairs.map { it.second }
310-
311-
// Create display name with occurrence number if there are multiple occurrences
312-
val displayName = if (occurrence.occurrenceIndex > 1) {
313-
"${occurrence.statusName} [${occurrence.occurrenceIndex}]"
338+
for ((statusName, timingSincePrevsValues) in statusOccurrencesMap) {
339+
// Calculate median chronological position for sorting
340+
val positions = statusPositions[statusName] ?: emptyList()
341+
val medianPosition = if (positions.isNotEmpty()) {
342+
positions.sorted()[positions.size / 2]
314343
} else {
315-
occurrence.statusName
344+
Int.MAX_VALUE
316345
}
317346

318347
result.add(
319348
StatisticalStatusData(
320-
statusName = displayName,
321-
timeSinceStartStats = calculateMetrics(timeSinceStartValues),
322-
timeSincePreviousStats = calculateMetrics(timeSincePreviousValues)
349+
statusName = statusName,
350+
timeSincePreviousStats = calculateMetrics(timingSincePrevsValues),
351+
medianChronologicalPosition = medianPosition
323352
)
324353
)
325354
}
326355

327-
// Sort by the first configured metric's Time Since Start value, or by status name if no metrics
328-
return if (metricsToDisplay.isNotEmpty()) {
329-
result.sortedBy { it.timeSinceStartStats[metricsToDisplay.first()] ?: 0L }
330-
} else {
331-
result.sortedBy { it.statusName }
332-
}
356+
// Sort by chronological order (median position within spans), then by status name for ties
357+
return result.sortedWith(compareBy({ it.medianChronologicalPosition }, { it.statusName }))
333358
}
334359

335360
private fun calculateMetrics(values: List<Long>): Map<MetricType, Long> {
@@ -383,17 +408,16 @@ class DefaultBenchmarkSpanPrinter(
383408
* Holds statistical data for a single status entry across multiple spans.
384409
*
385410
* This data class aggregates timing metrics for a specific status name,
386-
* containing both "time since start" and "time since previous" statistics
387-
* calculated across all spans in the batch.
411+
* containing "time since previous" statistics calculated across all spans in the batch.
388412
*
389-
* @property statusName The name of the status entry (e.g., "acquireToken", "networkCall")
390-
* @property timeSinceStartStats Map of metric type to value (in ms) for time elapsed from span start to this status
391-
* @property timeSincePreviousStats Map of metric type to value (in ms) for time elapsed from previous status to this status
413+
* @property statusName The name of the status entry (e.g., "acquireToken", "networkCall")
414+
* @property timeSincePreviousStats Map of metric type to value (in ms) for time elapsed from previous status to this status
415+
* @property medianChronologicalPosition The median position of this status within spans, used for chronological sorting
392416
*/
393417
data class StatisticalStatusData(
394418
val statusName: String,
395-
val timeSinceStartStats: Map<MetricType, Long>,
396-
val timeSincePreviousStats: Map<MetricType, Long>
419+
val timeSincePreviousStats: Map<MetricType, Long>,
420+
val medianChronologicalPosition: Int = Int.MAX_VALUE
397421
)
398422

399423
/**

0 commit comments

Comments
 (0)