A reporting endpoint got slow enough that someone pinged me about it, and the method at the center of it looked completely harmless. It took a sequence of orders, logged how many were billable, then added up their amounts. Three lines of real work. The kind of code you skim past in review because there's nothing to argue with.
public static decimal Summarize(IEnumerable<Order> billable)
{
int n = billable.Count();
decimal total = 0m;
foreach (var o in billable)
total += o.Amount;
log.Information("{Count} billable orders", n);
return total;
}
The part I slid right past was the parameter type. IEnumerable<Order>. And here's what the caller was handing in:
Summarize(orders.Where(IsBillable));
A Where doesn't filter anything when you call it. It hands back a little object that promises to filter later, once somebody walks it. And my method walks it twice: once for Count(), once for the foreach. Each walk re-runs the predicate on every element from scratch. The filtering I assumed happened once was happening every single time I touched that variable.
Counting the calls instead of guessing
I didn't want to argue from a hunch, so I made the predicate tell on itself. One static counter, bumped on every call, and a filter that does a bit of real work so re-running it isn't free:
static bool IsBillable(Order o)
{
Probe.PredicateCalls++;
return o.Active && o.Amount >= 50m;
}
Then two versions of the summary. The one I had, and one that walks the query a single time into a list before it reads anything:
// Two walks of the same deferred query.
static decimal SummarizeTwice(IEnumerable<Order> billable)
{
int n = billable.Count(); // walk #1
decimal total = 0m;
foreach (var o in billable) // walk #2
total += o.Amount;
_ = n;
return total;
}
// Walk it once into a list, then read the list.
static decimal SummarizeOnce(IEnumerable<Order> billable)
{
var materialized = billable as IReadOnlyList<Order> ?? billable.ToList();
int n = materialized.Count;
decimal total = 0m;
foreach (var o in materialized)
total += o.Amount;
_ = n;
return total;
}
Two million orders, a fresh deferred query each round, best-of-seven, JIT warmed first. The data gets built once up front so the list itself doesn't land on the scoreboard.
Orders: 2,000,000
Checksums match: True (both 330,342,136)
SummarizeTwice predicate calls: 4,000,000 best time: 55.9 ms
SummarizeOnce predicate calls: 2,000,000 best time: 45.5 ms
Extra calls from the second walk: 2,000,000
Time ratio (twice / once): 1.23x
Four million predicate calls to process two million orders. Exactly double, which is what you'd expect once you can see it: two full passes, every element filtered twice over. The counter catches each call as it happens, so that's an exact count rather than a profiler's estimate.
The time didn't double, and that's the honest part
Here's where I owe you some fairness about the thing I'm warning you off. The clock only moved about 1.2x, nowhere near 2x. My predicate is cheap, a bool check and a decimal compare, and materializing into a list isn't free either, so SummarizeOnce hands some of its win back in allocation. On this toy, the second walk is annoying, not fatal.
So why care? Because the predicate is almost never this cheap in the code that actually hurts. Put a database round trip behind that Where, or a parse, or a call that touches a file or a service, and "I did it twice" stops being 20% and becomes the entire bill. The in-memory version is where you learn the shape of the bug for cheap. The expensive version is where it pages you at 2am. The call count is the number that travels between the two; the milliseconds are specific to how heavy each element happens to be.
The fix is boring, which is how I like my fixes. Walk it once, then read off the result.
One opinion I'll actually plant a flag on: the real bug isn't the double walk, it's the parameter type. IEnumerable<T> is a quiet promise that you'll enumerate it at most once and won't go asking for a count. The moment a method wants both a count and the items, it should say so in its signature. Take IReadOnlyCollection<T> or IReadOnlyList<T> and let the caller decide where materializing happens. That as IReadOnlyList<T> ?? ToList() dance up above is me papering over a contract I should have written properly to begin with.
When not to reach for this: if you enumerate the sequence exactly once, leave it deferred. Materializing a stream you only walk a single time, just to feel safe, is how you turn a lazy pipeline into a buffer holding the whole thing in memory, which is the opposite of what IEnumerable streaming is good for. The problem was never deferral. It was me deferring and then walking twice anyway.
I went spelunking through the rest of that service afterward and found three more .Count()-then-foreach pairs sitting over LINQ queries. None of them were slow yet. All of them were waiting for the source to get expensive.
Got a favorite spot where a deferred query bites? The .Any() guard right before a foreach is the classic one, but I bet some of you have seen sneakier. Tell me in the comments.
The whole thing, if you want to run it
No external packages, just dotnet run -c Release on the .NET 10 SDK. (The GitHub push for this one got blocked by my sandbox's egress rules, so the full sample lives right here instead of in the usual repo.)
using System.Diagnostics;
const int Count = 2_000_000;
const int Rounds = 7;
var orders = Demo.BuildOrders(Count);
var twice = Measure(Demo.SummarizeTwice);
var once = Measure(Demo.SummarizeOnce);
Console.WriteLine($"Orders: {Count:N0}");
Console.WriteLine($"Checksums match: {twice.result == once.result} (both {twice.result:N0})");
Console.WriteLine();
Console.WriteLine($"SummarizeTwice predicate calls: {twice.calls:N0} best time: {twice.ms:F1} ms");
Console.WriteLine($"SummarizeOnce predicate calls: {once.calls:N0} best time: {once.ms:F1} ms");
Console.WriteLine();
Console.WriteLine($"Extra calls from the second walk: {twice.calls - once.calls:N0}");
Console.WriteLine($"Time ratio (twice / once): {twice.ms / once.ms:F2}x");
(decimal result, long calls, double ms) Measure(Func<IEnumerable<Order>, decimal> run)
{
_ = run(orders.Where(Demo.IsBillable)); // warm the JIT
double best = double.MaxValue;
decimal result = 0m;
long calls = 0;
for (int r = 0; r < Rounds; r++)
{
var query = orders.Where(Demo.IsBillable); // fresh deferred query each round
Probe.PredicateCalls = 0;
var sw = Stopwatch.StartNew();
result = run(query);
sw.Stop();
if (sw.Elapsed.TotalMilliseconds < best)
best = sw.Elapsed.TotalMilliseconds;
calls = Probe.PredicateCalls;
}
return (result, calls, best);
}
record Order(int Id, decimal Amount, bool Active);
static class Probe
{
public static long PredicateCalls;
}
static class Demo
{
public static List<Order> BuildOrders(int count)
{
var rng = new Random(1234);
var list = new List<Order>(count);
for (int i = 0; i < count; i++)
{
bool active = rng.Next(3) != 0; // roughly two thirds active
list.Add(new Order(i, rng.Next(1, 500), active));
}
return list;
}
public static bool IsBillable(Order o)
{
Probe.PredicateCalls++;
return o.Active && o.Amount >= 50m;
}
public static decimal SummarizeTwice(IEnumerable<Order> billable)
{
int n = billable.Count();
decimal total = 0m;
foreach (var o in billable)
total += o.Amount;
_ = n;
return total;
}
public static decimal SummarizeOnce(IEnumerable<Order> billable)
{
var materialized = billable as IReadOnlyList<Order> ?? billable.ToList();
int n = materialized.Count;
decimal total = 0m;
foreach (var o in materialized)
total += o.Amount;
_ = n;
return total;
}
}
— still counting things nobody asked me to count
Top comments (0)