prover.cs

using System.Diagnostics;
using System.Net.Http.Headers;
using System.Text.Json;
using System.Text.RegularExpressions;

/// <summary>
/// Proves that AzDO's reported duration for grouped parameterized tests is NOT
/// the sum of individual variant execution times.
///
/// Approach:
///   1. Parse a Helix console log to get actual per-variant execution times.
///   2. Group variants by base method name and sum their durations.
///   3. Query AzDO test results for the same build/run to get reported durations.
///   4. Compare: AzDO reported time vs actual summed variant time.
/// </summary>

var helixLogPath = args.Length > 0 ? args[0] : "/tmp/helix_console.log";
if (!File.Exists(helixLogPath))
{
    Console.Error.WriteLine($"Helix log not found: {helixLogPath}");
    Console.Error.WriteLine("Usage: dotnet run [helix-log-path]");
    return 1;
}

// --- Step 1: Parse actual test times from the Helix console log ---
Console.WriteLine("Step 1: Parsing actual test execution times from Helix log...");
var testPattern = new Regex(@"^\s+(Passed|Failed|Skipped)\s+(.+?)\s+\[([^\]]+)\]$");
var actualTests = new List<(string FullName, double DurationMs)>();

foreach (var line in File.ReadLines(helixLogPath))
{
    var match = testPattern.Match(line);
    if (match.Success)
    {
        var fullName = match.Groups[2].Value;
        var durationMs = ParseDurationMs(match.Groups[3].Value.Trim());
        actualTests.Add((fullName, durationMs));
    }
}

Console.WriteLine($"  Parsed {actualTests.Count} test results from Helix log");

// --- Step 2: Group parameterized tests by base name and sum durations ---
Console.WriteLine("\nStep 2: Grouping parameterized variants by base method name...");

static string StripParams(string name)
{
    var parenIndex = name.IndexOf('(');
    return parenIndex >= 0 ? name[..parenIndex] : name;
}

var parameterizedGroups = actualTests
    .Where(t => t.FullName.Contains('('))
    .GroupBy(t => StripParams(t.FullName))
    .Where(g => g.Count() > 1)
    .OrderByDescending(g => g.Sum(t => t.DurationMs))
    .ToList();

Console.WriteLine($"  Found {parameterizedGroups.Count} parameterized method groups (>1 variant)");
Console.WriteLine($"  Total parameterized variant count: {parameterizedGroups.Sum(g => g.Count())}");

// --- Step 3: Query AzDO for reported test durations ---
Console.WriteLine("\nStep 3: Fetching test durations from AzDO...");

// Get an Azure DevOps access token via az CLI
var tokenProcess = Process.Start(new ProcessStartInfo
{
    FileName = "az",
    Arguments = "account get-access-token --resource 499b84ac-1321-427f-aa17-267ca6975798 --query accessToken -o tsv",
    RedirectStandardOutput = true,
    UseShellExecute = false,
})!;
var accessToken = (await tokenProcess.StandardOutput.ReadToEndAsync()).Trim();
await tokenProcess.WaitForExitAsync();

if (string.IsNullOrEmpty(accessToken))
{
    Console.Error.WriteLine("  Failed to get AzDO access token via 'az' CLI. Are you logged in?");
    return 1;
}

Console.WriteLine("  Got access token from az CLI");

// Use build 1434970 (recent successful roslyn-CI on main) and run 119364 (Desktop Debug 64-bit, 125k tests)
const int buildId = 1434970;
const int runId = 119364;
const string org = "dnceng-public";
const string project = "public";

using var http = new HttpClient();
http.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Bearer", accessToken);

// Fetch test results in pages, collecting only the ones we care about
var targetNames = parameterizedGroups.Select(g => g.Key).ToHashSet();
var azdoResults = new Dictionary<string, double>();

Console.WriteLine($"  Searching AzDO run {runId} (build {buildId}) for {targetNames.Count} base method names...");

for (int skip = 0; ; skip += 10000)
{
    var url = $"https://dev.azure.com/{org}/{project}/_apis/test/runs/{runId}/results?$top=10000&$skip={skip}&api-version=7.0";
    var response = await http.GetStringAsync(url);
    var doc = JsonDocument.Parse(response);
    var values = doc.RootElement.GetProperty("value");

    foreach (var result in values.EnumerateArray())
    {
        if (!result.TryGetProperty("automatedTestName", out var nameElem) ||
            !result.TryGetProperty("durationInMs", out var durElem))
        {
            continue;
        }

        var name = nameElem.GetString()!;
        var baseName = StripParams(name);
        var durationMs = durElem.GetDouble();

        if (targetNames.Contains(baseName) && !azdoResults.ContainsKey(baseName))
        {
            azdoResults[baseName] = durationMs;
        }
    }

    if (values.GetArrayLength() < 10000)
    {
        break;
    }
}

