Skip to content

Commit bc46512

Browse files
rpdomerpdome
committed
wip
1 parent 5b97214 commit bc46512

File tree

1 file changed

+140
-150
lines changed

1 file changed

+140
-150
lines changed

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

Lines changed: 140 additions & 150 deletions
Original file line numberDiff line numberDiff line change
@@ -106,82 +106,117 @@ 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, grouped by exception message
125+
if (spansWithExceptions.isNotEmpty()) {
126+
writeSpanGroupsByExceptionMessage(writer, spansWithExceptions)
127+
}
140128

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("")
129+
writer.flush()
130+
}
131+
} catch (e: IOException) {
132+
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)
133+
}
134+
}
144135

145-
writer.appendLine("| Status Entry | Metric | Time Since Previous | Time Since Start |")
146-
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
136+
/**
137+
* Write statistical data for a specific group of spans
138+
*/
139+
private fun writeSpanGroupStatistics(writer: FileWriter, spans: List<IBenchmarkSpan>, groupTitle: String) {
140+
val statisticalData = calculateStatistics(spans)
141+
142+
if (statisticalData.isEmpty()) {
143+
writer.appendLine("=== $groupTitle ===")
144+
writer.appendLine("No status entries recorded for this group (${spans.size} spans)")
145+
writer.appendLine("")
146+
return
147+
}
147148

148-
statisticalData.forEach { statsData ->
149-
val paddedStatus = statsData.statusName.take(48).padEnd(48)
149+
// Calculate group-specific metrics
150+
val totalDurationFormatted = spans.mapNotNull { span ->
151+
val spanStartTime = span.getStartTimeInNanoSeconds()
152+
val spanEndTime = span.getEndTimeInNanoSeconds()
153+
if (spanEndTime > 0) {
154+
TimeUnit.NANOSECONDS.toMillis(spanEndTime - spanStartTime)
155+
} else null
156+
}.let { durations ->
157+
if (durations.isNotEmpty()) {
158+
val avgDuration = durations.average().toLong()
159+
"${avgDuration}ms"
160+
} else {
161+
"N/A"
162+
}
163+
}
150164

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)
165+
val avgConcurrentSize = spans.map { it.getConcurrentSilentRequestSize() }.average()
166+
val avgConcurrentSizeFormatted = String.format(Locale.US, "%.2f", avgConcurrentSize)
156167

157-
val statusColumn = if (metricType == metricsToDisplay.first()) {
158-
paddedStatus
159-
} else {
160-
"".padEnd(48)
161-
}
168+
writer.appendLine("=== $groupTitle ===")
169+
writer.appendLine("Avg Total Duration: $totalDurationFormatted | Avg Concurrent Size: $avgConcurrentSizeFormatted | Spans: ${spans.size}")
170+
writer.appendLine("")
162171

163-
writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue | $sinceStartValue |")
164-
}
172+
writer.appendLine("| Status Entry | Metric | Time Since Previous |")
173+
writer.appendLine("|--------------------------------------------------|--------|---------------------|")
165174

166-
// Separator line between status entries
167-
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
168-
}
175+
statisticalData.forEach { statsData ->
176+
val paddedStatus = statsData.statusName.take(48).padEnd(48)
169177

170-
writer.appendLine("")
178+
// Print only the configured metrics
179+
metricsToDisplay.forEach { metricType ->
180+
val metricLabel = metricType.displayName.padEnd(6)
181+
val sincePrevValue = getMetricValue(statsData.timeSincePreviousStats, metricType).padEnd(19)
171182

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)
183+
val statusColumn = if (metricType == metricsToDisplay.first()) {
184+
paddedStatus
185+
} else {
186+
"".padEnd(48)
176187
}
177188

178-
writer.flush()
189+
writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue |")
179190
}
180-
} catch (e: IOException) {
181-
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)
191+
192+
// Separator line between status entries
193+
writer.appendLine("|--------------------------------------------------|--------|---------------------|")
182194
}
195+
196+
writer.appendLine("")
183197
}
184198

