From 8a0046260ed70eda022b809e3c9f23a58d32ad0b Mon Sep 17 00:00:00 2001 From: WillowDev <216433317+willowdev-code@users.noreply.github.com> Date: Mon, 19 Oct 2026 12:04:09 +0200 Subject: [PATCH] ADO Lens 0.9.1 - `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. --- CHANGELOG.md | 8 +++ src/AdoLens/AdoLens.csproj | 2 +- src/AdoLens/Cli.cs | 4 +- src/AdoLens/CommandLine.cs | 2 +- src/AdoLens/Trace.cs | 92 ++++++++++++++++++++++++++----- tests/AdoLens.Tests/TraceTests.cs | 16 ++++++ 6 files changed, 106 insertions(+), 18 deletions(-) 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() {