C# debugging: when printing stops paying off

This program reads three rows of grades and prints an average for each student:

string[] rows =
{
    "Kowalski;5;4;5",
    "Nowak;3;4",
    "Wisniewska;5;5;4",
};

foreach (var row in rows)
{
    var parts = row.Split(';');
    var name = parts[0];
    double sum = 0;

    for (int i = 1; i <= 3; i++)
    {
        sum += int.Parse(parts[i]);
    }

    Console.WriteLine($"{name}: {sum / 3:F2}");
}

It prints one line and then throws:

Kowalski: 4.67
Unhandled exception. System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at Program.<Main>$(String[] args) in C:\...\dj-dbg\Program.cs:line 16

That gives you a file and a line number. What it withholds is the index that was missing, the array it was missing from, and the row of data being processed when it happened. Line 16 is sum += int.Parse(parts[i]); and it had already run five times without complaint.

From here there are two roads. Add a Console.WriteLine and look at the values, or set a breakpoint and stop the program on that line. Most c# debugging comes down to picking between those two, and the useful question isn’t which tool is better. It’s which question number makes printing stop paying off.

Worth noticing before you pick: Wisniewska never appears in the output at all, because the program dies on the second row, so the screen can’t even tell you whether her data is fine.

What one question costs

Print-driven c# debugging always runs the same cycle. Add a line, save the file, run dotnet run, read the output. I measured it eight times on Windows against SDK 10.0.400, adding one Console.WriteLine to the loop each time and timing it with Measure-Command:

edit+run 1: 6,714 ms
edit+run 2: 7,140 ms
edit+run 3: 5,505 ms
edit+run 4: 5,575 ms
edit+run 5: 6,550 ms
edit+run 6: 6,233 ms
edit+run 7: 6,388 ms
edit+run 8: 6,264 ms

The median is 6.4 seconds and the fastest pass was 5.5. A bare dotnet build on the same project, with no execution, takes 1.6 seconds.

That gap is worth a moment. Compiling costs 1.6 seconds and the full dotnet run costs over six, so nearly five seconds go to things unrelated to your code: checking whether the project needs a restore, starting a process, spinning up the runtime. If you’re staying with prints, build once and invoke the executable in bin/Debug directly.

Six seconds is nothing when you’re counting a single run. The trouble is that one print answers one question. You print i, you learn it’s three, and you’re not done, because you still don’t know how many elements parts holds. Second line, another six seconds. Now you can see the array length but not which row of data produced it, so you add a third.

Then there’s the cost no stopwatch records. Each time you go back to the editor, find the spot, assemble an interpolated string, save, and move your attention off the problem and onto the mechanics of typing. Once you’ve found the bug you have to delete all of it again, and a print left behind by accident ships to production and writes probe3 i=3 into the logs of a service nobody remembers debugging.

A single stop, seven variables

Same bug, but a breakpoint on line 16 instead of prints. DevJourney ships netcoredbg as its bundled debugger, so the values below come from the same engine that drives breakpoints in any editor speaking the DAP protocol.

The program stops on that line six times. The first five are Kowalski plus the first two of Nowak’s grades. The sixth is the one that matters:

args    {string[0]}
rows    {string[3]}
row     "Nowak;3;4"
parts   {string[3]}
name    "Nowak"
sum     7
i       3

Seven variables, one stop, no edit to the source file. None of it had to be typed out. row gives you the offending data, parts holds three elements instead of four, and the loop counter reached three.

What makes that view work is the comparison. On the first stop, still on Kowalski, the same pane reads:

row     "Kowalski;5;4;5"
parts   {string[4]}
name    "Kowalski"
sum     0
i       1

Four elements instead of three, and that single difference separates the row that works from the row that doesn’t. Nothing in the program’s output would have shown it, because Kowalski printed correctly and scrolled away. Press continue and you land on the next iteration with sum at 5 and the counter at 2, watching the accumulator move without printing it anywhere.

The watch pane takes expressions too, which gets you things the program hasn’t printed yet. sum/3 evaluates to 2.333333333333333 right there: the average Nowak would have received if the loop hadn’t walked off the array. His real average is 3.5. So the second bug, dividing by a hard-coded three rather than by the number of grades, is visible before the exception and without adding a single line.

Where the variables pane gives up

The pane doesn’t know everything. That’s part of the answer about the threshold.