199+
/**
200+
* Write separate statistical tables for each unique exception message
201+
*/
202+
private fun writeSpanGroupsByExceptionMessage(writer: FileWriter, spansWithExceptions: List<IBenchmarkSpan>) {
203+
// Group spans by exception message
204+
val spansByExceptionMessage = spansWithExceptions.groupBy { span ->
205+
val exception = span.getException()
206+
val exceptionMessage = exception?.message ?: "Unknown Error"
207+
val exceptionType = exception?.javaClass?.simpleName ?: "Unknown"
208+
"$exceptionType: $exceptionMessage"
209+
}
210+
211+
// Write a table for each exception message group
212+
spansByExceptionMessage.entries.sortedBy { it.key }.forEachIndexed { index, (exceptionMessage, spans) ->
213+
val groupTitle = "ERROR FLOWS - ${exceptionMessage.take(60)}"
214+
writeSpanGroupStatistics(writer, spans, groupTitle)
215+
}
216+
}
217+
218+
219+
185220
/**
186221
* Get a file to write the benchmark result to.
187222
* Separate file for each span name.
@@ -206,51 +241,7 @@ class DefaultBenchmarkSpanPrinter(
206241
.takeIf { it.isNotEmpty() } ?: "span"
207242
}
208243

209-
/**
210-
* Print the 5 slowest exceptions (if any) in the batch.
211-
**/
212-
private fun writeSlowestExceptions(writer: FileWriter, spans: List<IBenchmarkSpan>) {
213-
// Collect all exception timings across all spans
214-
data class ExceptionTiming(val spanIndex: Int, val timeSinceStartMs: Long, val exception: Throwable)
215-
216-
val exceptionTimings = mutableListOf<ExceptionTiming>()
217244

218-
spans.forEachIndexed { index, span ->
219-
val exception = span.getException()
220-
if (exception != null) {
221-
val statuses = span.getStatuses()
222-
val startTime = span.getStartTimeInNanoSeconds()
223-
224-
// Find the recordException status to get the timestamp
225-
val exceptionStatus = statuses.find { it.first == "recordException" }
226-
if (exceptionStatus != null) {
227-
val timeSinceStartMs = TimeUnit.NANOSECONDS.toMillis(exceptionStatus.second - startTime)
228-
exceptionTimings.add(ExceptionTiming(index + 1, timeSinceStartMs, exception))
229-
}
230-
}
231-
}
232-
233-
if (exceptionTimings.isNotEmpty()) {
234-
// Sort by time since start (descending) and take top 5
235-
val slowestExceptions = exceptionTimings.sortedByDescending { it.timeSinceStartMs }.take(5)
236-
237-
writer.appendLine("=== 5 Slowest Exceptions (Time Since Start) ===")
238-
writer.appendLine("")
239-
writer.appendLine("| Rank | Span # | Time Since Start | Exception Type | Message ")
240-
writer.appendLine("|------|--------|------------------|------------------------------------------|------------------------------------------")
241-
242-
slowestExceptions.forEachIndexed { rank, exceptionData ->
243-
val rankStr = (rank + 1).toString().padEnd(4)
244-
val spanNumStr = exceptionData.spanIndex.toString().padEnd(6)
245-
val timeStr = "${exceptionData.timeSinceStartMs}ms".padEnd(16)
246-
val exceptionType = exceptionData.exception.javaClass.simpleName.take(40).padEnd(40)
247-
val exceptionMessage = (exceptionData.exception.message ?: "N/A")
248-
writer.appendLine("| $rankStr | $spanNumStr | $timeStr | $exceptionType | $exceptionMessage ")
249-
}
250-
251-
writer.appendLine("")
252-
}
253-
}
254245

