Pomiar czasu wykonywania metod w C#

Testy wydajnościowe

Nie skłamię pisząc, że większość użytkowników dużych aplikacji w którymś momencie pracy z aplikacją wysunie oskarżenia następującej treści: ale to wolno działa!. Każdy chce, aby każda aplikacja działała błyskawicznie. Każdy chce, aby najnowsza gra chodziła w najwyższych rozdzielczościach na komputerze, który kupiliśmy trzy lata temu w promocji, przed świętami, w pobliskim sklepie. To przecież dobry komputer - mówimy. Gdy już wykorzystamy pół słownika wulgaryzmów na tę bezduszną maszynę, wykorzystujemy drugą część naszego nieparlamentarnego słownictwa na oprogramowanie. Przeklinamy autorów oprogramowania za ich kompetencje, a właściwie ich brak. Taki paradoks - przeklinamy coś, czego nie ma. Ale nie o to chodzi. To jest tylko jedna strona, dla przeciętnego odbiorcy tego wpisu druga strona. Zakładam bowiem, że czytają ten wpis raczej twórcy oprogramowania.

A twórca oprogramowania nie ma łatwo. W jego głowie tysiące myśli toczą nieustającą walkę. A tam gdzie walka, tam i ofiary. Pisanie oprogramowania wiąże się z szeregiem decyzji. Optymalizacja wymaga czasu. Czas z kolei przeliczany jest na pieniądz. Będący pod presją dyrektora finansowego kierownik projektu wybiera drogę tańszą. Tańsza droga doprowadza do mniej przemyślanych algorytmów i w konsekwencji wolniej działającego oprogramowania. Ten, który pisze kod znajduje się na dole piramidy. Pod naciskiem wszystkich warstw kierowniczych.

Z drugiej strony przedwczesna optymalizacja też nie jest dobra. Często nie ma potrzeby tracić czasu na pisanie superwydajnych algorytmów do aplikacji, która wykona się raz w miesiącu kilka sekund, może nawet kilka minut dłużej. Najczęściej stosuje się rozwiązanie tańsze. Pisze się kod tak, aby był czytelny, prosty i nie wymagał dużych nakładów czasowych. Potem próbuje się w gotowej aplikacji wykonać podstawowe zadania. Jeżeli nie odczujemy niedogodności, wszystko jest w porządku. Jeżeli coś wykonuje się zbyt długo, próbujemy dokładniej zmierzyć czas podejrzanych metod i zastanawiamy się, jak je zoptymalizować. I to właśnie dokładnymi pomiarami czasu zajmę się dzisiaj szczególnie.

Pomiar czasu w podejściu tradycyjnym

Algorytm pomiaru czasu wydaje się prosty: pobieramy czas początkowy, wykonujemy jakieś operacje, a następnie pobieramy czas końcowy. Różnica pomiędzy czasem końcowym a początkowym to właśnie czas operacji. W zasadzie jedyną decyzją jest wskazanie sposobu pobierania czasu. Do podstawowych zastosowań najlepiej nadaje się wywołanie DateTime.Now. Trzeba jednak wiedzieć, że DateTime.Now korzysta z zegara systemowego i jest mało dokładny. Do pomiarów wydajności znacznie lepiej używać klasy Stopwatch, która zrobi to dokładniej. Zgodnie z dokumentacją Stopwatch korzysta z zegara sprzętowego wysokiej rozdzielczości, a jeżeli tego zegara nie ma (wyjątkowo rzadkie przypadki), wtedy korzysta z zegara systemowego. W najgorszym razie Stopwatch będzie działało równie dobrze co Stopwatch. Zanim opiszę szczegóły przyjrzyjmy się poniższemu przykładowi:

var watch = new Stopwatch();
watch.Start();
function();
watch.Stop();
Console.WriteLine("Czas: {0} ms", 1000.0 * watch.ElapsedTicks / Stopwatch.Frequency);

Taki schemat można spokojnie przyjąć do pomiaru czasu eksperymentalnych metod, w projekcie gdzieś na boku. Trudno bowiem wyobrazić sobie, że w każdym miejscu będziemy pisać tyle linijek kodu. Wkrótce to naprawimy. Wyjaśnienia wymaga również sposób przeliczania pomiaru na znane nam jednostki czasowe.

Tyknięcia zegara w milisekundach

W .NET istnieje specjalny typ, który reprezentuje różnice czasowe - TimeSpan. Powstaje on między innymi w wyniku zastosowania operatora różnicy na dwóch datach typu DateTime. Klasa Stopwatch posługuje się innymi jednostkami - nazwę je sobie tyknięciami (ang. tick). Wprawdzie tick może oznaczać również takty procesora, ale tłumaczenie jednostek Stopwatch byłoby sporym nadużyciem. To co dostajemy to nie są takty. Skoro nie takty to co? A gdybyśmy tak mieli rzeczywiste procesory i takty? Przeliczenie wymagałoby poznania procesora, a przynajmniej jego częstotliwości taktowania. Wystarczyłoby w tym przypadku podzielić liczbę taktów przez częstotliwość taktowania. Popatrzmy na przykłady:

//Procesor 1 MHz, 200 taktów
200/1000000 = 0.0002 [s] = 0.2 [ms]

//Procesor 1 GHz, 1500 taktów
1500/1000000000 = 0.0000015 [s] = 0.0015 [ms]

Podobnie jest z obiektem klasy Stopwatch. Tam zamiast fizycznego procesora dostajemy procesor wirtualny, z wirtualną częstotliwością. Ta wirtualna częstotliwość może być pobrana ze statycznej właściwości Stopwatch.Frequency. Wirtualne takty, które zostały zliczone pomiędzy uruchomieniem (metoda Start) a zakończeniem (metoda Stop), są dostępne pod właściwością ElapsedTicks. Mamy zatem:

//Czas w sekundach
var timeInSeconds = watch.ElapsedTicks / Stopwatch.Frequency;

//Czas w milisekundach
var timeInMilliseconds = 1000.0 * watch.ElapsedTicks / Stopwatch.Frequency;

Jeżeli chcemy uzyskać pełną strukturę TimeSpan lub zadowala nas pomiar zaokrąglony do pełnych milisekund, możemy skorzystać z wbudowanych właściwości:

TimeSpan elapsedSpan = watch.Elapsed;
long milliseconds = watch.ElapsedMilliseconds;

To tyle teorii. Czas na rozwiązanie, które uprości wykonywanie pomiarów.

Pomiar czasu wyrażenia

Pierwsze podejście będzie wykorzystywało właściwości wyrażeń Lambda. Metoda do pomiaru czasu przyjmie dowolną akcję (obiekt klasy Action) i zmierzy czas jej wykonania. Zamiast opisywać, pokażę fragment kodu:

public static double GetTime(Action function)
{
    var watch = new Stopwatch();
    watch.Start();
    function();
    watch.Stop();
    return 1000.0 * watch.ElapsedTicks / Stopwatch.Frequency;
}

Zakładając, że metoda znajduje się w klasie Performance, jej wywołanie sprowadza się do następującej linijki:

//Pomiar czasu jednego wyrażenia
var time1 = Performance.GetTime(() => Thread.Sleep(50));

//Pomiar czasu kilku wyrażeń
var time2 = Performance.GetTime(() =>
{
    Thread.Sleep(11);
    Thread.Sleep(12);
});

Pomiar wydajności szybkich instrukcji

Zdarza się, że jakaś metoda jest na tyle szybka, że pomiar jej jednorazowego wywołania obarczony jest dużym narzutem samego pomiaru. W takich przypadkach lepszym rozwiązaniem jest zmierzenie czasu setek, tysięcy, a nawet miliona powtórzeń. Wykorzystanie wyrażeń Lambda sprowadza powyższe założenia do następującego kodu:

public static double GetTime(Action function, int repetitions)
{
    return GetTime(() =>
    {
        for (int i = 0; i < repetitions; i++)
            function();
    });
}

Czas zwracany przez metodę jest łącznym czasem całej operacji, to jest pętli z repetitions powtórzeniami. Gdybyśmy zechcieli czas pojedynczej instrukcji, wystarczy podzielić wynik przez liczbę powtórzeń.

Średni czas wykonania metody

Jak nietrudno się domyślić, stworzenie odpowiedniej metody, która policzy średni czas wykonania też nie będzie trudne. Popatrzmy na poniższy listing:

public static double GetAverageTime(Action function, int repetitions)
{
    double totalTime = 0.0;
    for (int i = 0; i < repetitions; i++)
    {
        totalTime += GetTime(function);
    }
    return totalTime / repetitions;
}

