Proste śledzenie wydajności serwisu (#bieda)

Uch, ponoć najtrudniej jest zacząć… Ciągle zbieram treść i materiały na zasadnicze posty, stąd najpierw chyba kilka szortów, które przyszły mi do głowy przy okazji pracy nad tamtymi / lub wygrzebałem je podczas przeszukiwania archiwów kodu i różnych jego wersji.

Na dzisiaj zagadnienie trywialne, ale wkurzające w realizacji. Zapewne można je rozwiązać na inne sposoby, ale implementacja tego zajęła mi o wiele mniej czasu niż prawdopodobne poszukiwania narzędzia (na którego użycie i tak zapewne nie dostałbym w firmie zgody ;-)). Zwłaszcza, że większość kodu już miałem kiedyś napisaną na inne potrzeby.

Otóż. Potrzebuję zweryfikować średnie czasy wykonania jakiegoś zdalnego kodu – wybranych funkcji lub ich fragmentów. Zdalne podpięcie profilera nie wchodzi w rachubę ze względu na brak dostępu do śledzonego serwera w sposób inny niż deployment/ WCF.

Można oczywiście zrzucać te czasy do logów, ale potem i tak trzeba by to zbierać i w jakiś sposób analizować. I jeszcze się do tego dobrać, co jak wspomniałem miałem utrudnione. Postanowiłem zbierać te dane ręcznie i wystawić przez WCF.

Wzmiankowana zdalna usługa posiada także stowarzyszoną usługę, wystawioną obok – nazwijmy ją InstrumentationService, która jest już wykorzystywana do zdalnego modyfikowania parametrów pracy głównej usługi – zamiast modyfikowania pliku web.config – na potrzeby testowania. Dobrze, mogę ją łatwo rozbudować.

Ale najpierw sam podstawowy kod prostego, asynchronicznego monitora wydajności:

public static class PerformanceMonitor
{
    private static readonly ConcurrentDictionary<string, PerfInfo> _results 
            = new ConcurrentDictionary<string, PerfInfo>();

    public static void RegisterExecution(string key, long elapsedTicks)
    {
        PerfInfo info;
        if (!_results.TryGetValue(key, out info))
        {
            info = new PerfInfo(key);
            if (!_results.TryAdd(key, info))
            {
                _results.TryGetValue(key, out info); // receive already stored object
            }
        }

        if (info != null)
            //lock (info)
        {
            Interlocked.Add(ref info.Events, 1);
            Interlocked.Add(ref info.TotalTicks, elapsedTicks);
        }
    }

    public static void MeasureBlock(string key, Action action)
    {
        Stopwatch sw = Stopwatch.StartNew();
        try
        {
            action.Invoke();
        }
        finally
        {
            sw.Stop();
            RegisterExecution(key, sw.ElapsedTicks);
        }
    }

    public static T MeasureBlock<T>(string key, Func<T> func)
    {
        Stopwatch sw = Stopwatch.StartNew();
        try
        {
            return func.Invoke();
        }
        finally
        {
            sw.Stop();
            RegisterExecution(key, sw.ElapsedTicks);
        }
    }
}

Implementacja dość oczywista, wpisy wydajnościowe grupowane są po wskazanym kluczu, zliczane są ticki oraz ilość wystąpień. Postawiłem na minimalistyczne synchronizacje wielowątkowe, problemów podczas testów nie stwierdziłem.
Najciekawsze oczywiście jest wykorzystanie tego monitora:

1. Z ręcznym mierzeniem czasu:

Stopwatch sw = new Stopwatch();
sw.Restart();
// ... kod do zmierzenia
sw.Stop();
PerformanceMonitor.RegisterExecution("Unikalny.Klucz.Mierzonego.Bloku", sw.ElapsedTicks);

