One attribute on a function, one graph per request, one flush at the end. That is how a database index change turned up in about an hour.

From September 2015 to July 2016 I worked on the account-management APIs at Serve, a payments company American Express had acquired. Those APIs were the centerpiece of the stack: “every single time that you swipe a credit card, you’d get a user through our APIs, and these things had to be fast.” A separate monitoring team was standing up Graphite with Grafana and needed a source. “They really wanted someone to start pumping in a whole bunch of information into their backend to be able to stress test it and to validate. And I said, ‘Yeah, sure, I can do that.’”

What I built was one attribute. Put it on a function and that function got timed, tied to its caller, and written into a graph held in memory for the life of the request — then flushed once, asynchronously, at the end of it. Three sinks read that flush: Graphite for the dashboards, Splunk for the per-request trace, and Redis for a dependency graph that turned into documentation nobody had to write.

The aspect

“In the .NET days aspect-oriented programming had just kind of come out. It was the new thing. So I was eager to try it. And I built an aspect that would go on top of each function that you could just say, ‘Hey, I want this to be monitored.’” Which library it was, I won’t state flatly: “It was a long time ago, but I believe it was something that was PostSharp. I believe that was right.”

The library was not new in 2015 — PostSharp’s own documentation says the product “has been around since the early days of .NET 2.0 in 2004” — but aspect-oriented programming was new to me.

The interception did two things. It timed the call, and it carried identity: “on the first function call, as a request came in… I would assign a request ID, and that request ID would go through the stack, and it would kind of be side-loaded onto each function call.” Which carrier I used for that side-loading, I don’t remember, and I won’t guess. That era had two documented ones. CallContext.LogicalSetData stored an object “in the logical call context” — a .NET Framework mechanism, listed on Microsoft’s docs for versions 1.1 through 4.8.1 and nothing after. AsyncLocal<T>, “ambient data that is local to a given asynchronous control flow,” is listed first for .NET Framework 4.6 — the release that shipped with Visual Studio 2015, so it landed the same year I started.

Then the graph: “an in-memory hash map. Essentially a graph that showed the function that it came from, right, the parent, the current function that it was at, any attributes of that function that we wanted to keep track of… on each function call, I would keep track of the time that it started, the time that it ended, to know latencies.”

The obvious objection is cost, because the attribute went on the busiest function in the stack. “The cost of the aspect really wasn’t much at all. At the end of the day, all the aspect was doing was writing kind of traces into memory and then, in an async way, being flushed at the end of the request. So again, in an async way, so it didn’t really add anything to the cost of those API calls.” Nobody fought me on it. The director had come from a company that was already doing it: “he thought it was a great idea. They were doing things like that … long before we were thinking about doing that.”

Overhead is the half I answered. The other standard complaint about aspects — control flow you can’t see at the call site, woven in at build time — nobody raised with me, so I have no scar to offer on it.

A second aspect, built the same way, cached a function’s result by a hash of its inputs; that one has its own note.

Three sinks

Graphite got function-path aggregates and nothing else. The metric name was the call path in dot notation, and the request ID never entered it. The push was somebody else’s work: “there was another team member that had created a custom Graphite library that would asynchronously take all of these things and, on a separate thread, feed them into Graphite.”

Splunk got the per-request side. When something broke, “the error code would show up on the website, with a request ID. We’d be able to take that, dump it into Splunk, and see the whole trace, right, by sorting on timestamp.”

Redis got the dependency graph — the shape of which function called which, accumulated as traces went by.

Dot paths and tags

“Having that dot notation was fantastic because it helped me create really good dashboards with it. And that’s something that in the future, as I try to use different kinds of technologies instead of Graphite, made creating dashboards a lot more difficult.” That’s a preference I hold, not a verdict I have benchmarked, and I’m not going to name the later tools — I didn’t write down which ones, and I’m not reconstructing it now.

Graphite’s dot path against OpenTelemetry’s attributes, from each project’s own docs.

The flexibility is real, and the dashboards I could build fastest were still the ones over a path.

One log per request

Splunk is where the bill showed up, and the bill is what changed the logging. “For every single log entry that you’d have throughout all your APIs, you would append the request ID. And so in one individual API call, you might have dozens of log entries, which adds a whole lot of extra fluff, if you will, and increases the cost for Splunk. Splunk was expensive, and you paid for the amount of data flowing to it and also the amount of data stored.” Splunk still sells that shape: its own ingest pricing page describes “ingest volume-based pricing… based on gigabytes of data ingested into Splunk.”

