Debugowanie C#: kiedy print przestaje się opłacać

Program czyta trzy wiersze z ocenami i liczy średnią dla każdego ucznia:

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}");
}

Po uruchomieniu wypisuje jedną linię i kończy się wyjątkiem:

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

Komunikat podaje plik i numer linii. Nie podaje ani indeksu, którego zabrakło, ani tablicy, w której go zabrakło, ani wiersza danych, przy którym to się stało. Linia 16 to sum += int.Parse(parts[i]); i wykonała się wcześniej pięć razy bez żadnego problemu. Wiśniewska nie pojawia się w wyjściu wcale, bo program kończy się na drugim wierszu, więc z samego ekranu nie wiadomo nawet, czy jej dane są poprawne.

Masz stąd dwie drogi. Dopisać Console.WriteLine i zobaczyć wartości albo postawić breakpoint i zatrzymać program w tym miejscu. Debugowanie C# sprowadza się w praktyce do wyboru między tymi dwoma, tylko że pytanie nie brzmi, które narzędzie jest lepsze. Brzmi: przy którym z kolei pytaniu print przestaje się opłacać.

Ile kosztuje jedno pytanie

Debugowanie C# printami ma zawsze ten sam cykl. Dopisujesz linię, zapisujesz plik, uruchamiasz dotnet run, czytasz wyjście. Zmierzyłem go ośmiokrotnie na Windowsie, na SDK w wersji 10.0.400, za każdym razem dokładając do pętli jeden Console.WriteLine i licząc czas przez 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

Mediana wypada na 6,4 sekundy, a najszybszy przebieg na 5,5. Sam dotnet build, bez uruchamiania, zajmuje w tym samym projekcie 1,6 sekundy.

Ta różnica jest sama w sobie warta uwagi. Prawie pięć sekund schodzi na rzeczy, które nie mają z twoim kodem nic wspólnego: sprawdzenie, czy projekt wymaga przywrócenia pakietów, uruchomienie procesu, start środowiska. Jeżeli zostajesz przy printach, opłaca się raz zbudować projekt i wywoływać potem plik wykonywalny z bin/Debug bezpośrednio.

Sześć sekund to niewiele, dopóki liczysz jedno uruchomienie. Kłopot polega na tym, że jeden print odpowiada na jedno pytanie. Wypisujesz i i dowiadujesz się, że wynosi trzy. To jeszcze nie wystarcza, bo nie wiesz, ile elementów ma parts. Druga linia, kolejne sześć sekund. Teraz widzisz rozmiar tablicy, ale nie wiesz, który wiersz danych za nim stoi, więc dokładasz trzecią.

Do tego dochodzi koszt, którego stoper nie zmierzy. Za każdym razem wracasz do edytora, szukasz miejsca, składasz string interpolowany, zapisujesz plik i przenosisz uwagę z problemu na mechanikę pisania. Po znalezieniu błędu trzeba jeszcze wszystkie te linie usunąć, a print zostawiony przez nieuwagę trafia potem na produkcję i wypisuje probe3 i=3 do logów aplikacji, o której nikt już nie pamięta, że była kiedykolwiek debugowana.

Co widać po jednym zatrzymaniu

Ten sam błąd, tylko zamiast printów breakpoint na linii 16. DevJourney ma wbudowany debugger netcoredbg, więc poniższe wartości pochodzą z tego samego silnika, który obsługuje breakpointy w edytorach opartych o protokół DAP.

Program zatrzymuje się na tej linii sześć razy. Pierwsze pięć zatrzymań to Kowalski i dwie pierwsze oceny Nowaka. Szóste jest tym, o które chodzi:

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

Siedem zmiennych, jedno zatrzymanie, zero zmian w pliku źródłowym. row pokazuje wiersz danych, parts ma trzy elementy zamiast czterech, licznik pętli doszedł do trzech. Cała przyczyna jest w tych trzech wierszach i żaden z nich nie wymagał osobnego uruchomienia.