Typing parts.Length as a watch expression ends like this in netcoredbg:

error: The name 'parts.Length' does not exist in the current context

Reading the length takes another route, either expanding parts into its elements or reading {string[3]} out of the value column. row.Length behaves the same. Indexing does work, parts[0] returns "Nowak" and parts[2] returns "4", but asking for parts[3], the element that isn’t there, comes back as a raw error code:

Error: 0x80070057

And if you skip the breakpoint and let the program throw on its own, the debugger stops somewhere that isn’t your code at all:

exception-name="System.IndexOutOfRangeException"
exception-stage="unhandled"
func="Internal.Runtime.CompilerHelpers.ThrowHelpers.ThrowIndexOutOfRangeException()"

That’s a frame inside the runtime. To see your own variables you walk back up the call stack to Program.cs, and only there does the pane show anything you can use. Worth knowing before you decide the debugger is broken.

The condition that silently stopped being one

Since the sixth stop is the interesting one, there’s an obvious shortcut: put a condition on the breakpoint so the program halts exactly where you want. In netcoredbg that reads parts.Length < 4 && i == 3, and the debugger accepts it without complaint.

Then you run it:

Breakpoint error: The condition for a breakpoint failed to execute. The condition
was 'parts.Length < 4 && i == 3'. The error returned was 'error: The name
'parts.Length' does not exist in the current context'.

The condition also gets evaluated while the program is still parked on its first line, where none of those variables exist yet. Evaluation fails, and the breakpoint quietly stops being conditional and halts on the very first hit as though you’d never set one. Nothing flags it. The breakpoint list still shows the condition as if it applied.

There’s a workaround, a condition that avoids property access, i == 3 on its own. But you have to know that, and that’s the debugger’s real price: a handful of behaviours you have to meet once before the tool starts saving you time. Printing has no such entry cost, and that’s its one durable advantage.

Why the threshold lands on the third question

What’s left is arithmetic. One print is 6.4 seconds of machine time plus the typing and the later deletion. A breakpoint is one build, 1.6 seconds, and costs nothing on every question after that, because the variables are already on screen.

At one question, printing wins. You know what you’re after, you add a line, you get an answer, and you don’t need to remember a keyboard shortcut.

At two it’s a draw.

From the third question on, printing loses and keeps losing, because each one costs a full cycle while the debugger laid out every variable at the first stop. Three prints is more than nineteen seconds of waiting and three trips back to the editor, assuming the third guess finally lands on the variable that’s actually wrong.

The seconds are the smaller half of the bill anyway. Six seconds is long enough that doing something else isn’t worth it and short enough that your attention drifts regardless. Three of those in a row and you come back holding half of what you were checking.

Hence the rule that survives contact with real work: when you’re adding a second print in the same place, that’s the moment for a breakpoint.

When printing is the only thing that works

There’s a class of bug where stopping the program doesn’t merely fail to help, it destroys the evidence. Two tasks increment the same counter a hundred thousand times each, with no synchronisation:

int counter = 0;

var a = Task.Run(() => { for (int i = 0; i < 100_000; i++) counter++; });
var b = Task.Run(() => { for (int i = 0; i < 100_000; i++) counter++; });

await Task.WhenAll(a, b);

Console.WriteLine(counter);

Eight consecutive runs of the same binary, expected value 200000:

200000
170865
189613
200000
164299
200000
200000
200000

Five correct, three not. You can’t put a breakpoint on an event that shows up in three runs out of eight with no way to predict which. Worse, halting one thread gives the other time to finish its loop, so looking inside removes the condition that produces the bug.

Recording wins here, though it has a trap of its own. A Console.WriteLine in that loop body means two hundred thousand calls, each one synchronising access to the output stream, and the result stops being a race again, this time because of the measuring instrument. The record has to be cheap: an event counter, an Interlocked.Increment where you suspect the problem, and one write after both tasks finish.

Both techniques assume you can read what you’re handed. IndexOutOfRangeException says very little, but plenty of messages tell you everything you need once you know where to look, and CS0029 on an assignment is the clearest example of that. Before you can stop anything you need a working SDK, and installing it and running a first program takes about fifteen minutes.

In DevJourney the breakpoints go in the same window you write the code in, and the course outline brings the debugger in right after the first loops, before printing has time to become a habit.