Skip to content

Make benchmark tool record multiple attribute record separately, Fixes AB#3429544 #2815

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 5 commits into
base: dev
Choose a base branch
from
+143 −143
Draft

Make benchmark tool record multiple attribute record separately, Fixes AB#3429544 #2815

Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
60adf3f
Make tool record multiple attribute record separately
rpdome Nov 17, 2025
5480c91
Update common4j/src/main/com/microsoft/identity/common/java/opentelem…
rpdome Nov 18, 2025
b897763
Merge branch 'dev' into rapong/toolFix
rpdome Nov 18, 2025
5b97214
tweak
rpdome Nov 18, 2025
bc46512
wip
rpdome Nov 18, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
286 changes: 143 additions & 143 deletions .../src/main/com/microsoft/identity/common/java/opentelemetry/DefaultBenchmarkSpanPrinter.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -106,82 +106,117 @@ class DefaultBenchmarkSpanPrinter(
val file = getFile(spanName)

FileWriter(file, true).use { writer ->
// Write statistics for the spans (averages, percentiles, etc.)
val statisticalData = calculateStatistics(spans)

if (statisticalData.isEmpty()) {
val timestamp = DATE_FORMAT.format(Date())
writer.appendLine("| $timestamp | N/A | No status entries recorded (batch size: ${spans.size})")
return@use
}
// Separate spans into two groups: with exceptions and without exceptions
val spansWithExceptions = spans.filter { it.getException() != null }
val spansWithoutExceptions = spans.filter { it.getException() == null }

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

// Calculate total duration using dedicated end times (convert nanoseconds to milliseconds)
val totalDurationFormatted = spans.mapNotNull { span ->
val spanStartTime = span.getStartTimeInNanoSeconds()
val spanEndTime = span.getEndTimeInNanoSeconds()
if (spanEndTime > 0) { // Only include spans that have been ended
TimeUnit.NANOSECONDS.toMillis(spanEndTime - spanStartTime)
} else null
}.let { durations ->
if (durations.isNotEmpty()) {
val avgDuration = durations.average().toLong()
"${avgDuration}ms"
} else {
"N/A"
}
// Write statistics for spans WITHOUT exceptions
if (spansWithoutExceptions.isNotEmpty()) {
writeSpanGroupStatistics(writer, spansWithoutExceptions, "SUCCESS FLOWS (No Exceptions)")
}

// Calculate average concurrent size
val avgConcurrentSize = spans.map { it.getConcurrentSilentRequestSize() }.average()
val avgConcurrentSizeFormatted = String.format(Locale.US, "%.2f", avgConcurrentSize)
// Write statistics for spans WITH exceptions, grouped by exception message
if (spansWithExceptions.isNotEmpty()) {
writeSpanGroupsByExceptionMessage(writer, spansWithExceptions)
}

writer.appendLine("")
writer.appendLine("=== Statistical Benchmark Session: $formattedTimestamp | Avg Total Duration: $totalDurationFormatted | Avg Concurrent Size: $avgConcurrentSizeFormatted | Batch Size: ${spans.size} ===")
writer.appendLine("")
writer.flush()
}
} catch (e: IOException) {
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)
}
}