2. Problem z tym kodem jest taki, że dość mocno zaśmieca kod oryginalny. Założenie moje było takie, że takie wstawki mogą siedzieć w kodzie jakiś czas zanim zostaną usunięte (ew. można by pomyśleć nad wykorzystaniem dyrektywy #if TRACE…) i fajnie jakby dało się je wstawiać minimalnym kosztem. Stad podejście z wykorzystaniem Action i Func<T>:

var zwróconaWartość = PerformanceMonitor.MeasureBlock("Kolejny.Unikalny.PerfKod", () =>
                      jakiśObiekt.ZwracającaWartośćFunkcja(lokalnyParametr));

3. Oczywiście można dać większe bloki kodu, nawet otoczyć całe wnętrze funkcji za pomocą try-finally. Troszkę jeszcze bardziej skomplikować gdy operujemy na wielu zmiennych lokalnych.
Ewentualnie, można lekko uprościć wywołania, automatyzując tworzenie klucza, za pomocą informacji ze StackFrame:

public static void MeasureBlock(Action action)
{
    Stopwatch sw = Stopwatch.StartNew();
    try
    {
        action.Invoke();
    }
    finally
    {
        sw.Stop();
        StackFrame frame = new StackFrame(1);
        var callingMethod = frame.GetMethod();
        var key = callingMethod.DeclaringType.Name + "."
                  + callingMethod.Name + "; Line: " + frame.GetFileLineNumber();
        RegisterExecution(key, sw.ElapsedTicks);
    }
}

public static T MeasureBlock<T>(Func<T> func)
{
    Stopwatch sw = Stopwatch.StartNew();
    try
    {
        return func.Invoke();
    }
    finally
    {
        sw.Stop();
        StackFrame frame = new StackFrame(1);
        var callingMethod = frame.GetMethod();
        var key = callingMethod.DeclaringType.Name + "."
                  + callingMethod.Name + "; Line: " + frame.GetFileLineNumber();
        RegisterExecution(key, sw.ElapsedTicks);
    }
}

I uzyskać dzięki temu jeszcze bardziej banalne i czytelne wywołania.

Pozostaje jeszcze dopisać do monitora metody zbierające i formatujące wyniki (oraz resetujące dotychczas zebrane dane), np. do takiego prostego tabelarycznego formatu:

public static void ExportPerformanceResults(StreamWriter stream, OrderMode orderMode, OrderVector vector)
{
    var comparator = new PerfInfoComparator(orderMode);
    PerfInfo[] dataSet;
    if (vector == OrderVector.Ascending)
    {
        dataSet = _results.Values.Select(i => i).OrderBy(i => i, comparator).ToArray();
    }
    else
    {
        dataSet = _results.Values.Select(i => i).OrderByDescending(i => i, comparator).ToArray();
    }

    stream.WriteLine(@"| EventName | EventCount | TotalTicks | AverageTicks | Average Time (ms) |");
    foreach (PerfInfo perfInfo in dataSet)
    {
        stream.WriteLine(@"| " + string.Join(@" | ", new[]
        {
            perfInfo.Name,
            perfInfo.Events.ToString(@"D"),
            perfInfo.TotalTicks.ToString(@"D"),
            (perfInfo.TotalTicks/perfInfo.Events).ToString(@"D"),
            ((decimal) perfInfo.TotalTicks/perfInfo.Events/TimeSpan.TicksPerMillisecond)
                .ToString(@"F4")
        }) + @" |");
    }
}

public static void Clear()
{
    _results.Clear();
}

Oraz wystawić je poprzez serwis:

public string ObtainPerformanceResults()
{
    using (MemoryStream memStream = new MemoryStream())
    {
        var sw = new StreamWriter(memStream);
        PerformanceMonitor.ExportPerformanceResults(sw,
            OrderMode.AverageTime, OrderVector.Descending);

        sw.Flush();
        memStream.Position = 0;
        var sr = new StreamReader(memStream);
        var myStr = sr.ReadToEnd();
        return myStr;
    }
}

A, i jeszcze te brakujące enumy i sama klasa PerfInfo:

public enum OrderMode
{
    Name,
    TotalTime,
    AverageTime,
    EventCount
}

public enum OrderVector
{
    Ascending,
    Descending
}

public class PerfInfo
{
    private readonly string _name;
    public int Events;
    public long TotalTicks;

    public PerfInfo(string name)
    {
        _name = name;
    }

    public string Name
    {
        get { return _name; }
    }
}

public class PerfInfoComparator : IComparer<PerfInfo>
{
    private readonly OrderMode _orderMode;

    public PerfInfoComparator(OrderMode orderMode)
    {
        _orderMode = orderMode;
    }

    public int Compare(PerfInfo x, PerfInfo y)
    {
        switch (_orderMode)
        {
            case OrderMode.Name:
                return x.Name.CompareTo(y.Name);
            case OrderMode.TotalTime:
                return x.TotalTicks.CompareTo(y.TotalTicks);
            case OrderMode.AverageTime:
                return (x.TotalTicks/x.Events).CompareTo(y.TotalTicks/y.Events); // will always be at least 1 🙂
            case OrderMode.EventCount:
                return x.Events.CompareTo(y.TotalTicks);
            default:
                throw new ArgumentOutOfRangeException("orderMode");
        }
    }
}