Merge pull request #57 from EFNext/feat/telemetry

Add telemetry support for diagnostics

Author: koenbeuk

docs/.vitepress/config.mts

@@ -64,6 +64,7 @@ const sidebar: DefaultTheme.Sidebar = {
         { text: 'Switch Expressions', link: '/reference/switch-expressions' },
         { text: 'Expression Transformers', link: '/reference/expression-transformers' },
         { text: 'Diagnostics & Code Fixes', link: '/reference/diagnostics' },
+        { text: 'Telemetry', link: '/reference/telemetry' },
         { text: 'Troubleshooting', link: '/reference/troubleshooting' },
       ]
     }

docs/reference/telemetry.md

@@ -0,0 +1,88 @@
+# Telemetry
+
+ExpressiveSharp emits runtime telemetry through the standard .NET diagnostics primitives — `ActivitySource` for distributed traces, `Meter` for metrics, and `EventSource` for previously-silent failure paths. All three share the source name `ExpressiveSharp` (also exposed as the constant `ExpressiveDiagnostics.SourceName`).
+
+Every instrument is **zero-cost when no listener is attached**: counters and activities short-circuit on the no-listener path, and the more expensive observations (node-counting, `MemberInfo.ToString()` for tags) are guarded explicitly.
+
+## Activity (Distributed Tracing)
+
+A single span is emitted from the `ExpressiveSharp` `ActivitySource` (the source's name is also exposed as the constant `ExpressiveDiagnostics.SourceName`):
+
+| Span | Emitted from | Tags |
+|------|--------------|------|
+| `Expressive.Expand` | `expression.ExpandExpressives()` (and the EF Core / MongoDB query compiler decorators that call into it) | `transformer.count`, `expansion.node_count`, `expansion.duration_ms` |
+
+Because the span runs synchronously inside the EF Core query pipeline, it nests cleanly under EF Core's `Microsoft.EntityFrameworkCore` activity. Trace viewers will show:
+
+```
+EF query  →  Expressive.Expand  →  SQL execution
+```
+
+### OpenTelemetry
+
+```csharp
+using var tracerProvider = Sdk.CreateTracerProviderBuilder()
+    .AddSource("ExpressiveSharp")
+    .AddSource("Microsoft.EntityFrameworkCore") // optional — nests Expressive.Expand under EF activities
+    .AddOtlpExporter()
+    .Build();
+```
+
+::: tip
+The `expansion.duration_ms` tag is recorded redundantly with the activity's intrinsic duration so consumers that only run a metrics pipeline (no tracer) still get the timing.
+:::
+
+## Meter (Metrics)
+
+Five instruments on `Meter("ExpressiveSharp")`:
+
+| Instrument | Type | Unit | Tags | What it tells you |
+|------------|------|------|------|-------------------|
+| `expressive.cache.hits` | Counter<long> | — | — | The runtime resolver cache served the lookup without computing it again. |
+| `expressive.cache.misses` | Counter<long> | — | — | The resolver had to compute the lambda for a member it hadn't seen before. |
+| `expressive.reflection_fallback.count` | Counter<long> | — | `member` | The slow reflection-based fallback ran. Used for open-generic class members and generic methods not in the static registry. **Sustained activity here is a perf bug.** |
+| `expressive.expansion.node_count` | Histogram<int> | nodes | — | Total expression-tree node count after expansion + transformers. Surfaces members that explode into massive trees and bloat SQL. |
+| `expressive.expansion.duration_ms` | Histogram<double> | ms | — | Wall-clock cost of one `ExpandExpressives()` call. |
+
+### Live monitoring with `dotnet-counters`
+
+```sh
+dotnet-counters monitor -n MyApp ExpressiveSharp
+```
+
+### OpenTelemetry
+
+```csharp
+using var meterProvider = Sdk.CreateMeterProviderBuilder()
+    .AddMeter("ExpressiveSharp")
+    .AddOtlpExporter()
+    .Build();
+```
+
+::: info
+A healthy steady-state has **`cache.hits` ≫ `cache.misses`** after warmup, and **`reflection_fallback.count` should be flat** unless your code uses open-generic `[Expressive]` members. A non-trivial slope on `reflection_fallback.count` means the runtime is paying reflection costs that the static registry could have served — please file an issue with a reproducer.
+:::
+
+## EventSource (Failure Diagnostics)
+
+Three events on `EventSource("ExpressiveSharp")`. They surface failure paths that ExpressiveSharp deliberately recovers from but that historically left users debugging by rubber duck.
+
+| Event ID | Name | Level | Payload | When it fires |
+|----------|------|-------|---------|---------------|
+| `1` | `RegistryInitializationFailed` | Error | `assemblyName`, `exceptionType`, `message` | An assembly's generated `ExpressionRegistry` static constructor threw. The registry is marked inert (no `[ExpressiveFor]` lookups will succeed against it) but the process keeps running. |
+| `2` | `HotReloadResetFailed` | Warning | `assemblyName`, `exceptionType`, `message` | A hot-reload edit-and-continue update arrived but invalidating the assembly's expression registry threw. The stale registry stays cached, so the next lookup may return pre-edit lambdas. |
+| `3` | `MultipleExpressiveForMappings` | Error | `memberInfoString`, `firstAssembly`, `secondAssembly` | Two different assemblies both registered an `[ExpressiveFor]` mapping for the same member. An `InvalidOperationException` is thrown immediately after; the event fires first so it survives even if the exception is later caught. |
+
+### Collecting with `dotnet-trace`
+
+The most common path. No code changes, no app restart:
+
+```sh
+dotnet-trace collect -n MyApp --providers ExpressiveSharp::Verbose
+```
+
+Open the resulting `.nettrace` file in [PerfView](https://github.com/microsoft/perfview) or Visual Studio's diagnostic tools to inspect the events.
+
+## Stability
+
+The source name `ExpressiveSharp`, the instrument names, and the EventSource event IDs are part of the public API surface and follow the same stability rules as the rest of ExpressiveSharp. Tags carried on activities and counters may be extended (new tags added) but existing tags will not be renamed within a major version.

docs/reference/troubleshooting.md

@@ -322,6 +322,23 @@ public double Total => Price * Quantity;
 public double TotalWithTax => Total * (1 + TaxRate);  // Total is inlined
 ```
 
+### How do I see what ExpressiveSharp is doing at runtime?
+
+ExpressiveSharp emits three independent signals on the `ExpressiveSharp` source name — each requires a different out-of-process tool:
+
+```sh
+# Failure events (registry static-ctor failures, hot-reload reset failures, [ExpressiveFor] collisions)
+dotnet-trace collect -n MyApp --providers ExpressiveSharp::Verbose
+
+# Metrics (cache hit/miss ratios, expansion timings, reflection-fallback rate)
+dotnet-counters monitor -n MyApp ExpressiveSharp
+
+# Distributed tracing (the Expressive.Expand activity span) — wire via OpenTelemetry,
+# see the Telemetry reference for the AddSource("ExpressiveSharp") snippet.
+```
+
+See [Telemetry](./telemetry) for the full instrument and event reference.
+
 ### Is ExpressiveSharp EF Core specific?
 
 No. The core `ExpressiveSharp` package works with any LINQ provider or standalone expression tree use case. See [ExpressionPolyfill.Create](../guide/expression-polyfill) and [IExpressiveQueryable](../guide/expressive-queryable) for non-EF-Core usage.

src/ExpressiveSharp/Diagnostics/ExpressiveDiagnostics.cs

@@ -0,0 +1,27 @@
+using System.Diagnostics;
+using System.Diagnostics.Metrics;
+
+namespace ExpressiveSharp.Diagnostics;
+
+public static class ExpressiveDiagnostics
+{
+    public const string SourceName = "ExpressiveSharp";
+
+    internal static readonly ActivitySource ActivitySource = new(SourceName);
+    internal static readonly Meter Meter = new(SourceName);
+
+    internal static readonly Counter<long> CacheHits =
+        Meter.CreateCounter<long>("expressive.cache.hits");
+
+    internal static readonly Counter<long> CacheMisses =
+        Meter.CreateCounter<long>("expressive.cache.misses");
+
+    internal static readonly Counter<long> ReflectionFallback =
+        Meter.CreateCounter<long>("expressive.reflection_fallback.count");
+
+    internal static readonly Histogram<int> ExpansionNodeCount =
+        Meter.CreateHistogram<int>("expressive.expansion.node_count");
+
+    internal static readonly Histogram<double> ExpansionDurationMs =
+        Meter.CreateHistogram<double>("expressive.expansion.duration_ms", unit: "ms");
+}

src/ExpressiveSharp/Diagnostics/ExpressiveEventSource.cs

@@ -0,0 +1,62 @@
+using System;
+using System.Diagnostics.Tracing;
+using System.Reflection;
+
+namespace ExpressiveSharp.Diagnostics;
+
+[EventSource(Name = ExpressiveDiagnostics.SourceName)]
+internal sealed class ExpressiveEventSource : EventSource
+{
+    public static readonly ExpressiveEventSource Log = new();
+
+    private ExpressiveEventSource() { }
+
+    [Event(1, Level = EventLevel.Error,
+        Message = "ExpressiveSharp registry initialization failed for assembly '{0}': {1}: {2}")]
+    public void RegistryInitializationFailed(string assemblyName, string exceptionType, string message)
+        => WriteEvent(1, assemblyName, exceptionType, message);
+
+    [NonEvent]
+    public void RegistryInitializationFailed(Assembly assembly, Exception exception)
+    {
+        if (!IsEnabled()) return;
+        // The caller catches TypeInitializationException, but the actionable cause is the
+        // static-ctor exception nested inside it — unwrap so consumers see the real failure.
+        var actual = exception is TypeInitializationException && exception.InnerException is { } inner
+            ? inner : exception;
+        RegistryInitializationFailed(
+            assembly.GetName().Name ?? "<unknown>",
+            actual.GetType().FullName ?? actual.GetType().Name,
+            actual.Message);
+    }
+
+    [Event(2, Level = EventLevel.Warning,
+        Message = "ExpressiveSharp hot-reload registry reset failed for assembly '{0}': {1}: {2}")]
+    public void HotReloadResetFailed(string assemblyName, string exceptionType, string message)
+        => WriteEvent(2, assemblyName, exceptionType, message);
+
+    [NonEvent]
+    public void HotReloadResetFailed(Assembly assembly, Exception exception)
+    {
+        if (!IsEnabled()) return;
+        HotReloadResetFailed(
+            assembly.GetName().Name ?? "<unknown>",
+            exception.GetType().FullName ?? exception.GetType().Name,
+            exception.Message);
+    }
+
+    [Event(3, Level = EventLevel.Error,
+        Message = "Multiple [ExpressiveFor] mappings found for '{0}' in assemblies '{1}' and '{2}'")]
+    public void MultipleExpressiveForMappings(string memberInfoString, string firstAssembly, string secondAssembly)
+        => WriteEvent(3, memberInfoString, firstAssembly, secondAssembly);
+
+    [NonEvent]
+    public void MultipleExpressiveForMappings(MemberInfo memberInfo, Assembly first, Assembly second)
+    {
+        if (!IsEnabled()) return;
+        MultipleExpressiveForMappings(
+            memberInfo.ToString() ?? memberInfo.Name,
+            first.GetName().Name ?? "<unknown>",
+            second.GetName().Name ?? "<unknown>");
+    }
+}

src/ExpressiveSharp/Extensions/ExpressionExtensions.cs

@@ -1,4 +1,6 @@
+using System.Diagnostics;
 using System.Linq.Expressions;
+using ExpressiveSharp.Diagnostics;
 using ExpressiveSharp.Services;
 
 namespace ExpressiveSharp;
@@ -16,28 +18,70 @@ public static Expression ExpandExpressives(this Expression expression)
     /// Like <see cref="ExpandExpressives(Expression)"/> but uses transformers from the given options.
     /// </summary>
     public static Expression ExpandExpressives(this Expression expression, ExpressiveOptions options)
-    {
-        var expanded = new ExpressiveReplacer(new ExpressiveResolver()).Replace(expression);
-        var transformers = options.GetTransformers();
-        foreach (var transformer in transformers)
-        {
-            expanded = transformer.Transform(expanded);
-        }
-        return expanded;
-    }
+        => ExpandExpressivesCore(expression, options.GetTransformers());
 
     /// <summary>
     /// Like <see cref="ExpandExpressives(Expression)"/> but uses the explicitly supplied transformers.
     /// </summary>
     public static Expression ExpandExpressives(
         this Expression expression,
         params IExpressionTreeTransformer[] transformers)
+        => ExpandExpressivesCore(expression, transformers);
+
+    private static Expression ExpandExpressivesCore(
+        Expression expression,
+        IReadOnlyList<IExpressionTreeTransformer> transformers)
     {
+        using var activity = ExpressiveDiagnostics.ActivitySource.StartActivity("Expressive.Expand");
+
+        var measureDuration = activity is not null || ExpressiveDiagnostics.ExpansionDurationMs.Enabled;
+        var startTimestamp = measureDuration ? Stopwatch.GetTimestamp() : 0L;
+
         var expanded = new ExpressiveReplacer(new ExpressiveResolver()).Replace(expression);
-        foreach (var transformer in transformers)
+        for (var i = 0; i < transformers.Count; i++)
+        {
+            expanded = transformers[i].Transform(expanded);
+        }
+
+        if (activity is not null)
+        {
+            activity.SetTag("transformer.count", transformers.Count);
+        }
+
+        if (activity is not null || ExpressiveDiagnostics.ExpansionNodeCount.Enabled)
+        {
+            var nodeCount = ExpansionNodeCounter.Count(expanded);
+            ExpressiveDiagnostics.ExpansionNodeCount.Record(nodeCount);
+            activity?.SetTag("expansion.node_count", nodeCount);
+        }
+
+        if (measureDuration)
         {
-            expanded = transformer.Transform(expanded);
+            var elapsedMs = Stopwatch.GetElapsedTime(startTimestamp).TotalMilliseconds;
+            ExpressiveDiagnostics.ExpansionDurationMs.Record(elapsedMs);
+            activity?.SetTag("expansion.duration_ms", elapsedMs);
         }
+
         return expanded;
     }
+
+    private sealed class ExpansionNodeCounter : ExpressionVisitor
+    {
+        private int _count;
+
+        public static int Count(Expression? expression)
+        {
+            if (expression is null) return 0;
+            var counter = new ExpansionNodeCounter();
+            counter.Visit(expression);
+            return counter._count;
+        }
+
+        public override Expression? Visit(Expression? node)
+        {
+            if (node is null) return null;
+            _count++;
+            return base.Visit(node);
+        }
+    }
 }

src/ExpressiveSharp/Services/ExpressiveHotReloadHandler.cs

@@ -2,6 +2,7 @@
 using System.Collections.Generic;
 using System.Reflection;
 using System.Reflection.Metadata;
+using ExpressiveSharp.Diagnostics;
 
 [assembly: MetadataUpdateHandler(typeof(ExpressiveSharp.Services.ExpressiveHotReloadHandler))]
 
@@ -56,8 +57,17 @@ private static void ResetGeneratedRegistries(IEnumerable<Assembly> assemblies)
             var reset = registryType?.GetMethod("ResetMap", BindingFlags.Static | BindingFlags.NonPublic);
             if (reset is null) continue;
 
-            try { reset.Invoke(null, null); }
-            catch { /* best-effort; stale registry stays stale */ }
+            try
+            {
+                reset.Invoke(null, null);
+            }
+            catch (Exception ex)
+            {
+                // Best-effort; stale registry stays stale. Surface via EventSource so
+                // a hot-reload edit-and-continue failure is no longer silent.
+                var inner = (ex as TargetInvocationException)?.InnerException ?? ex;
+                ExpressiveEventSource.Log.HotReloadResetFailed(assembly, inner);
+            }
         }
     }
 }