Wartość tego widoku bierze się z porównania. Na pierwszym zatrzymaniu, jeszcze na Kowalskim, to samo okno wygląda tak:

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

Cztery elementy zamiast trzech i to jest cała różnica między wierszem, który przechodzi, a tym, który nie przechodzi. Klawisz kontynuacji przenosi cię do kolejnego obiegu, gdzie sum wynosi już 5, a licznik 2, i akumulator widać w ruchu bez wypisywania go gdziekolwiek. Nikt tego nie zobaczy w wyjściu programu, bo Kowalski wypisał się poprawnie i zniknął z ekranu. Żeby dojść do tego samego printami, trzeba było wypisywać parts.Length przy każdym obiegu pętli i porównywać liczby w kolumnie tekstu.

Okno obserwowanych wartości przyjmuje też wyrażenia, więc dostajesz rzeczy, których program jeszcze nie wypisał. sum/3 zwraca w tym momencie 2.333333333333333, czyli średnią, jaką Nowak dostałby, gdyby pętla nie wyszła poza tablicę. Jego prawdziwa średnia to 3,5. Drugi błąd, dzielenie przez stałą trójkę zamiast przez liczbę ocen, widać więc przed wyjątkiem i bez dopisywania czegokolwiek.

Czego w oknie zmiennych nie ma

Okno nie jest wszechwiedzące. To też należy do odpowiedzi o próg.

Wpisanie parts.Length jako wyrażenia kończy się w netcoredbg tak:

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

Długość tablicy trzeba odczytać inaczej: rozwijając parts do listy elementów albo czytając {string[3]} z kolumny wartości. Z row.Length jest identycznie. Indeksowanie z kolei działa, parts[0] zwraca "Nowak", a parts[2] zwraca "4", tyle że pytanie o parts[3], czyli o brakujący element, kończy się surowym kodem błędu:

Error: 0x80070057

A jeżeli zamiast stawiać breakpoint poczekasz, aż program sam zakończy się wyjątkiem, debugger zatrzyma się nie w twoim kodzie, tylko tutaj:

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

To ramka wewnątrz środowiska uruchomieniowego. Żeby zobaczyć swoje zmienne, trzeba cofnąć się po stosie wywołań do Program.cs, i dopiero tam okno pokaże cokolwiek użytecznego. Warto o tym wiedzieć, zanim uznasz, że debugger jest zepsuty.

Sam komunikat wyjątku zostaje przy tym po angielsku niezależnie od ustawień. Zmienna DOTNET_CLI_UI_LANGUAGE=pl tłumaczy komunikaty samego narzędzia dotnet, ale nie treść wyjątków, bo współdzielone środowisko uruchomieniowe w wersji 10.0.11 nie zawiera katalogów z tłumaczeniami. Polski Windows nie zmieni tu nic.

Warunek na breakpoincie, który nie zadziałał

Skoro interesujące jest szóste zatrzymanie, nasuwa się skrót: warunek na breakpoincie, żeby program stanął od razu tam, gdzie trzeba. W netcoredbg wygląda to na parts.Length < 4 && i == 3 i debugger przyjmuje taki warunek bez zastrzeżeń.

Po uruchomieniu przychodzi jednak to:

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'.

Warunek jest sprawdzany również w momencie, w którym program stoi jeszcze na pierwszej linii i żadna z tych zmiennych nie została utworzona. Sprawdzenie kończy się błędem, a breakpoint przestaje być warunkowy i zatrzymuje program przy pierwszym trafieniu, tak jakby warunku nie było. Bez czytania okna komunikatów wygląda to na zwykłą awarię narzędzia. Nic tego nie sygnalizuje w samym edytorze, bo lista breakpointów nadal pokazuje warunek tak, jakby obowiązywał.