Metoda nadaje się do testowania czasu wykonywania się metod pod obciążeniem lub wywołań sieciowych. Metodę można stosować tam, gdzie te czasy faktycznie mogą się różnić. Warto jednocześnie zwrócić uwagę na stan aplikacji podczas testowania. W systemach informatycznych powszechne jest stosowanie pamięci podręcznych, buforów lub innych struktur danych, które przyspieszają wykonywanie operacji. Baza danych zapytana drugi raz o to samo nie będzie wykonywała kosztownych odczytów - skorzysta z tego, co ma w pamięci. Jeżeli podczas pierwszego wywołania budujemy drzewo binarne, zapamiętujemy je, a potem tylko z niego korzystamy, wtedy jasne staje się, że pierwsze wywołanie będzie wolniejsze. Pierwsze uruchomienie usługi sieciowej lub aplikacji wymaga uruchomienia przez system procesu, wczytania bibliotek i załadowania ich do pamięci, przydzielenia wątku i mnóstwa innych, niewidocznych gołym okiem operacji. Nie ma jednego sposobu radzenia sobie z tym zagadnieniem. Często stosuje się tzw. rozgrzewanie systemu (ang. warm up). Wykonuje się wtedy kilka operacji poza pomiarem i pozwala się systemom przygotować: uzupełnić pamięć operacyjną, utworzyć słowniki z haszowaniem, uruchomić i połączyć z usługami. Gdy system się rozkręci, można mierzyć czas. Implementacja takiego algorytmu mogłaby wyglądać następująco:

public static double GetAverageTime(Action function, int warmUpRepetitions, int repetitions)
{
    GetAverageTime(function, warmUpRepetitions);
    return GetAverageTime(function, repetitions);
}

Metody można mnożyć. Łatwo wyobrazić sobie metodę, która mierzy czas maksymalny kilku wywołań, metodę, która pomija wyniki odbiegające od przeciętnych. Pozostawiam to do samodzielnej implementacji. Zajmę się nieco inną metodą pomiaru.

Pomiar bloków kodu

Wprawdzie poprzednia metoda może spokojnie zmierzyć czas wykonywania się dowolnego bloku z instrukcjami, ale pokażę coś, co może się niektórym wydać bardziej eleganckie. Pomiar czasu z wykorzystaniem instrukcji using, która może od razu wykonać logowanie. Wykorzystam to, że using automatycznie wykonuje metodę Dispose obiektu. Popatrzmy na definicję klasy, którą nazwałem Measure:

class Measure : IDisposable
{
    public Stopwatch Watch { get; set; }
    public string Name { get; set; }

    public Measure([CallerMemberName]string name = null)
    {
        Name = name;
        Watch = new Stopwatch();
        Watch.Start();
    }

    public void Dispose()
    {
        Watch.Stop();
        OnMeasure(1000.0 * Watch.ElapsedTicks / Stopwatch.Frequency);
    }

    public virtual void OnMeasure(double milliseconds)
    {
        Debug.WriteLine("{0}: {1:F4}", Name, milliseconds);
    }
}

Dla niektórych zaskakujący może być konstruktor. Postanowiłem, że każdy pomiar czasu musi mieć jakąś nazwę, bo trzeba przecież w jakiś sposób zidentyfikować pomiar wśród wielu innych. Tę nazwę można przekazać w postaci parametru, tak jak do zwykłego konstruktora, ale nie trzeba. Ten, być może tajemniczy dla niektórych, atrybut sprawia, że w przypadku braku parametru kompilator automatycznie wstawi w to miejsce nazwę metody, w której wykonywany jest pomiar. W konstruktorze uruchamiamy też zegar. Gdy opuścimy blok using, wywołana zostanie metoda IDisposable.Dispose. Tam zatrzymujemy zegar i wywołujemy metodę wirtualną z wyliczonym czasem. Dlaczego wirtualną? A po to, aby dało się modyfikować jej zachowanie. W wersji podstawowej komunikat wypisywany jest w oknie Debug, w wersji innej mógłby być wypisywany na przykład w oknie konsoli. Popatrzmy na poniższy listing:

class ConsoleMeasure:Measure
{
    public ConsoleMeasure([CallerMemberName]string name = null)
        :base(name)
    {

    }

    public override void OnMeasure(double milliseconds)
    {
        Console.WriteLine("{0} {1}: {2:F4}", DateTime.Now, Name, milliseconds);
    }
}

Przeciążona metoda oprócz tego, że wypisuje w oknie konsoli, modyfikuje sam komunikat doklejając datę zdarzenia. To przykład, który miał pokazać potencjał dziedziczenia w przypadku klasy Measure. Aby pokazać elegancję rozwiązania, popatrzmy na przykładowe wywołania:

using (new Measure())
{
    Thread.Sleep(123);
}

using (new Measure("Pobieranie danych z usługi"))
{
    Thread.Sleep(48);
}

using (new ConsoleMeasure())
{
    Thread.Sleep(18);
}