255246
/**
256247
* Calculate statistical metrics (average, percentiles) for all status entries across the batch of spans.
@@ -263,73 +254,75 @@ class DefaultBenchmarkSpanPrinter(
263254
* Note: If the same status name appears multiple times, each occurrence is tracked separately
264255
* with an enumeration (e.g., "status [1]", "status [2]").
265256
*
257+
* The "Time Since Previous" column shows the statistical timing for how long each status
258+
* typically takes to execute relative to the previous status within individual spans.
259+
* When aggregated across spans, these represent independent timing measurements.
260+
*
266261
* @param spans List of spans to analyze (all spans should have the same span name)
267262
*
268263
* @return List of statistical data for each status occurrence, sorted by the first configured metric's time since start
269264
*/
270265
private fun calculateStatistics(spans: List<IBenchmarkSpan>): List<StatisticalStatusData> {
271266
if (spans.isEmpty()) return emptyList()
272267

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>
268+
// Use LinkedHashMap to maintain insertion order based on first span's status appearances
269+
val statusOccurrencesMap = linkedMapOf<String, MutableList<Long>>() // timeSincePrevious values
270+
271+
// Process first span to establish the order and which statuses to track
272+
val firstSpan = spans.first()
273+
val firstSpanStatuses = firstSpan.getStatuses()
274+
val firstSpanStatusCounts = mutableMapOf<String, Int>()
275+
276+
// Initialize the map with statuses from the first span to establish order
277+
firstSpanStatuses.forEach { (statusName, _) ->
278+
val spanOccurrenceIndex = firstSpanStatusCounts.getOrDefault(statusName, 0) + 1
279+
firstSpanStatusCounts[statusName] = spanOccurrenceIndex
280+
val occurrenceStatusName = getStatusName(spanOccurrenceIndex, statusName)
281+
282+
// Initialize empty list for this status (maintains insertion order)
283+
statusOccurrencesMap[occurrenceStatusName] = mutableListOf()
284+
}
277285

286+
// Now process all spans (including the first one again) to collect timing data
278287
for (span in spans) {
279288
val statuses = span.getStatuses()
280289
val startTime = span.getStartTimeInNanoSeconds()
281-
282-
// Track how many times we've seen each status name in this span
283-
val statusCounts = mutableMapOf<String, Int>()
290+
val spanStatusCounts = mutableMapOf<String, Int>()
284291

285292
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
289-
290-
val timeSinceStartMs = TimeUnit.NANOSECONDS.toMillis(timestamp - startTime)
291-
292-
val previousTime = if (statusIndex > 0) {
293-
statuses[statusIndex - 1].second
294-
} else {
295-
startTime
293+
val spanOccurrenceIndex = spanStatusCounts.getOrDefault(statusName, 0) + 1
294+
spanStatusCounts[statusName] = spanOccurrenceIndex
295+
val occurrenceStatusName = getStatusName(spanOccurrenceIndex, statusName)
296+
297+
// Only process if this status was in the first span (exists in our map)
298+
statusOccurrencesMap[occurrenceStatusName]?.let {
299+
val previousTime = if (statusIndex > 0) {
300+
statuses[statusIndex - 1].second
301+
} else {
302+
startTime
303+
}
304+
val timeSincePreviousMs = TimeUnit.NANOSECONDS.toMillis(timestamp - previousTime)
305+
it.add(timeSincePreviousMs)
296306
}
297-
val timeSincePreviousMs = TimeUnit.NANOSECONDS.toMillis(timestamp - previousTime)
298-
299-
val occurrence = StatusOccurrence(statusName, occurrenceIndex)
300-
statusOccurrencesMap.getOrPut(occurrence) { mutableListOf() }
301-
.add(Pair(timeSincePreviousMs, timeSinceStartMs))
302307
}
303308
}
304309

305-
val result = mutableListOf<StatisticalStatusData>()
306-
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}]"
314-
} else {
315-
occurrence.statusName
316-
}
317-
318-
result.add(
319-
StatisticalStatusData(
320-
statusName = displayName,
321-
timeSinceStartStats = calculateMetrics(timeSinceStartValues),
322-
timeSincePreviousStats = calculateMetrics(timeSincePreviousValues)
323-
)
310+
// LinkedHashMap maintains insertion order, so no sorting needed
311+
return statusOccurrencesMap.map { (statusName, timingSincePrevsValues) ->
312+
StatisticalStatusData(
313+
statusName = statusName,
314+
timeSincePreviousStats = calculateMetrics(timingSincePrevsValues)
324315
)
325316
}
317+
}
326318

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 }
319+
private fun getStatusName(spanOccurrenceIndex: Int, statusName: String): String {
320+
val occurrenceStatusName = if (spanOccurrenceIndex > 1) {
321+
"[$spanOccurrenceIndex] $statusName"
330322
} else {
331-
result.sortedBy { it.statusName }
323+
statusName
332324
}
325+
return occurrenceStatusName
333326
}
334327

335328
private fun calculateMetrics(values: List<Long>): Map<MetricType, Long> {
@@ -383,16 +376,13 @@ class DefaultBenchmarkSpanPrinter(
383376
* Holds statistical data for a single status entry across multiple spans.
384377
*
385378
* 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.
379+
* containing "time since previous" statistics calculated across all spans in the batch.
388380
*
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
381+
* @property statusName The name of the status entry (e.g., "acquireToken", "networkCall")
382+
* @property timeSincePreviousStats Map of metric type to value (in ms) for time elapsed from previous status to this status
392383
*/
393384
data class StatisticalStatusData(
394385
val statusName: String,
395-
val timeSinceStartStats: Map<MetricType, Long>,
396386
val timeSincePreviousStats: Map<MetricType, Long>
397387
)
398388

0 commit comments

Comments
 (0)