/**
* Write statistical data for a specific group of spans
*/
private fun writeSpanGroupStatistics(writer: FileWriter, spans: List<IBenchmarkSpan>, groupTitle: String) {
val statisticalData = calculateStatistics(spans)

writer.appendLine("| Status Entry | Metric | Time Since Previous | Time Since Start |")
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
if (statisticalData.isEmpty()) {
writer.appendLine("=== $groupTitle ===")
writer.appendLine("No status entries recorded for this group (${spans.size} spans)")
writer.appendLine("")
return
}

statisticalData.forEach { statsData ->
val paddedStatus = statsData.statusName.take(48).padEnd(48)
// Calculate group-specific metrics
val totalDurationFormatted = spans.mapNotNull { span ->
val spanStartTime = span.getStartTimeInNanoSeconds()
val spanEndTime = span.getEndTimeInNanoSeconds()
if (spanEndTime > 0) {
TimeUnit.NANOSECONDS.toMillis(spanEndTime - spanStartTime)
} else null
}.let { durations ->
if (durations.isNotEmpty()) {
val avgDuration = durations.average().toLong()
"${avgDuration}ms"
} else {
"N/A"
}
}

// Print only the configured metrics
metricsToDisplay.forEach { metricType ->
val metricLabel = metricType.displayName.padEnd(6)
val sincePrevValue = getMetricValue(statsData.timeSincePreviousStats, metricType).padEnd(19)
val sinceStartValue = getMetricValue(statsData.timeSinceStartStats, metricType).padEnd(16)
val avgConcurrentSize = spans.map { it.getConcurrentSilentRequestSize() }.average()
val avgConcurrentSizeFormatted = String.format(Locale.US, "%.2f", avgConcurrentSize)

val statusColumn = if (metricType == metricsToDisplay.first()) {
paddedStatus
} else {
"".padEnd(48)
}
writer.appendLine("=== $groupTitle ===")
writer.appendLine("Avg Total Duration: $totalDurationFormatted | Avg Concurrent Size: $avgConcurrentSizeFormatted | Spans: ${spans.size}")
writer.appendLine("")

writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue | $sinceStartValue |")
}
writer.appendLine("| Status Entry | Metric | Time Since Previous |")
writer.appendLine("|--------------------------------------------------|--------|---------------------|")

// Separator line between status entries
writer.appendLine("|--------------------------------------------------|--------|---------------------|------------------|")
}
statisticalData.forEach { statsData ->
val paddedStatus = statsData.statusName.take(48).padEnd(48)

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

// Check if any status contains "recordException" and print slowest exceptions
val hasExceptions = statisticalData.any { it.statusName == "recordException" }
if (hasExceptions) {
writeSlowestExceptions(writer, spans)
val statusColumn = if (metricType == metricsToDisplay.first()) {
paddedStatus
} else {
"".padEnd(48)
}

writer.flush()
writer.appendLine("| $statusColumn | $metricLabel | $sincePrevValue |")
}
} catch (e: IOException) {
Logger.error(TAG, "IOException while writing averaged batch to file: $outputDirectoryAbsolutePath", e)

// Separator line between status entries
writer.appendLine("|--------------------------------------------------|--------|---------------------|")
}

writer.appendLine("")
}

/**
* Write separate statistical tables for each unique exception message
*/
private fun writeSpanGroupsByExceptionMessage(writer: FileWriter, spansWithExceptions: List<IBenchmarkSpan>) {
// Group spans by exception message
val spansByExceptionMessage = spansWithExceptions.groupBy { span ->
val exception = span.getException()
val exceptionMessage = exception?.message ?: "Unknown Error"
val exceptionType = exception?.javaClass?.simpleName ?: "Unknown"
"$exceptionType: $exceptionMessage"
}

// Write a table for each exception message group
spansByExceptionMessage.entries.sortedBy { it.key }.forEachIndexed { index, (exceptionMessage, spans) ->
val groupTitle = "ERROR FLOWS - ${exceptionMessage.take(60)}"
writeSpanGroupStatistics(writer, spans, groupTitle)
}
}