Console.WriteLine($"  Found AzDO times for {azdoResults.Count} of {targetNames.Count} target methods");

// --- Step 4: Compare ---
Console.WriteLine("\n" + new string('=', 130));
Console.WriteLine("PROOF: AzDO reported time vs actual summed variant time");
Console.WriteLine(new string('=', 130));
Console.WriteLine();
Console.WriteLine($"{"Base Method Name",-75} {"Variants",8} {"AzDO Time",10} {"Sum Time",10} {"Ratio",8}");
Console.WriteLine(new string('-', 115));

var comparisons = new List<(string Name, int Variants, double AzdoMs, double SumMs, double Ratio)>();

foreach (var group in parameterizedGroups)
{
    if (!azdoResults.TryGetValue(group.Key, out var azdoMs))
    {
        continue;
    }

    var sumMs = group.Sum(t => t.DurationMs);
    var ratio = sumMs / azdoMs;
    var shortName = group.Key.Length > 75 ? "..." + group.Key[^72..] : group.Key;

    comparisons.Add((shortName, group.Count(), azdoMs, sumMs, ratio));
}

foreach (var c in comparisons.OrderByDescending(c => c.Ratio))
{
    Console.WriteLine($"{c.Name,-75} {c.Variants,8} {FormatMs(c.AzdoMs),10} {FormatMs(c.SumMs),10} {c.Ratio,7:F1}x");
}

Console.WriteLine();
Console.WriteLine(new string('=', 130));
Console.WriteLine("SUMMARY");
Console.WriteLine(new string('=', 130));

var matchedCount = comparisons.Count;
var totalAzdo = comparisons.Sum(c => c.AzdoMs);
var totalActual = comparisons.Sum(c => c.SumMs);
var overallRatio = totalActual / totalAzdo;
var significantUnderestimates = comparisons.Count(c => c.Ratio > 1.5);

Console.WriteLine($"  Parameterized methods matched: {matchedCount}");
Console.WriteLine($"  Total AzDO reported time:      {FormatMs(totalAzdo)}");
Console.WriteLine($"  Total actual summed time:       {FormatMs(totalActual)}");
Console.WriteLine($"  Overall underestimate ratio:    {overallRatio:F1}x");
Console.WriteLine($"  Methods underestimated >1.5x:   {significantUnderestimates} of {matchedCount}");
Console.WriteLine();

if (overallRatio > 1.5)
{
    Console.WriteLine("  CONCLUSION: AzDO's grouped test duration is NOT the sum of individual");
    Console.WriteLine("  parameterized variant execution times. The scheduler treats these times as");
    Console.WriteLine("  the total cost, but the actual execution of all variants takes significantly");
    Console.WriteLine($"  longer ({overallRatio:F1}x). This causes work items to exceed their time budget.");
}
else
{
    Console.WriteLine("  CONCLUSION: AzDO times appear to approximately match summed variant times.");
}

return 0;

static double ParseDurationMs(string s)
{
    if (s.Contains('h'))
    {
        double ms = 0;
        foreach (Match p in Regex.Matches(s, @"(\d+)\s*(h|min|s|ms)"))
        {
            var val = double.Parse(p.Groups[1].Value);
            ms += p.Groups[2].Value switch { "h" => val * 3_600_000, "min" => val * 60_000, "s" => val * 1_000, _ => val };
        }
        return ms;
    }
    if (s.Contains("min"))
    {
        double ms = 0;
        foreach (Match p in Regex.Matches(s, @"(\d+)\s*(min|s|ms)"))
        {
            var val = double.Parse(p.Groups[1].Value);
            ms += p.Groups[2].Value switch { "min" => val * 60_000, "s" => val * 1_000, _ => val };
        }
        return ms;
    }
    if (s.EndsWith("ms")) return double.Parse(Regex.Match(s, @"[\d.]+").Value);
    if (s.EndsWith("s")) return double.Parse(Regex.Match(s, @"[\d.]+").Value) * 1000;
    return 0;
}

static string FormatMs(double ms)
{
    if (ms >= 60_000) return $"{ms / 60_000:F1}m";
    if (ms >= 1_000) return $"{ms / 1_000:F1}s";
    return $"{ms:F0}ms";
}