Use parameterized trace calls instead of eager interpolated strings - #4528
Conversation
Interpolated strings passed to SqlClientEventSource.Try*Event are built unconditionally at the call site, so the overload's internal IsTraceEnabled/IsAdvancedTraceOn check no longer avoids the cost. This allocates on every call even with tracing off. SqlConnectionInternal.Deactivate runs on every pooled connection return and accounted for ~200 bytes per open/close cycle, which is most of the +264 bytes/op regression the connection pool benchmarks show against 6.1.6. Wrap the affected call sites in the matching enablement check so the string is only built when the event will be written. The guards mirror the checks already inside each overload, so behavior is unchanged. Measured on a pooled open/close loop against the in-proc TDS server: sync 688.5 -> 488.5 bytes/op, async 880.5 -> 680.5 bytes/op. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Three call sites were mis-converted when they moved to interpolated strings:
- OnFeatureExtAck logged "Object ID {0}", which in an interpolated string is
the expression 0, so it always reported an object ID of 0 instead of the
actual one.
- Two sites kept a trailing format argument after interpolation. These bind to
the generic overload, which runs string.Format over already-formatted text.
The argument is redundant, and a value containing a brace (a routed server
name, for instance) would raise a FormatException from inside tracing.
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
The earlier sweep only matched calls whose first argument began with an interpolated string, so it missed the "literal " + $"..." form. That form allocates the same way. The remaining 41 sites include the correlation traces in ExecuteReader, ExecuteNonQuery, ExecuteScalar and ExecuteXmlReader, which interpolate CommandText and ClientConnectionId on every execution. In 6.1.6 these passed a constant format string with arguments, so nothing was built unless the event was enabled. Measured on a repeated ExecuteReader loop: 3199.4 -> 1027.5 bytes/op. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
The Try*Event overloads check whether the event is enabled before doing
any formatting work. Passing an interpolated string defeats that, because
the string is built at the call site before the call is made, so every
traced operation allocated even with tracing switched off.
Converts the 119 interpolated call sites introduced since 6.1.6 back to
a composite format string plus arguments, which is what the overloads are
designed for. Trace output is unchanged.
Also corrects two artifacts of the original conversion:
- OnFeatureExtAck logged "Object ID {0}", which inside an interpolated
string is the expression 0, so it always reported 0.
- Two calls kept a trailing argument that duplicated an interpolated
expression; the argument is now the format argument.
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
There was a problem hiding this comment.
Pull request overview
This PR reduces allocation overhead when tracing is disabled by replacing eagerly-built interpolated strings at SqlClientEventSource.Log.Try*Event(...) call sites with composite format strings plus arguments, restoring the pre-unification logging pattern and improving connection pool benchmark memory behavior.
Changes:
- Rewrites
TryTraceEvent,TryAdvancedTraceEvent, andTryCorrelationTraceEventcall sites to use parameterized (format + args) logging instead of interpolated strings. - Fixes a few latent tracing defects encountered during the mechanical rewrite (incorrect placeholder usage and redundant trailing args that could lead to
FormatException). - Keeps
SqlClientEventSourceunchanged and confines changes to driver call sites.
Reviewed changes
Copilot reviewed 8 out of 8 changed files in this pull request and generated 1 comment.
Show a summary per file
| File | Description |
|---|---|
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs | Converts hot-path connection/pool tracing to parameterized calls to avoid allocations when tracing is off. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Reader.cs | Rewrites reader execution trace/correlation calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.NonQuery.cs | Rewrites non-query execution trace/correlation calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Scalar.cs | Rewrites scalar execution trace/correlation calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.Xml.cs | Rewrites XML reader execution trace/correlation calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlCommand.cs | Rewrites various command lifecycle/property-setting trace calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs | Rewrites auth provider discovery/loading trace calls to parameterized form. |
| src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Utilities/AsyncHelper.cs | Rewrites unobserved continuation exception trace to parameterized form. |
Suppressed comments (2)
src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs:1854
- This advanced-trace call uses
{1:T}/{2:T}, butTryAdvancedTraceEventstringifies arguments beforestring.Format(SqlClientEventSource.cs:1186+), so the:Tspecifiers will not be applied and trace output changes compared to the previous interpolated-string version. Guard onIsAdvancedTraceOn()and pre-format the time values, and drop the:Tspecifiers in the composite format string.
"The expiration time is {1:T}. " +
"Current Time is {2:T}.",
ObjectID,
dbConnectionPoolAuthenticationContext.ExpirationTime,
DateTime.UtcNow);
src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs:4063
- This trace message uses
{1:T}/{2:T}, butTryTraceEventconverts arguments to strings before formatting (SqlClientEventSource.cs:487+). As a result the:Tspecifier won’t be applied and trace output differs from the previous interpolated string behavior. If you need the log to remain time-only, guard the call and pass pre-formatted time strings, and remove the:Tspecifiers.
"The expiration time is {1:T}. " +
"Current Time is {2:T}.",
ObjectID,
dbConnectionPoolAuthenticationContext.ExpirationTime,
DateTime.UtcNow);
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
saurabh500
left a comment
saurabh500
left a comment
There was a problem hiding this comment.
The bot comment needs to be addressed. Otherwise good find and thanks for addressing this.
The generic Try*Event overloads call ToString() on each argument before
string.Format, so a {1:T} specifier in the composite format string is
never applied. Three fed auth trace sites relied on :T and would have
logged full date and time instead of time only.
Guard these three sites on the matching enablement check and pass
pre-formatted time strings, which keeps the output identical to the
interpolated version and still allocates nothing when tracing is off.
Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 8 out of 8 changed files in this pull request and generated no new comments.
Suppressed comments (1)
src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlAuthenticationProviderManager.cs:74
- This trace call still eagerly allocates the public-key-token string (
BitConverter.ToString(...).Replace(...)) even when tracing is disabled, because the argument expression is evaluated beforeTryTraceEventchecksIsTraceEnabled(). To keep startup cost minimal (and consistent with the rest of this PR’s approach), guard the call and compute the token string only when tracing is on.
nameof(SqlAuthenticationProviderManager) +
": Attempting to load Azure extension assembly={0} with " +
"expected public key token={1}",
azureAssemblyName,
BitConverter.ToString(s_azurePublicKeyToken).Replace("-", ""));
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #4528 +/- ##
==========================================
- Coverage 64.71% 62.75% -1.96%
==========================================
Files 288 283 -5
Lines 44088 67315 +23227
==========================================
+ Hits 28532 42246 +13714
- Misses 15556 25069 +9513
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
cheenamalhotra
added
the
Performance 📈
For future use: we could also use interpolated string handlers and prevent this from recurring. These handlers should compile and run correctly on both .NET and .NET Framework with the appropriate polyfills. SharpLab shows what a simple example could compile to here. While the current parameters are cheap, this isn't guaranteed - and only these handlers will avoid evaluating them if the log is disabled. |
|
@mdaigle did this affect 7.0 ? |
Description
Connection pool perf benchmarks have shown memory regressions against the 6.1.6 baseline. The cause is that 119
SqlClientEventSource.Log.Try*Event(...)call sites were converted to C# interpolated strings during the netfx/netcore unification.Those overloads are written to be cheap when tracing is off:
That only helps when the caller passes a constant format string plus arguments. An interpolated string is built at the call site before the call, so the guard is reached after the cost has already been paid. Every traced operation allocated a formatted string even with tracing disabled.
Approach
This restores the format string plus arguments style the driver used in 6.1.6:
All 119 sites were converted mechanically with a C#-aware rewriter that handles verbatim strings, nested interpolation holes, alignment and format suffixes, and the
"literal " + $"..."form (roughly a third of the sites, and easy to miss with a naive search). Trace output is unchanged. Every conversion fits an existing overload, soSqlClientEventSourceitself is untouched.Files changed, all under
src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/:Connection/SqlConnectionInternal.cs(the bulk, including the per-checkoutDeactivatepath that drove the pool numbers)SqlCommand.Reader.cs,SqlCommand.cs,SqlCommand.NonQuery.cs,SqlCommand.Xml.cs,SqlCommand.Scalar.csSqlAuthenticationProviderManager.csUtilities/AsyncHelper.csNo public API changes. No behavior changes outside of tracing cost.
Three latent defects fixed in passing
OnFeatureExtAcklogged$"Object ID {0}". Inside an interpolated string{0}is the expression0, so it always reported an object ID of 0 rather than the real one.string.Formatover already-formatted text. The argument is redundant, and a value containing a brace (for example a routed server name) would raise aFormatExceptionfrom inside tracing.Trade-off worth noting
The parameterized form still evaluates argument expressions eagerly, which a
if (Log.Is*On())guard would avoid. The arguments on the hot paths are cheap:ObjectIDis anintpassed through a generic overload so it does not box,ClientConnectionIdis aGuid?,CommandTextis a plain getter, andActivityCorrelator.Currentis thread-local cached. The only allocating arguments are on startup paths inSqlAuthenticationProviderManager.A guard-based variant of the same fix measures byte-for-byte identical and is available on
dev/automation/guard-eager-trace-stringsif reviewers prefer that shape. The parameterized form was chosen because it removes the nesting, matches the convention used everywhere else in the driver, and keeps the call sites diffing cleanly against 6.1.6.Two things for follow-up, not addressed here
Residual 64 bytes/op on pooled open/close. Churn is still exactly 64 B/op above 6.1.6, identically in sync and async. None of it is logging. Confirmed by experiment: caching the per-open
TimeoutTimerdrops churn from 476.56 KB to 429.69 KB per 1000 ops, isolating 48 of the 64 bytes. The remaining 16 B isSqlConnectionobject layout growth. Both look deliberate rather than defects.UseOptimizedAsyncBehaviourdominates the pool numbers. The perf runner's checked-inrunnerconfig.jsoncsetsUseOptimizedAsyncBehaviour: true, which turns offSwitch.Microsoft.Data.SqlClient.UseCompatibilityAsyncBehaviourand...UseCompatibilityProcessSni. Neither switch exists in 6.1.6, so the setting is a no-op on the baseline and a significant behavior change on current. With it on,ConnectionPoolContentionsync allocates 9.49 MB against 6.1.6's 1.61 MB; with it off, 1.84 MB. That is a larger effect than the trace regression and entirely unrelated to it, and likely part of what the original pool reports were picking up. Worth a separate look by the async path owners.Issues
No filed issue. Found while investigating reported connection pool memory regressions against the 6.1.6 perf baseline.
Testing
No new tests. This is a mechanical rewrite of trace call sites that produces identical trace output, so existing EventSource coverage is the right check. The three defect fixes are in trace message content only.
Automated:
Try*Eventsites remain, and validated all 130 trace calls in the touched files for contiguous placeholders, correct arity, and overload availability.Performance, measured back to back on the same machine and SQL Server instance with the repo's own BenchmarkDotNet runners. "6.1.6" is the released package consumed via
-p:ReferenceType=Package -p:MdsPackageVersion=6.1.6, so only the driver varies.UseOptimizedAsyncBehaviourwas off on both builds so the comparison is like for like.ConnectionPoolChurn, allocated per 1000 ops:RapidOpenCloseSingleThreadRapidOpenCloseSingleThreadAsyncConnectionPoolContention, 50 workers / pool 50:ConnectionPoolStress, parallelism 10 / pool 50 shown; all 36 cases behave the same way:RapidFireOpenCloseRandomizedHoldAndQueryMixedSyncAsyncContentionMultiCommandReusePoolExhaustionRecoveryBurstyTrafficPatternAcross all 36 stress cases the fixed build lands within a few percent of 6.1.6, in several cases slightly under it.
Command execution is the bigger real-world win, since it affects any application running queries and not only pooled workloads: repeated
ExecuteReadergoes from 3199.4 B/op to 1027.5 B/op.Measurement caveat: SQL Server ran in an emulated arm64 container (
azure-sql-edge, since themssql/server:2022amd64 image does not run under emulation on Apple silicon). Treat the timing columns as unreliable. The allocation figures are host independent and are what the conclusions rest on.Not covered locally: net462 and Windows-specific paths, which will be exercised by CI.
Guidelines
Please review the contribution guidelines before submitting a pull request: