diff --git a/CHANGELOG.md b/CHANGELOG.md index 275adf0..02d5351 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,13 @@ # Changelog +## 0.9.1 — 2026-10-19 + +- `ado_trace` always answers: on an item with many links (pull requests, commits, builds, releases) the slow parts + stop after 40 seconds and an INCOMPLETE section says what was not checked, instead of the client giving up with a + timeout. At most 8 branch and deployment checks run at the same time (more were throttled), and the TFVC branch of + changesets is asked once per folder, all at once. +- `adolens trace --timing`: how long each part took, to find what is slow on a given project. + ## 0.9.0 — 2026-10-18 Improvements from testing on a real project. diff --git a/src/AdoLens/AdoLens.csproj b/src/AdoLens/AdoLens.csproj index 5516611..fc83764 100644 --- a/src/AdoLens/AdoLens.csproj +++ b/src/AdoLens/AdoLens.csproj @@ -23,7 +23,7 @@ ADO Lens for Azure DevOps Azure DevOps (work items, boards, wiki, Git and TFVC, pipelines) served to AI assistants over MCP Copyright © 2026 WillowDev - 0.9.0 + 0.9.1 diff --git a/src/AdoLens/Cli.cs b/src/AdoLens/Cli.cs index da20e41..2525189 100644 --- a/src/AdoLens/Cli.cs +++ b/src/AdoLens/Cli.cs @@ -50,7 +50,7 @@ sprint [current|next|previous|] --team --detail summary|normal|full board [] --team --move --column --detail summary|normal|full backlog --level requirement|portfolio|task| --top 30 --move --above | --below myday --since 1d|3d|2w|yyyy-MM-dd (default: the previous working day) - trace was it done as asked, and where is it (DEV / UAT / PROD) --detail summary|full + trace was it done as asked, and where is it (DEV / UAT / PROD) --detail summary|full --timing (how long each part took) changes <523 | C523 | "PR 482" | sha --repo > files, X++ methods; --file for a diff pr [] PRs waiting for my review and mine (--list active: all); with id: reviewers, checks, threads --merged [--since 7d] [--repo ] [--top 30]: completed into a branch, with work items @@ -853,7 +853,7 @@ static List SplitLanguages(string text) => public async Task TraceAsync() { if (Int(cl.Positional.FirstOrDefault()) is not { } id) { Console.Error.WriteLine("usage: adolens trace [--detail summary|full]"); return 2; } - Print(await TraceQueries.TraceAsync(NewLens(), cl.Opt("connection"), id, cl.Opt("detail"))); + Print(await TraceQueries.TraceAsync(NewLens(), cl.Opt("connection"), id, cl.Opt("detail"), timing: cl.Flag("timing"))); return 0; } diff --git a/src/AdoLens/CommandLine.cs b/src/AdoLens/CommandLine.cs index 6067b3a..c92aeda 100644 --- a/src/AdoLens/CommandLine.cs +++ b/src/AdoLens/CommandLine.cs @@ -19,7 +19,7 @@ public sealed partial class CommandLine ["test-create"] = ["connection=", "file=", "plan=", "suite="], ["logout"] = ["connection=", "all", "remove"], ["connections"] = [], - ["trace"] = ["connection=", "detail="], + ["trace"] = ["connection=", "detail=", "timing"], ["pr"] = ["connection=", "project=", "repo=", "list=", "detail=", "merged=", "since=", "top="], ["pipeline"] = ["connection=", "project=", "definition=", "branch=", "top=", "detail=", "artifacts", "artifact=", "part=", "save", "to=", "deployments", "stage="], ["changes"] = ["connection=", "repo=", "file=", "detail="], diff --git a/src/AdoLens/Trace.cs b/src/AdoLens/Trace.cs index a7c614e..100661e 100644 --- a/src/AdoLens/Trace.cs +++ b/src/AdoLens/Trace.cs @@ -40,13 +40,35 @@ static IEnumerable Objects(CodeChange c) => c.Files.Select(f => AotDiff.IsAot(f.Path) ? AotDiff.ObjectName(f.Path) : f.Path[(f.Path.LastIndexOf('/') + 1)..]) .Where(n => n.Length > 0).Distinct(StringComparer.OrdinalIgnoreCase); - public static async Task TraceAsync(Lens lens, string? connection, int id, string? detail, CancellationToken ct = default) + /// + /// How long a trace may take. Clients give up on a tool after a while (about a minute), so the slow parts - reading + /// the linked changes, builds and where it is deployed - stop at this point and the answer says what is missing. + /// + internal static TimeSpan Budget = TimeSpan.FromSeconds(40); + + /// Calls asking whether a change is in a branch or deployment at the same time (more get throttled). + const int ParallelChecks = 8; + + public static async Task TraceAsync(Lens lens, string? connection, int id, string? detail, CancellationToken ct = default, bool timing = false) { var session = lens.For(connection); var work = session.Work; var code = session.Code; var full = detail == "full"; var summary = detail == "summary"; + using var deadline = CancellationTokenSource.CreateLinkedTokenSource(ct); + deadline.CancelAfter(Budget); + var dt = deadline.Token; + bool OutOfTime(Exception e) => e is OperationCanceledException && !ct.IsCancellationRequested; + var missing = new List(); + var clock = System.Diagnostics.Stopwatch.StartNew(); + var phases = new List(); + var lap = TimeSpan.Zero; + void Mark(string phase) + { + phases.Add($"{phase} {(clock.Elapsed - lap).TotalSeconds:0.0}s"); + lap = clock.Elapsed; + } var items = await work.GetAsync([id], relations: true, ct: ct); if (items.Count == 0) return $"no work item #{id} visible with this PAT"; @@ -96,13 +118,17 @@ string Category(JsonElement x) => .Where(u => Json.Obj(Json.Obj(u, "fields"), WorkItems.AcceptanceRef).ValueKind == JsonValueKind.Object) .Select(u => (When: UpdateTime(u), Who: Json.Str(Json.Obj(u, "revisedBy"), "displayName"))) .Where(x => x.When is not null).ToList(); + Mark($"item and {children.Count} tasks"); // 2. What was done: code linked to the item and to its tasks. var links = Links(wi).Concat(children.SelectMany(Links)).DistinctBy(l => (l.Kind, l.Value)).ToList(); var changes = new List<(CodeChange Change, int From)>(); var failed = new List(); - await Parallel.ForEachAsync(links.Where(l => l.Kind != "build/build" && l.Kind != "git/ref"), - new ParallelOptions { MaxDegreeOfParallelism = 6, CancellationToken = ct }, async (l, token) => + var toRead = links.Where(l => l.Kind != "build/build" && l.Kind != "git/ref").ToList(); + try + { + await Parallel.ForEachAsync(toRead, + new ParallelOptions { MaxDegreeOfParallelism = 6, CancellationToken = dt }, async (l, token) => { try { @@ -117,6 +143,12 @@ await Parallel.ForEachAsync(links.Where(l => l.Kind != "build/build" && l.Kind ! } catch (AdoApiException ex) { lock (failed) failed.Add($"{l.Kind.Split('/')[^1]} {l.Value.Split('/')[^1]}: {Formatting.Collapse(ex.Message, 100)}"); } }); + } + catch (Exception e) when (OutOfTime(e)) + { + missing.Add($"{toRead.Count - changes.Count - failed.Count} of {toRead.Count} linked changes were not read in time"); + } + Mark($"{changes.Count} changes"); changes = Combine(changes.OrderBy(c => c.Change.Date).ToList()); var (env, envSource) = await EnvironmentFlow.EffectiveAsync(session, project, ct); // A PR from a long-lived branch (a release branch into master, staging into master…) carries many items at once: @@ -125,8 +157,16 @@ await Parallel.ForEachAsync(links.Where(l => l.Kind != "build/build" && l.Kind ! bool IsPromotion(CodeChange x) => x.Kind == "pr" && x.Branch is { } src && (env.ContainsKey(src) || prTargets.Contains(src) || x.Files.Count > 100); var branches = new Dictionary(); - foreach (var cs in changes.Select(x => x.Change).Where(x => x.Kind == "changeset")) - branches[cs.Id] = cs.Files.Count > 0 ? await code.TfvcBranchAsync(cs.Files[0].Path, ct) : null; + // One call per branch path, all at the same time (changesets of one item are mostly on the same branches). + var tfvc = changes.Select(x => x.Change).Where(x => x.Kind == "changeset").ToList(); + var branchOf = new System.Collections.Concurrent.ConcurrentDictionary>(StringComparer.OrdinalIgnoreCase); + try + { + var found = await Task.WhenAll(tfvc.Select(cs => cs.Files.Count == 0 ? Task.FromResult(null) + : branchOf.GetOrAdd(cs.Files[0].Path[..Math.Max(0, cs.Files[0].Path.LastIndexOf('/'))], _ => code.TfvcBranchAsync(cs.Files[0].Path, dt)))); + for (var i = 0; i < tfvc.Count; i++) branches[tfvc[i].Id] = found[i]; + } + catch (Exception e) when (OutOfTime(e)) { missing.Add("TFVC branches of the changesets were not read in time"); } sb.AppendLine("\nDONE"); if (changes.Count == 0) sb.AppendLine("no changesets, commits or pull requests linked to the item or its tasks"); @@ -168,7 +208,7 @@ bool IsPromotion(CodeChange x) => { var said = string.Join("\n", new[] { WorkItems.DescriptionRef, WorkItems.ReproStepsRef, "Microsoft.VSTS.CMMI.ProposedFix", "Microsoft.VSTS.Common.Resolution", "Microsoft.VSTS.TCM.SystemInfo" }.Select(f => Html.ToMarkdown(WorkItems.Field(wi, f)))) - + "\n" + string.Join("\n", (await TryCommentsAsync(work, project, id, ct)).Select(c => Html.ToMarkdown(Json.Str(c, "text")))); + + "\n" + string.Join("\n", (await TryCommentsAsync(work, project, id, dt)).Select(c => Html.ToMarkdown(Json.Str(c, "text")))); var hints = ConfigWords().Matches(said).Select(m => m.Value.ToLowerInvariant()).Distinct().Take(4).ToList(); signals.Add(hints.Count > 0 ? $"no code linked, and the item speaks of configuration ({string.Join(", ", hints)}): probably a change in the system's setup - it can be checked only there, not in code" @@ -187,10 +227,12 @@ bool IsPromotion(CodeChange x) => { sb.AppendLine("\nBUILDS"); var shownBuilds = buildIds.Take(full ? 50 : 5).ToList(); - var builds = await Task.WhenAll(shownBuilds.Select(b => code.BuildAsync(project, b, ct))); + JsonElement?[] builds; + try { builds = await Task.WhenAll(shownBuilds.Select(b => code.BuildAsync(project, b, dt))); } + catch (Exception e) when (OutOfTime(e)) { builds = new JsonElement?[shownBuilds.Count]; missing.Add("builds were not read in time"); } for (var i = 0; i < shownBuilds.Count; i++) { - if (builds[i] is not { } b) { sb.AppendLine($"- build {shownBuilds[i]}: no longer kept (deleted by retention)"); continue; } + if (builds[i] is not { } b) { sb.AppendLine($"- build {shownBuilds[i]}: {(dt.IsCancellationRequested ? "not read in time" : "no longer kept (deleted by retention)")}"); continue; } sb.AppendLine($"- {Json.Str(Json.Obj(b, "definition"), "name")} {Json.Str(b, "buildNumber")}: {Json.Str(b, "result") ?? Json.Str(b, "status")}, " + $"{Code.Short(Json.Str(b, "sourceBranch"))} @ {Json.Str(b, "sourceVersion")?[..Math.Min(8, Json.Str(b, "sourceVersion")!.Length)]}, {Date(DateTime.TryParse(Json.Str(b, "finishTime"), CultureInfo.InvariantCulture, DateTimeStyles.AdjustToUniversal, out var f) ? f : null)}"); if (i == 0 && Json.Str(b, "result") is "failed" or "partiallySucceeded") signals.Add($"the latest linked build ({Json.Str(b, "buildNumber")}) {Json.Str(b, "result")}"); @@ -202,7 +244,11 @@ bool IsPromotion(CodeChange x) => // Releases live with the code, which can be in another project than the work item. var projects = changes.Select(x => x.Change.Project).Append(project).Where(p => p is not null).Select(p => p!) .Distinct(StringComparer.OrdinalIgnoreCase).ToList(); - var deployments = (await Task.WhenAll(projects.Select(p => code.DeploymentsAsync(p, ct)))).SelectMany(x => x).ToList(); + Mark("builds"); + List deployments; + try { deployments = (await Task.WhenAll(projects.Select(p => code.DeploymentsAsync(p, dt)))).SelectMany(x => x).ToList(); } + catch (Exception e) when (OutOfTime(e)) { deployments = []; missing.Add("release deployments were not read in time"); } + Mark($"{deployments.Count} release stages"); // The environment map names a release stage ("Definition/Stage", e.g. one stage deploying to UAT and SCM at once), // a whole release definition, or a branch ("staging"; TFVC: the last part of the branch path, e.g. "Main"). var envOrder = env.Keys.Select((k, i) => (k, i)).ToDictionary(x => x.k, x => x.i, StringComparer.OrdinalIgnoreCase); @@ -221,8 +267,15 @@ string Label(string? branch, string def, string stage) => // Each answer is one Azure DevOps call: asked once, all at the same time (a sequential walk timed out on items // with several PRs and many release stages). var containsCache = new System.Collections.Concurrent.ConcurrentDictionary<(string, string, bool), Task>(); + using var gate = new SemaphoreSlim(ParallelChecks); Task Contains(string repo, string commit, string target, bool isBranch) => - containsCache.GetOrAdd((commit, target, isBranch), _ => code.ContainsAsync(repo, commit, target, isBranch, ct)); + containsCache.GetOrAdd((commit, target, isBranch), _ => Gated(() => code.ContainsAsync(repo, commit, target, isBranch, dt))); + async Task Gated(Func> check) + { + await gate.WaitAsync(dt); + try { return await check(); } + finally { gate.Release(); } + } async Task<(List In, List NotYet, bool Known)> GitStatus(string repo, string target, bool isBranch, DateTime? deployedAt) { var git = changes.Select(x => x.Change).Where(x => x.Kind != "changeset" && string.Equals(x.RepoId, repo, StringComparison.OrdinalIgnoreCase)).ToList(); @@ -272,7 +325,7 @@ static string Names(IEnumerable list) => return (string?)(label + (inside.Count > 0 ? $"YES - deployed {deployed}: {Names(inside.Where(x => !IsPromotion(x)).DefaultIfEmpty(inside[0]))}" + (notYet.Count > 0 ? $"; not yet: {Names(notYet)}" : "") : $"NOT YET - last deployment {deployed} has none of it")); - }, ct)); + }, dt)); } } // Git branches named in the environment map, even without release pipelines: is the work merged there? @@ -289,9 +342,16 @@ static string Names(IEnumerable list) => return (string?)($"- {envLabel} = branch {branch} ({repoName}): " + (inside.Count > 0 ? $"merged: {Names(inside.Where(x => !IsPromotion(x)).DefaultIfEmpty(inside[0]))}" + (notYet.Count > 0 ? $"; not yet: {Names(notYet)}" : "") : "NOT merged yet")); - }, ct)); + }, dt)); } - where.AddRange((await Task.WhenAll(stageTasks)).Where(l => l is not null).Select(l => l!)); + try { await Task.WhenAll(stageTasks); } + catch (Exception e) when (OutOfTime(e)) + { + var open = stageTasks.Count(t => !t.IsCompletedSuccessfully); + missing.Add($"{open} of {stageTasks.Count} stages and branches were not checked in time (ado_changes or ado_pipeline answer them one by one)"); + } + where.AddRange(stageTasks.Where(t => t.IsCompletedSuccessfully).Select(t => t.Result).Where(l => l is not null).Select(l => l!)); + Mark($"{containsCache.Count} branch checks"); if (where.Count > 0) sb.AppendLine("\nWHERE").AppendLine(string.Join('\n', where)); else if (changes.Count > 0) sb.AppendLine("\nWHERE").AppendLine("no release stage deploys the branches of this change"); @@ -328,6 +388,10 @@ static string Names(IEnumerable list) => sb.AppendLine("\nTASKS").AppendLine(string.Join('\n', children.Select(t => $"- {WorkItemFormat.Header(t)}{(WorkItems.Field(t, "System.AssignedTo") is { } who ? $" ({who})" : "")}"))); sb.AppendLine("\nSIGNALS").AppendLine(signals.Count == 0 ? "- none" : string.Join('\n', signals.Select(x => "- " + x))); + if (missing.Count > 0) + sb.AppendLine($"\nINCOMPLETE (stopped after {Budget.TotalSeconds:0} s so the answer comes at all)").AppendLine(string.Join('\n', missing.Select(x => "- " + x))); + Mark("rest"); + if (timing) sb.AppendLine($"\ntiming: {string.Join(", ", phases)}; total {clock.Elapsed.TotalSeconds:0.0}s"); return sb.ToString().TrimEnd(); } @@ -359,7 +423,7 @@ static string Names(IEnumerable list) => static async Task> TryCommentsAsync(WorkItems work, string project, int id, CancellationToken ct) { try { return await work.CommentsAsync(project, id, 30, ct); } - catch (AdoApiException) { return []; } + catch (Exception e) when (e is AdoApiException or OperationCanceledException) { return []; } } [GeneratedRegex(@"^Merged PR (?\d+)")] diff --git a/tests/AdoLens.Tests/TraceTests.cs b/tests/AdoLens.Tests/TraceTests.cs index 7e39d5e..57ebc15 100644 --- a/tests/AdoLens.Tests/TraceTests.cs +++ b/tests/AdoLens.Tests/TraceTests.cs @@ -194,6 +194,22 @@ public void A_pull_request_and_its_merge_commit_are_one_change() Assert.Single(result[0].Change.Files); } + [Fact] + public async Task A_trace_that_runs_out_of_time_answers_with_what_it_has() + { + var budget = TraceQueries.Budget; + TraceQueries.Budget = TimeSpan.Zero; + try + { + var text = (await TraceQueries.TraceAsync(lens, null, 1, null, timing: true)).Replace("\r", ""); + Assert.Contains("ASKED", text); + Assert.Contains("INCOMPLETE (stopped after 0 s so the answer comes at all)", text); + Assert.Contains("linked changes were not read in time", text); + Assert.Contains("timing: item and", text); + } + finally { TraceQueries.Budget = budget; } + } + [Fact] public async Task Changes_list_objects_with_methods_and_diff_one_file() {