Ensure thread-safety in aggregated telemetry - #71606
Merged
Merged
Conversation
ghost
added
Area-IDE
untriaged
Member
|
@ToddGrun Should we be targeting this against 17.9? |
sharwell
reviewed
Jan 12, 2024
Contributor
Author
|
It might be worth considering. There were a bunch of hits, but they appeared more heavily in what appeared to be automation runs if I remember correctly. In reply to: 1889797448 |
Member
|
@ToddGrun Given this was a new regression in 17.9, I imagine that might just be due to a relative lack of use (doubly so due to the holidays meaning we didn't have much human use.) I'd totally support this in 17.9. |
Contributor
Author
@jasonmalinowski -- what's the process for getting this into 17.9 too? Do I proceed with merging this into main first and then cherrypicking it somewhere? Or does it instead just target a 17.9 branch and flow from there back to main? |
…for a particular telemetry event.
…it's getting posted.
ToddGrun
force-pushed
the
dev/toddgrun/1934204
branch
from
January 16, 2024 23:44
54bbaa6 to
85dd916
Compare
arunchndr
approved these changes
Jan 17, 2024
dibarbet
added a commit
to dibarbet/roslyn
that referenced
this pull request
Aug 27, 2026
Blocking: - The standalone language server passed logDelta: false, so block end events silently lost vs.ide.vbcs.<id>.delta. The deleted RoslynLogger passed the delta unconditionally -- it had no logDelta concept -- and the option that gates it in devenv has no counterpart in that host. - RoslynTelemetry.Workspaces.cs referenced RecordBlockTime(FunctionId, string, int), which stopped existing when the unused threshold parameter was removed. CS1574 is not in the repo's NoWarn, so this broke a warnaserror build. Telemetry fidelity: - TimedBlock and TimedEventBlock timed with Environment.TickCount, quantized to ~15.6ms. Every aggregated duration histogram measures sub-100ms IDE operations, so a 3ms code fix pass recorded 0 or 15. The deleted TimedTelemetryLogBlock used SharedStopwatch; both now do again. - That same type suppressed recording in debug bits and under a debugger, and it served the aggregated path too (AggregatingHistogramLog.LogBlockTime returned one). Only the discrete path kept the guard; RecordBlockTime now has it as well, so a breakpoint inside GetMostSevereFixAsync no longer contributes a multi-second sample. Correctness: - Log(FunctionId, LogMessage) freed the pooled message only when a sink was enabled. Callers migrated from TelemetryLogging.Log, which always freed, leaked one message per call -- including PerformanceTrackerService in the OOP process, where no event sink is normally registered. - A block ended on whichever sinks were enabled at dispose, not on the ones it started on, so a sink enabled mid-block received an end with no start. TelemetryLogger asserts the pending scope exists, so that throws; the opposite flip leaks the scope. RoslynLogBlock now records which sinks got the start and ends on exactly those. - VSMetricSink.Flush exchanged the aggregation map before posting, so a concurrent Count/Record missed and built a second instrument with the same name on the same meter while the first was being posted -- the shape of dotnet#71606. Cleared after the loop again, as before. - AggregationKey ignored counter-vs-histogram, so one event and metric name used both ways would hand a counter to an IHistogram cast. The old design kept separate dictionaries and could not express this. - An exception from Flush escaped the 30-minute loop, whose task nobody observes, silently ending all later flushes for the session. Also: guard LanguageServerTelemetry's Report/Flush on having a session, since MEF disposes it a second time and the session reporters are not idempotent; drop PerfMarginPanel's registration guard, which AddEventSink already provides and which prevented re-registration after tests clear sinks; remove four dead consts; correct the VS Code Razor ReportMetric comment, which claimed a data loss that cannot occur because that reporter never builds a session manager. Adds RoslynTelemetryTests covering the pairing contract. Validation: Ide.slnf and Compilers.slnf build clean; Workspaces telemetry tests 6/6 on net10.0 and net472; LSP telemetry tests 18/18. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: 4c5bb045-3aa8-4014-bc0c-d5a968389dee
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
We've recently had several forms of exceptions come through due to threading issues in our interaction with the vstelemetry api. Specifically, we need to be more cautious around our use of TelemetrySession.PostMetricEvent.
This PR adds two locks with the following intent:
_flushLock:
This lock is intended to ensure that concurrent iterations over _histograms is not allowed. Such concurrent iterations could potentially invoke TelemetrySession.PostMetricEvent multiple times with the same histogramEvent .
histogramLock:
This lock is intended to ensure that overlapping calls of IHistogram.Record and TelemetrySession.PostMetricEvent for that histogram are not allowed. A separate lock is allocated for each histogram to reduce the likelihood of contention during Log calls. This lock also prevents concurrent Record calls on the same histogram.
In addition to preventing these concurrency issues, a primary goal here was not to add much overhead via these lock calls. I considered just using a single lock, but opted instead for this approach to prevent contention as much as possible during the much more frequent Log calls.
Addresses https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1934204