So the aggregation moved into memory alongside the trace: “start in-memory storing a log, and then flushing that log at the end. And so along with that, I would also flush the request ID, and all of a sudden you had all the different kind of metrics and context of that one API request inside of one log entry, and it was one JSON log entry, which made it very easy to interrogate.”

The timeline is the part people want to be a clean before-and-after. It wasn’t. “That was a long-moving target, and we eventually got there. But for the longest time we were doing one log entry per log event, and just making sure that we had a request ID associated with it.” For most of my stint the trace got rebuilt in Splunk by request ID and a timestamp sort. I have no Splunk savings figure to show you — the transition was gradual, and I never captured one.

The practice has a public name now. Stripe published canonical log lines on July 30, 2019 — “in addition to their normal log traces, requests… also emit one long log line at the end that includes many of their key characteristics.” That post doesn’t say when Stripe started doing it, and I’m not claiming a date race with anybody. Mine was 2015 into 2016, and it was driven by an invoice. Ten years on, I was still threading a request ID through everything and putting every log in one place.

The docs drew themselves

My manager asked for documentation. “Hey, Cabby, I really need you to document how all this stuff works. I need you to document, like, how this process works.” I hate documentation. “I told him, ‘Hey, I really don’t want to do it, but I’ll do something better.’ And then I came back a few days later.”

What came back was the Redis sink. “As these traces were happening, I would pop in kind of the dependency graph, and then on demand, if you’d go to a website, I’d go pull that information from Redis, and I would dynamically create a graph of the entire call stacks and how everything worked.” It carried average latencies, and “the ability to click on any function call and go into Grafana and see full detailed charts.”

He loved it. He has told the story at three companies since.

What it caught

The backend was Oracle. “Our get-user-info method calls, which was called hundreds of millions of times a day, went from being just a few milliseconds, say 10, 15 milliseconds, to hundreds of milliseconds. And that ultimately caused a huge slowdown across the entire stack.”

The dashboard is what turned that into a diagnosis. “This one particular function now has spiked up from 10 milliseconds to 150 milliseconds or whatever it was.” Then down a level: the function called the database several times, and “the database call that was supposed to be getting that get-user data — that was what increased all the latency.” From onset to standing at the database team’s desk: “probably it was an hour, maybe an hour and a half.” I said, “Hey, you guys did something.” “And then they said, ‘Yeah, we just pushed a change to’ — I don’t know how an index worked or however they did that query. And they rolled it back and the whole state was fine again.”

What I can’t tell you is what that same hunt cost before the platform existed. Nobody measured the before, so there’s no comparison to publish — only the after, and the after was an hour with a chart.

That incident is where the position came from: “that was one of my first times where I really was able to take monitoring and understand that monitor everything is important, and being able to have a visual representation so that when in time of stress you’d be able to just look at something and be like, ‘Oh, okay, well, that’s the problem.’” It’s the same argument I make about a hundred people on a bridge call taking turns asking whose problem it is. One pane of glass, drill until you hit the cause.

The rule

The instrumentation is the smaller lesson — the bigger one is how the work got assigned: “don’t tell me exactly how it needs to be done, tell me what the constraints are, and I’ll figure out the optimal way of dealing with the constraints.” I was handed a constraint: the monitoring backend needed data pushed through it. I was also handed an instruction: write the documentation. The constraint got a platform. The instruction got something better.

Underneath

Docs checked 2026-09-02. None of the code below is from that build. It’s reference, written from the current docs — the modern shape of the same mechanism: an attribute that opens a span per call, and one processor that collapses the request into a single line.

The interception point still exists under its original name. OnMethodBoundaryAspect in PostSharp.Aspects is an “aspect that, when applied to a method defined in the current assembly, inserts a piece of code before and after the body of these methods,” with OnEntry, OnSuccess, OnException, and OnExit. The docs describe it wrapping the target in a try…catch…finally at the IL level. State moves between those handlers through MethodExecutionArgs.MethodExecutionTag, “user-defined state information whose lifetime is linked to the current method execution.” PostSharp’s successor, Metalama, marks OnMethodBoundaryAspect obsolete in favor of OverrideMethodAspect.