/**
* Get a file to write the benchmark result to.
* Separate file for each span name.
Expand All @@ -206,120 +241,88 @@ class DefaultBenchmarkSpanPrinter(
.takeIf { it.isNotEmpty() } ?: "span"
}

/**
* Print the 5 slowest exceptions (if any) in the batch.
**/
private fun writeSlowestExceptions(writer: FileWriter, spans: List<IBenchmarkSpan>) {
// Collect all exception timings across all spans
data class ExceptionTiming(val spanIndex: Int, val timeSinceStartMs: Long, val exception: Throwable)

val exceptionTimings = mutableListOf<ExceptionTiming>()

spans.forEachIndexed { index, span ->
val exception = span.getException()
if (exception != null) {
val statuses = span.getStatuses()
val startTime = span.getStartTimeInNanoSeconds()

// Find the recordException status to get the timestamp
val exceptionStatus = statuses.find { it.first == "recordException" }
if (exceptionStatus != null) {
val timeSinceStartMs = TimeUnit.NANOSECONDS.toMillis(exceptionStatus.second - startTime)
exceptionTimings.add(ExceptionTiming(index + 1, timeSinceStartMs, exception))
}
}
}

if (exceptionTimings.isNotEmpty()) {
// Sort by time since start (descending) and take top 5
val slowestExceptions = exceptionTimings.sortedByDescending { it.timeSinceStartMs }.take(5)

writer.appendLine("=== 5 Slowest Exceptions (Time Since Start) ===")
writer.appendLine("")
writer.appendLine("| Rank | Span # | Time Since Start | Exception Type | Message ")
writer.appendLine("|------|--------|------------------|------------------------------------------|------------------------------------------")

slowestExceptions.forEachIndexed { rank, exceptionData ->
val rankStr = (rank + 1).toString().padEnd(4)
val spanNumStr = exceptionData.spanIndex.toString().padEnd(6)
val timeStr = "${exceptionData.timeSinceStartMs}ms".padEnd(16)
val exceptionType = exceptionData.exception.javaClass.simpleName.take(40).padEnd(40)
val exceptionMessage = (exceptionData.exception.message ?: "N/A")
writer.appendLine("| $rankStr | $spanNumStr | $timeStr | $exceptionType | $exceptionMessage ")
}

writer.appendLine("")
}
}

