Add pre-MSBuild submission duration metric - #55499
Conversation
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 3b83669f-7e3c-40d1-bd1e-c457682e40ea
|
Azure Pipelines: Successfully started running 1 pipeline(s). 2 pipeline(s) were filtered out due to trigger conditions. There may be pipelines that require an authorized user to comment /azp run to run. |
Fixes #55193 ## Summary `ReleasePropertyProjectLocator` already uses properties-only partial evaluation to discover `PackRelease` and `PublishRelease`. This change keeps `ProjectEvaluationStage.Properties` and reuses one short-lived `EvaluationContext` across all physical-project evaluations performed by a single discovery operation. The selected policy is `Shared`. It provides the best measured process-start-to-first-MSBuild-submission duration for both Pack and Publish and shares SDK resolution, filesystem observations, and wildcard/import expansion state across the physical-project discovery evaluations. The context is scoped to one short-lived release-property discovery operation, and the existing parallel solution evaluation remains fully parallel without an external lock. ## Performance **Measurement PR:** [#55499 — Add pre-MSBuild submission duration metric](#55499) The measurement uses `dotnet.cli.process_start_to_msbuild_submission.duration` from that SDK PR, recorded immediately before the first Pack/Publish MSBuild invocation. - OrchardCore `OrchardCore.slnx` - 12 measured iterations per variant across three independent runs - balanced rotated/reversed variant ordering - `dotnet pack OrchardCore.slnx --no-build` - `dotnet publish OrchardCore.slnx --no-build` - one process-local `dotnet-cli` histogram measurement per invocation This metric covers CLI process startup, argument parsing, physical project/solution discovery, and the hidden `ReleasePropertyProjectLocator` evaluations. It excludes the subsequent MSBuild build execution. ### Pack results | Policy | Mean | Median | Min–max | Median improvement vs Isolated | Paired wins | Median paired improvement | | --- | ---: | ---: | ---: | ---: | ---: | ---: | | Isolated | 2,760.63 ms | 2,772.20 ms | 2,615.80–2,914.30 ms | baseline | — | — | | SharedSDKCache | 1,276.10 ms | 1,264.33 ms | 1,246.62–1,334.77 ms | **1,507.87 ms (54.39%)** | 12/12 | 1,490.56 ms | | Shared | 1,259.27 ms | 1,243.23 ms | 1,222.42–1,350.46 ms | **1,528.97 ms (55.15%)** | 12/12 | 1,493.93 ms | Full `Shared` reduced Pack pre-submission median by 1,528.97 ms (55.15%) relative to Isolated and was 21.10 ms faster than `SharedSDKCache`. ### Publish results | Policy | Mean | Median | Min–max | Median improvement vs Isolated | Paired wins | Median paired improvement | | --- | ---: | ---: | ---: | ---: | ---: | ---: | | Isolated | 2,747.90 ms | 2,746.73 ms | 2,652.81–2,804.69 ms | baseline | — | — | | SharedSDKCache | 1,243.57 ms | 1,242.82 ms | 1,214.22–1,287.10 ms | **1,503.90 ms (54.75%)** | 12/12 | 1,503.04 ms | | Shared | 1,213.05 ms | 1,214.22 ms | 1,196.87–1,240.48 ms | **1,532.51 ms (55.79%)** | 12/12 | 1,538.15 ms | Full `Shared` reduced Publish pre-submission median by 1,532.51 ms (55.79%) relative to Isolated and was 28.60 ms faster than `SharedSDKCache`. ## Tests - Added a locator test that performs two discovery calls in the same process, mutates import existence between calls, and verifies that the first call's shared filesystem observations are not retained by the second call.
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
|
Azure Pipelines: Successfully started running 2 pipeline(s). 1 pipeline(s) were filtered out due to trigger conditions. There may be pipelines that require an authorized user to comment /azp run to run. |
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
There was a problem hiding this comment.
🟡 Changes recommended
MSBuildSubmissionMetricCommandName is declared as non-nullable but is used/assigned as nullable, making the contract misleading and increasing future null-deref risk.
Once you've addressed the issues Copilot identified, you can request another Copilot review.
Pull request overview
This PR introduces a new CLI histogram metric to measure elapsed time from dotnet process start until the first MSBuild submission for dotnet pack and dotnet publish, and adds a unit test validating the metric’s unit and command tag.
Changes:
- Add
CliMetrics(meter + histogram) and helper methods to recorddotnet.cli.process_start_to_msbuild_submission.duration. - Wire metric recording into both physical and file-based project paths via
RestoringCommandandVirtualProjectBuildingCommand. - Add a
MeterListenertest to validate the histogram emits seconds and thecommand.nametag.
File summaries
| File | Description |
|---|---|
| test/dotnet.Tests/TelemetryTests/CliMetricsTests.cs | Adds a unit test validating metric emission and tags via MeterListener. |
| src/Cli/Microsoft.DotNet.Cli.Utils/CliMetrics.cs | Introduces the dotnet-cli meter + histogram and recording helpers. |
| src/Cli/dotnet/Commands/Run/VirtualProjectBuildingCommand.cs | Records the metric before starting MSBuild operations for file-based scenarios. |
| src/Cli/dotnet/Commands/Restore/RestoringCommand.cs | Records the metric before the first restore/MSBuild invocation for physical project scenarios. |
| src/Cli/dotnet/Commands/Publish/PublishCommand.cs | Sets the command tag value (publish) on the executed command instance. |
| src/Cli/dotnet/Commands/Pack/PackCommand.cs | Sets the command tag value (pack) on the executed command instance (MSBuild-based path). |
| src/Cli/dotnet/CommandBase.cs | Adds a per-command field and helper to record the metric once. |
Review details
- Files reviewed: 7/7 changed files
- Comments generated: 1
- Review effort level: Lite
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
| } | ||
|
|
||
| DateTime endTimeUtc = DateTime.UtcNow; | ||
| DateTime startTimeUtc = Process.GetCurrentProcess().StartTime.ToUniversalTime(); |
There was a problem hiding this comment.
Does this number include the CLR start-up time?
There was a problem hiding this comment.
Is this a useful metric then? The start-up time even with NativeAOT isn't stable. Do we have an existing metric when dotnet.dll starts executing code?
There was a problem hiding this comment.
Mmm.. I am not usre that we have such metric when dotnet.dll starts executing.. If start up time is so noisy so mb not to use Process.GetCurrentProcess().StartTime.ToUniversalTime(); but use start time from Program constructor? What do you think
There was a problem hiding this comment.
I would be surprised if this is the first telemetry that needs to subtract the start-up time. @baronfel do you know of an existing pattern in dotnet.dll that we could reuse?
There was a problem hiding this comment.
We already track this time as part of the activity that is started first in the native entry point and the managed Program Main - check there first. We snapshot the process start time (which is not the time that Main was entered), grab the current time, and subtract to get the amount of time native host startup (and coreclr startup for the managed path) took.
There was a problem hiding this comment.
Thnx, now I use existing preTelemetry timestamp from Program.cs. + I also renamed the metric so it will be more clear that we do not measure start up time
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
baronfel
left a comment
There was a problem hiding this comment.
I kind of don't agree with the direction overall. I think there's a way to get this data that is more integrated with the way the dotnet CLI is already 'naming' phases of work.
| private static class Instruments | ||
| { | ||
| private static readonly Meter s_meter = new(MeterName, Product.Version); | ||
|
|
||
| internal static readonly Histogram<double> ManagedEntryToMSBuildSubmissionDuration = | ||
| s_meter.CreateHistogram<double>( | ||
| ManagedEntryToMSBuildSubmissionDurationName, | ||
| unit: "s", | ||
| description: "Elapsed time from managed dotnet CLI entry to the first Pack or Publish MSBuild invocation, excluding native host and CLR startup."); | ||
| } | ||
| } |
There was a problem hiding this comment.
This feels far too specific to me to have as a general metric. In general I'd think of the dotnet CLI as we think of the evaluation phase in msbuild - there are various 'phases' of work that take different times:
- process startup
- first-time CLI run overhead
- argument parsing
- command invocation
and then those individual commands may have other sub-phases. for example, pack may have
- evaluate to discover pack settings
- actual msbuild submission
In the CLI today, these phases are modeled as Spans - a concept from OpenTelemetry that is a timed unit of work that has various pieces of metadata that can be attached to it. In .NET Spans are most often surfaced as System.Diagnostics.Activities.Activity instances - you can see them being created across Program.cs and the NativeEntryPoint.cs already to track such interesting areas of time.
The way I'd been thinking that we would gather this information today is by adding an activity for the MSBuild submission portion of the MSbuild-using commands - this activity will be automatically visible in OTel viewers. Then, if we need a System.Diagnostics.Meter metric specifically for collection in crank or other scenarios, we can add an ActivityListener in the dotnet CLI that would publish histogram-style metrics for the activities:
var listener = new ActivityListener
{
ShouldListenTo = source => source.Name == "dotnet-cli",
Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllDataAndRecorded,
ActivityStopped = activity =>
{
double durationMs = activity.Duration.TotalMilliseconds;
Instruments.ActivityDuration.Record(durationMs, new KeyValuePair<string, object?>("activity.name", activity.OperationName));
}
};
ActivitySource.AddActivityListener(listener);From there dotnet-counters, Crank, etc can easily compute the deltas of the time - subtracting the time for the msbuild submission activity from the time of the overall command.
| static Program() | ||
| { | ||
| var preTelemetry = DateTime.UtcNow; | ||
| CliMetrics.SetManagedEntryTimeUtc(preTelemetry); |
There was a problem hiding this comment.
I don't like having to know this to generate timestamps - the Activities we create already capture this data and I think we should be leaning into them more.
Fixes dotnet/msbuild#14537
Summary
dotnet.cli.managed_entry_to_msbuild_submission.durationfordotnet packanddotnet publish.preTelemetrytimestamp captured at the start of the managed CLIPrograminitializer.parsing, project or solution discovery, and Pack/Publish release-property evaluation.
MeterListenerunit test for the duration, unit, and command tag.The existing root
mainactivity remains backdated to process start for end-to-end CLI timing.