The tracing side is no longer bespoke. OpenTelemetry’s .NET docs are explicit that ”.NET is different from other languages/runtimes” here: “the Tracing API is implemented by the System.Diagnostics API, repurposing existing constructs like ActivitySource and Activity to be OpenTelemetry-compliant.” Nesting is automatic — a child started inside a parent “will be tracked as a nested operation” — and Activity.Current is the ambient parent, which is the modern answer to the side-loading I hand-rolled.

using System.Diagnostics;
using PostSharp.Aspects;
using PostSharp.Serialization;

// Written from the PostSharp and OpenTelemetry docs.
// The attribute is the whole interface: [Traced] on a method, nothing else.
[PSerializable]
public sealed class TracedAttribute : OnMethodBoundaryAspect
{
    private static readonly ActivitySource Source = new("Reference.Traced");

    public override void OnEntry(MethodExecutionArgs args)
    {
        // StartActivity parents off Activity.Current automatically, so the
        // request's root activity carries the whole call tree with it.
        var activity = Source.StartActivity(
            $"{args.Method.DeclaringType?.Name}.{args.Method.Name}");

        // code.function.name is the current stable semantic convention and
        // wants the fully-qualified name; code.function and code.namespace
        // are deprecated in favor of it.
        activity?.SetTag(
            "code.function.name",
            $"{args.Method.DeclaringType?.FullName}.{args.Method.Name}");

        args.MethodExecutionTag = activity;
    }

    public override void OnException(MethodExecutionArgs args)
    {
        (args.MethodExecutionTag as Activity)?.SetStatus(
            ActivityStatusCode.Error, args.Exception.GetType().Name);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        // Disposing stops the activity, which is what sets Duration.
        (args.MethodExecutionTag as Activity)?.Dispose();
    }
}

The attribute names come from OpenTelemetry’s code attribute registry: code.function.name, code.file.path, code.line.number, code.column.number, and code.stacktrace are the stable set, and the older code.function, code.namespace, code.filepath, and code.lineno are deprecated — code.namespace was folded into the now fully-qualified code.function.name. Activity.SetStatus(ActivityStatusCode, string?) sets the status and, for Error only, a description. Activity.Duration is “the delta between StartTimeUtc and the end time if the Activity has ended.”

Build-time weaving isn’t the only way in anymore. A runtime proxy works when your seams are interfaces: DispatchProxy “provides a mechanism for instantiating proxy objects and handling their method dispatch,” with a single Invoke(MethodInfo, object[]) hook — though Microsoft’s docs list it for .NET Core 1.0 and later, not .NET Framework. Source generators are the third option. Whichever you pick, the objection I never had to defend still stands: woven or proxied, the call site doesn’t show you that anything is happening.

The canonical line is the second half. OpenTelemetry’s .NET SDK takes a custom processor for exactly this: processors “should inherit from OpenTelemetry.BaseProcessor<Activity>… and implement the OnStart and OnEnd methods,” registered with AddProcessor on the TracerProviderBuilder, per the SDK extension docs. Those docs also warn that both methods “should be thread safe, and should not block or take long time, since they will be called on critical code path” — the same constraint that made the original flush asynchronous.

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Text.Json;
using System.Threading;
using OpenTelemetry;

// Written from the OpenTelemetry .NET SDK docs.
// Accumulate every span of a request, emit one JSON line when the root ends.
public sealed class CanonicalLineProcessor : BaseProcessor<Activity>
{
    private static readonly AsyncLocal<List<object>?> Calls = new();

    public override void OnStart(Activity activity)
    {
        if (activity.Parent is null)
        {
            Calls.Value = new List<object>();
        }
    }

    public override void OnEnd(Activity activity)
    {
        var calls = Calls.Value;
        if (calls is null)
        {
            return;
        }

        calls.Add(new
        {
            fn = activity.DisplayName,
            parent = activity.Parent?.DisplayName,
            ms = activity.Duration.TotalMilliseconds,
        });

        if (activity.Parent is null)
        {
            // One line, one request. Hand it to whatever ships logs.
            Console.WriteLine(JsonSerializer.Serialize(new
            {
                trace_id = activity.TraceId.ToString(),
                total_ms = activity.Duration.TotalMilliseconds,
                calls,
            }));

            Calls.Value = null;
        }
    }
}

That is the whole trade, then and now. I pay once, at the boundary, in memory, and flush once at the end. Instrumentation survives contact with a hot path only when the hot path never waits on it.

More field notes

Start