/**
* Calculate statistical metrics (average, percentiles) for all status entries across the batch of spans.
*
* For each unique status name found across all spans, this method:
* For each status occurrence found across all spans (including duplicates), this method:
* 1. Collects timing values (time since previous status, time since start) from all spans
* 2. Calculates configured statistical metrics (e.g., Avg, P50, P75, P90)
* 3. Returns the results sorted by the first configured metric's time since start value
*
* Note: If the same status name appears multiple times, each occurrence is tracked separately
* with an enumeration (e.g., "status [1]", "status [2]").
*
* The "Time Since Previous" column shows the statistical timing for how long each status
* typically takes to execute relative to the previous status within individual spans.
* When aggregated across spans, these represent independent timing measurements.
*
* @param spans List of spans to analyze (all spans should have the same span name)
*
* @return List of statistical data for each unique status, sorted by the first configured metric's time since start
* @return List of statistical data for each status occurrence, sorted by the first configured metric's time since start
*/
private fun calculateStatistics(spans: List<IBenchmarkSpan>): List<StatisticalStatusData> {
if (spans.isEmpty()) return emptyList()

// Collect all unique status names across all spans
val allStatusNames = mutableSetOf<String>()
for (span in spans) {
for ((statusName, _) in span.getStatuses()) {
allStatusNames.add(statusName)
}
}
// Use LinkedHashMap to maintain insertion order based on first span's status appearances
val statusOccurrencesMap = linkedMapOf<String, MutableList<Long>>() // timeSincePrevious values

// Process first span to establish the order and which statuses to track
val firstSpan = spans.first()
val firstSpanStatuses = firstSpan.getStatuses()
val firstSpanStatusCounts = mutableMapOf<String, Int>()

val result = mutableListOf<StatisticalStatusData>()
// Initialize the map with statuses from the first span to establish order
firstSpanStatuses.forEach { (statusName, _) ->
val spanOccurrenceIndex = firstSpanStatusCounts.getOrDefault(statusName, 0) + 1
firstSpanStatusCounts[statusName] = spanOccurrenceIndex
val occurrenceStatusName = getStatusName(spanOccurrenceIndex, statusName)

for (statusName in allStatusNames) {
val timeSincePreviousValues = mutableListOf<Long>()
val timeSinceStartValues = mutableListOf<Long>()
// Initialize empty list for this status (maintains insertion order)
statusOccurrencesMap[occurrenceStatusName] = mutableListOf()
}

for (span in spans) {
val statuses = span.getStatuses()
val startTime = span.getStartTimeInNanoSeconds()
// Now process all spans (including the first one again) to collect timing data
for (span in spans) {
val statuses = span.getStatuses()
val startTime = span.getStartTimeInNanoSeconds()
val spanStatusCounts = mutableMapOf<String, Int>()

// Find this status in the span
val statusIndex = statuses.indexOfFirst { it.first == statusName }
if (statusIndex >= 0) {
val entry = statuses[statusIndex]
val timeSinceStartMs = TimeUnit.NANOSECONDS.toMillis(entry.second - startTime)
statuses.forEachIndexed { statusIndex, (statusName, timestamp) ->
val spanOccurrenceIndex = spanStatusCounts.getOrDefault(statusName, 0) + 1
spanStatusCounts[statusName] = spanOccurrenceIndex
val occurrenceStatusName = getStatusName(spanOccurrenceIndex, statusName)

// Only process if this status was in the first span (exists in our map)
statusOccurrencesMap[occurrenceStatusName]?.let {
val previousTime = if (statusIndex > 0) {
statuses[statusIndex - 1].second
} else {
startTime
}
val timeSincePreviousMs = TimeUnit.NANOSECONDS.toMillis(entry.second - previousTime)

timeSincePreviousValues.add(timeSincePreviousMs)
timeSinceStartValues.add(timeSinceStartMs)
val timeSincePreviousMs = TimeUnit.NANOSECONDS.toMillis(timestamp - previousTime)
it.add(timeSincePreviousMs)
}
}
}

if (timeSincePreviousValues.isNotEmpty()) {
result.add(
StatisticalStatusData(
statusName = statusName,
timeSinceStartStats = calculateMetrics(timeSinceStartValues),
timeSincePreviousStats = calculateMetrics(timeSincePreviousValues)
)
)
}
// LinkedHashMap maintains insertion order, so no sorting needed
return statusOccurrencesMap.map { (statusName, timingSincePrevsValues) ->
StatisticalStatusData(
statusName = statusName,
timeSincePreviousStats = calculateMetrics(timingSincePrevsValues)
)
}
}

// Sort by the first configured metric's Time Since Start value, or by status name if no metrics
return if (metricsToDisplay.isNotEmpty()) {
result.sortedBy { it.timeSinceStartStats[metricsToDisplay.first()] ?: 0L }
private fun getStatusName(spanOccurrenceIndex: Int, statusName: String): String {
val occurrenceStatusName = if (spanOccurrenceIndex > 1) {
"[$spanOccurrenceIndex] $statusName"
} else {
result.sortedBy { it.statusName }
statusName
}
return occurrenceStatusName
}

private fun calculateMetrics(values: List<Long>): Map<MetricType, Long> {
Expand Down Expand Up @@ -373,16 +376,13 @@ class DefaultBenchmarkSpanPrinter(
* Holds statistical data for a single status entry across multiple spans.
*
* This data class aggregates timing metrics for a specific status name,
* containing both "time since start" and "time since previous" statistics
* calculated across all spans in the batch.
* containing "time since previous" statistics calculated across all spans in the batch.
*
* @property statusName The name of the status entry (e.g., "acquireToken", "networkCall")
* @property timeSinceStartStats Map of metric type to value (in ms) for time elapsed from span start to this status
* @property timeSincePreviousStats Map of metric type to value (in ms) for time elapsed from previous status to this status
* @property statusName The name of the status entry (e.g., "acquireToken", "networkCall")
* @property timeSincePreviousStats Map of metric type to value (in ms) for time elapsed from previous status to this status
*/
data class StatisticalStatusData(
val statusName: String,
val timeSinceStartStats: Map<MetricType, Long>,
val timeSincePreviousStats: Map<MetricType, Long>
)

Expand Down
Loading