Da się to obejść, wpisując warunek bez odwołania do właściwości, na przykład samo i == 3. Trzeba jednak wiedzieć, że tak jest, i to jest realna cena debuggera: kilka rzeczy, które trzeba raz przećwiczyć, zanim zaczną oszczędzać czas. Print nie ma takiego progu wejścia. To jego jedyna trwała przewaga.

Próg wypada przy trzecim pytaniu

Zostaje arytmetyka. Jeden print to 6,4 sekundy pracy maszyny plus czas na wpisanie linii i późniejsze jej usunięcie. Breakpoint to jeden build, 1,6 sekundy, i zero kosztu przy każdym kolejnym pytaniu, bo zmienne są już na ekranie.

Przy jednym pytaniu print wygrywa. Wiesz, czego szukasz, dopisujesz jedną linię, masz odpowiedź i nie musisz pamiętać żadnego skrótu klawiszowego.

Przy dwóch wychodzi remis.

Od trzeciego pytania print zaczyna przegrywać i przegrywa coraz wyraźniej, bo każde kolejne kosztuje pełny cykl, podczas gdy debugger wyłożył komplet zmiennych już przy pierwszym zatrzymaniu. Trzy printy to ponad dziewiętnaście sekund samego czekania i trzy powroty do edytora, przy założeniu, że za trzecim razem trafisz w tę zmienną, która odpowiada za błąd.

Sekundy są tu zresztą mniejszą częścią rachunku. Sześć sekund czekania na wynik to akurat tyle, żeby nie opłacało się robić nic innego, a jednocześnie wystarczająco długo, żeby uwaga zdążyła się przesunąć gdzie indziej. Trzy takie przerwy pod rząd i wracasz do problemu, pamiętając już tylko połowę tego, co przed chwilą sprawdzałeś.

Stąd reguła, która sprawdza się w codziennej pracy: jeżeli dopisujesz drugiego printa w tym samym miejscu, to jest moment na breakpoint.

Kiedy print jest jedynym narzędziem, które zadziała

Jest klasa błędów, przy których zatrzymanie programu nie tyle nie pomaga, co zaciera dowody. Dwa zadania zwiększają ten sam licznik po sto tysięcy razy każde, bez żadnej synchronizacji:

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);

Osiem uruchomień pod rząd, ten sam plik wykonywalny, oczekiwana wartość 200000:

200000
170865
189613
200000
164299
200000
200000
200000

Pięć razy poprawnie, trzy razy nie. Nie da się postawić breakpointa na zdarzeniu, które występuje w trzech przebiegach na osiem i o którym z góry nie wiadomo, w którym przebiegu wystąpi. Co gorsza, zatrzymanie jednego wątku daje drugiemu czas na dokończenie pętli, więc samo zajrzenie do środka usuwa warunek, który błąd wywołuje.

Tutaj wygrywa zapis, tylko że i on ma swoją pułapkę. Console.WriteLine w ciele tej pętli oznacza dwieście tysięcy wywołań wypisujących na konsolę, z których każde synchronizuje dostęp do strumienia wyjścia, więc wynik znowu przestaje być wyścigiem, tym razem z winy narzędzia pomiarowego. Zapis musi być tani: licznik zdarzeń, Interlocked.Increment w podejrzanym miejscu, wypisanie wyniku dopiero po zakończeniu obu zadań. Program działa z pełną prędkością, a ty dostajesz przebieg wszystkich iteracji, a nie jeden zatrzymany moment.

Obie techniki zakładają jednak, że potrafisz przeczytać to, co dostajesz. IndexOutOfRangeException mówi mało, ale istnieją komunikaty, które podają wszystko, czego trzeba, i CS0029 przy przypisaniu typów jest tego najlepszym przykładem. Zanim cokolwiek zatrzymasz, potrzebujesz działającego SDK, a instalacja i pierwszy program to kwestia kwadransa.

Breakpointy stawia się w DevJourney w tym samym oknie, w którym piszesz kod, a program kursu wprowadza debugger zaraz po pierwszych pętlach, zanim zdążysz przyzwyczaić się do printów.