Oczywiście zamiast wywołań Thread.Sleep(#) można umieścić dowolne instrukcje. Przeciążona metoda może być w łatwy sposób zmodyfikowana tak, aby zapisywała dane w pliku, w bazie danych. Bazowa klasa może być dostosowana do reguł wstrzykiwania zależności, a sama implementacja podmieniana w zależności od potrzeb. Możliwa jest również obróbka tych danych.

Agregacja i przetwarzanie danych pomiarowych

Klasa Measure może być dowolnie rozszerzana, a to, co rzeczywiście będzie wykonywała, ograniczone jest tylko umiejętnościami programisty i jego wyobraźnią. Popatrzmy na przykładową implementację wykorzystującą zewnętrzny agregator:

class MemoryGroupMeasure:Measure
{
    public MemoryMeasureAggregator Aggregator { get; set; }

    public MemoryGroupMeasure(MemoryMeasureAggregator aggregator, [CallerMemberName]string name = null)
        : base(name)
    {
        Aggregator = aggregator;
    }

    public override void OnMeasure(double milliseconds)
    {
        Aggregator.Aggregate(Name, milliseconds);
    }
}

Konstruktor, oprócz nazwy dostępnej już wcześniej, przyjmuje obiekt gromadzący dane. Metoda OnMeasure zostaje przeciążona w taki sposób, aby nakazać temu obiektowi gromadzącemu dane zapamiętać wykonany właśnie pomiar. Jeżeli tylko obiekt agregujący będzie współdzielony przez wszystkie bloki wykonujące pomiary, będzie mógł obliczyć praktycznie dowolne statystyki. Jak taki obiekt agregujący mógłby wyglądać? Popatrzmy na poniższy listing:

class MemoryMeasureAggregator
{
    private Dictionary<string, List<double>> Measures { get; set; }

    public MemoryMeasureAggregator()
    {
        Measures = new Dictionary<string, List<double>>();
    }

    public void Aggregate(string name, double totalTime)
    {
        List<double> current = null;
        if (Measures.TryGetValue(name, out current))
        {
            current.Add(totalTime);
        }
        else
        {
            Measures.Add(name, new List<double>() { totalTime });
        }
    }

    public Measurement Average(string name)
    {
        List<double> current = null;
        if (Measures.TryGetValue(name, out current))
        {
            return new Measurement(name, current.Average());
        }
        else
        {
            return new Measurement(name, 0.0);
        }
    }

    public IEnumerable<Measurement> Average()
    {
        return Measures.Select(a => new Measurement(a.Key, a.Value.Average()));
    }
}

Implementacja metody Aggregate nie powinna być zaskakująca: nazwa metody jest kluczem w słowniku, którego wartościami jest lista wszystkich pomiarów dla tego klucza. Pozostałe dwie metody służą do pobrania średniego czasu wykonywania się jednej metody (definiowanej przez nazwę), oraz średnich czasów wszystkich metod. Wynik zwracany jest w strukturze Measurement. Klasa Measurement jest prosta:

class Measurement
{
    public string Name { get; private set; }
    public double Value { get; private set; }

    public Measurement(string name, double value)
    {
        Name = name;
        Value = value;
    }

    public static implicit operator double (Measurement m)
    {
        return m.Value;
    }
}

Tak jak i w innych miejscach tak i tutaj wspomnę, że klasa agregująca może być dowolnie rozszerzana. Można dodać funkcję do pobierania wartości minimalnej, maksymalnej, można się pokusić o mediany, odchylenia. Popatrzmy jeszcze na przykład testowy:

var aggregator = new MemoryMeasureAggregator();
Random random = new Random();
string[] names = { "Metoda A", "Metoda B", "Metoda C" };
for (int i = 0; i < 10; i++)
{
    using (new MemoryGroupMeasure(aggregator, names[random.Next(names.Length)]))
    {
        Thread.Sleep(random.Next(10, 20));
    }
}
foreach (var measurement in aggregator.Average())
    Console.WriteLine("{0}: {1:F4}", measurement.Name, measurement.Value);

W pokazanym fragmencie widać, że tworzony jest jeden obiekt agregujący. Następnie w pętli symulujemy pomiary hipotetycznych metod, losowo wybranych spośród trzech dostępnych w tablicy names. Po zakończeniu procesu, mamy dostępne wszystkie dane.

Podsumowanie

Celem artykułu było pokazanie sposobu wykonywania pomiarów czasu w aplikacjach .NET. To, z której chcemy korzystać, będzie pewnie wynikało z prywatnych odczuć i struktury aplikacji. Trzeba wiedzieć, że wiele dużych aplikacji ma takie punkty zaczepienia, które idealnie nadają się do wpięcia mechanizmu pomiaru czasu. I tak, WCF ma swój interfejs IOperationInvoker, który pozwala przechwycić wywołanie metody. Przedstawiony w artykule Wzorzec dekoratora w praktyce mechanizm również pozwala na łatwe przechwycenie wszystkich wywoływanych metod. Tak przechwycona metoda może być w łatwy sposób otoczona instrukcją using.

Wszystkie metody pokazane wcześniej zostały zebrane w projekcie Visual Studio i dołączone do artykułu.

Kategoria:C#