Kürzlich habe ich für einen Kunden ein Code- und Architekturreview durchgeführt. Es handelte sich um eine Web-Anwendung, die als Software as a Service (SaaS) Lösung vertrieben werden soll. Die Lösung befindet sich aktuell in einer Beta Phase und wird bereits von ca. 50 ausgewählten Kunden genutzt. Kurz vor Start der Beta Phase verließ der ursprüngliche Softwarearchitekt das Unternehmen. Sein Nachfolger hatte den subjektiven Eindruck, dass die Architektur an einigen Stellen nicht optimal ist. Nun ist es in der Softwareentwicklung häufig so, dass man alles, was man nicht selbst entwickelt hat, als nicht optimal ansieht. Daher wollte er sich eine zweite, unabhängige und vor allem objektive, Meinung einholen, ehe er größere Umbaumaßnahmen auf der Zielgeraden durchführt.

Auf den ersten Blick machten sowohl die Architektur als auch der Code einen sehr sauberen Eindruck. Innerhalb der Web-Anwendung gab es zwar einige Unschönheiten bei der Nutzung des Entity Framework, über die ich zu einem späteren Zeitpunkt noch einmal schreiben werde, im Großen und Ganzen sah der Code jedoch in Ordnung aus. Auch eine statische Code Analyse mit NDepend zeigte keine groben Schnitzer.

Stutzig machte mich jedoch der Code, der außerhalb der Web-Anwendung läuft. Neben der Web-Anwendung existiert nämlich noch ein zweites Programm, welches regelmäßig Daten aus mehreren Fremdsystemen liest, diese mit der eigenen Datenbasis vergleicht und, abhängig vom Ergebnis des Vergleichs, neue Daten einfügt, die später von der Web-Anwendung dargestellt werden.

Ausgangslage

Sehr vereinfacht kann man sich folgendes Modell und folgende Abbildung des Modells in der Datenbank vorstellen:

Wir haben also Kunden, die über Bestellungen verfügen, die wiederum Bestellpositionen haben, welche auf Produkte verweisen. Außerdem gibt es sogenannte Notification Objekte, die zu bestimmten Ereignissen geschrieben werden. Das tatsächliche Modell meines Kundens war natürlich weitaus umfangreicher und auch in einer anderen Geschäftsdomäne. Zu Erläuterungszwecken reicht diese Vereinfachung jedoch vollkommen aus.

Der zweifelhafte Quellcode sah (stark vereinfacht!) wie folgt aus:

var lastRun = DateTime.Now.AddDays(-7); // lastRun wurde natürlich aus der DB geladen
var sw = new Stopwatch();
using (var db = new Db())
{
    sw.Start();
    // Hier wurden eigentlich Daten aus einer anderen Datenquelle geladen
    // Diese Daten wurden dann in den Vergleich einbezogen. Zu Demozwecken
    // soll jedoch diese Vereinfachung genügen
    foreach (var order in db.Orders)
        .Where(o => o.OrderState == OrderState.Shipped
            && o.OrderDate > lastRun).ToList())
    {
        db.Notifications.Add(new Notification { Message = string.Format("Order {0} Shipped", order.Id), Order = order });
    db.SaveChanges();
    }
    sw.Stop();

}
Console.WriteLine("Processing took {0} ms", sw.ElapsedMilliseconds);

Es wurden also Daten aus einem Drittsystem abgerufen, mit allen Daten, die sich seit dem letzten Lauf verändert hatten, verglichen und - je nach Ergebnis - wurden neue Daten in der Anwendung erzeugt (vereinfacht gesagt). Der Architekt hatte zwar bemerkt, dass dieser Code nicht optimal lief, allerdings konnte er die Auswirkungen nicht vollständig einschätzen und, da er zuvor noch nie mit dem Entity Framework gearbeitet hatte, wusste er auch nicht, wie er das Problem lösen könnte.

Haben wir ein Problem?

Im ersten Schritt wollte ich dem Kunden zunächst darlegen, dass er ein Problem hat, und wie groß dies später werden wird.

Während der Entwicklung hatte das Entwicklungsteam stets mit manuell erzeugten Testdaten gearbeitet. Es waren einige 100 Datensätze, die aufwändig durch die Entwickler eingepflegt wurden. Mit dieser Datenmenge lief das System absolut zufriedenstellend. Die ersten Probleme zeigten sich, als die Software von den ersten Beta Anwendern genutzt wurden. Bereits bei 50 Kunden mit 40 Transaktionen (neuen Bestellungen) pro Verarbeitungslauf wurde schnell klar, dass die Performance schon bei 50 Anwendern nicht zufriedenstellend ist.

Ein Gespräch mit dem Produktmanager ergab nun, dass man das klare Ziel hat, 10.000 Kunden mit jeweils 100 Transaktionen pro Lauf bedienen zu können. Um die Daten möglichst aktuell zu halten, sollte der Verarbeitungslauf vier mal pro Stunde laufen. Dies bedeutet, dass das System in der Lage sein muss, 1.000.000 Datensätze in weniger als 15 Minuten zu verarbeiten.

Um nicht weiterhin nur vermuten zu können, ob das System diese Anforderungen erfüllen kann oder nicht, entschieden wir uns dazu, die Entwicklungsdatenbank mit einer realistischen Anzahl von Testdaten zu füllen. Bereits bei einem einfachen Schema wie unserem, in dem es mehrere beteiligte Tabellen inklusive Beziehungen zwischen den Tabellen gibt, ist es jedoch gar nicht so einfach, realistische Testdaten zu generieren.

Natürlich hätten wir mit einem kleinen Programm Schritt für Schritt alle Tabellen mit hochgezählten Dummy Daten füllen können, allerdings hätte es zum einen eine Weile gedauert, dieses Programm zu schreiben, zum anderen wären die Daten auch relativ monoton gewesen.

Eine andere Alternative wäre es gewesen, einen Dump der Live-Datenbank einzuspielen und dort Daten zu duplizieren. In diesem Fall hätten jedoch alle Daten aus Datenschutzgründen anonymisiert werden müssen, was auch nur schwer umsetzbar gewesen wäre.

Deshalb entschieden wir uns dafür, die Daten mit dem redgate SQL Data Generator zu erzeugen. Das schöne am SQL Data Generator ist nicht nur, dass er realistische Testdaten erzeugen kann, wie man in diesem Screenshot sieht:

sondern dass er auch wunderbar mit Fremdschlüsseln umgehen kann, und somit in kürzester Zeit realistische und vor allem konsistente Testdaten in großer Menge erzeugen kann:

Nachdem wir nun also eine realistische Testdatenbank hatten, ließen wir das Programm erneut laufen. Dieser Durchlauf dauerte mehr als 9 h! Die durch das Produktmanagement geforderte Verarbeitungszeit von 15 Minuten wurde also um mehr als das 36-fache überschritten. Wie in vielen anderen Entwicklungsprojekten auch, ist dieses Problem während der Entwicklung nie aufgefallen, da keine realistischen Testdaten vorlagen und keine entwicklungsbegleitenden Performancetests durchgeführt wurden.

Wie können wir das Problem lösen?

Nachdem nun klar war, dass ein geschäftskritisches Problem besteht, musste natürlich eine Lösung her. Schnell wurden die ersten Ansätze unter den Entwicklern diskutiert. Der Vorschlag mit der meisten Zustimmung bestand aus einer Kombination aus Multiprocessing, zeitweise inkonsistenten Daten und Event Sourcing. Das vom Entwickler angezeichnete Architekturbild dazu sah auch wirklich sehr gut aus, allerdings schreckten mich zwei Dinge ab:

1. Die Dauer für die Implementierung dieser Lösung  schätzte das Entwicklungsteam auf 3 Monate
2. Ob diese Änderung wirklich erfolgreich sein würde, wurde nur vermutet. Bisher hatte niemand nachgemessen, wo genau innerhalb der Verarbeitungscodes der Flaschenhals war und ob der neue Ansatz überhaupt an der richtigen Stelle ansetzt

Also entschieden wir uns dazu, einen Gang zurück zu schalten und erst einmal mit einem Performance Profiler zu messen, wo das Problem wirklich liegt.

Wie der Screenshot des ANTS Performance Profiler zeigt, wird die meiste Zeit von der Methode SaveChanges verbraucht, dicht gefolgt von der Methode Add des DbSet. Beide Methoden werden in diesem Beispiel mit 10.000 Quelldatensätzen 4.777 Mal aufgerufen, nämlich für jeden Datensatz, der neu hinzugefügt werden soll.

Seit der Version 6 des Entity Framework ist es jedoch gar nicht mehr notwendig, jedes Objekt einem DbSet einzeln hinzuzufügen. Stattdessen kann über AddRange eine komplette Liste hinzugefügt werden, wie das nachfolgende Listing zeigt. Außerdem muss SaveChanges auch nicht jedes Mal aufgerufen werden, sondern nur einmalig bzw. häppchenweise.

var lastRun = DateTime.Now.AddDays(-7); // lastRun wurde natürlich aus der DB geladen
var sw = new Stopwatch();
using (var db = new Db())
{
    sw.Start();
    var notifications = new List();
    // Hier wurden eigentlich Daten aus einer anderen Datenquelle geladen
    // Diese Daten wurden dann in den Vergleich einbezogen. Zu Demozwecken
    // soll jedoch diese Vereinfachung genügen
    foreach (var order in db.Orders)
        .Where(o => o.OrderState == OrderState.Shipped
            && o.OrderDate > lastRun).ToList())
    {
        notifications.Add(new Notification { Message = string.Format("Order {0} Shipped", order.Id), Order = order });
    }
    db.Notifications.AddRange(notifications);
    db.SaveChanges();
    sw.Stop();

}
Console.WriteLine("Processing took {0} ms", sw.ElapsedMilliseconds);

Durch diese Code Änderung konnte die Verarbeitungszeit von 9 Stunden auf 6 Minuten reduziert werden.

Auch ein erneuter Blick auf redgates ANTS Performance Profiler zeigt, dass AddRange und SaveChanges nun nur noch eine untergeordnete Rolle spielen.

Fazit

Natürlich ist der vorliegende Quellcode noch nicht optimal. Den Entity Framework Kontext mit so einer großen Datenmenge zu befüllen und nur einmalig SaveChanges aufzurufen, birgt immer das Risiko einer Out-Of-Memory Exception. Daher sollte besser häppchenweise gespeichert werden. Noch besser wäre es natürlich die Massendaten über ein SQLBulkCopy einzufügen.

Mit der Erweiterung EntityFramework.BulkInsert geht dies relativ einfach, wie das nachfolgende Listing zeigt. Der Code läuft für 1.000.000 Datensätze übrigens innerhalb von 31 Sekunden.

var lastRun = DateTime.Now.AddDays(-7); // lastRun wurde natürlich aus der DB geladen
var sw = new Stopwatch();
using (var db = new Db())
{
    using (var transactionScope = new TransactionScope())
    {
        db.Configuration.AutoDetectChangesEnabled = false;

        sw.Start();
        var notifications = new List();
        foreach (var order in db.Orders
            .Where(o => o.OrderState == OrderState.Shipped
                        && o.OrderDate > lastRun).ToList())
        {
            notifications.Add(new Notification
            {
                Message = string.Format("Order {0} Shipped", order.Id),
                Order = order
            });
        }
        db.BulkInsert(notifications);
        db.SaveChanges();
        transactionScope.Complete();
    }

    sw.Stop();

}
Console.WriteLine("Processing took {0} ms", sw.ElapsedMilliseconds);

Die genaue Lösung war mir für diesen Beitrag jedoch gar nicht so wichtig.

Stattdessen möchte ich folgende Punkte noch einmal hervorheben:

1. Bereits während der Entwicklung sollte man darauf achten, mit realistischen Testdaten in einer ausreichenden Menge zu arbeiten. Ein Werkzeug wie der SQL Data Generator hilft hier ungemein.
2. Wenn ein Performanceproblem erkannt wird, dann sollte man immer die zuerst die genaue Ursache mit einem Profiler analysieren ehe man mit der vermuteten Lösung beginnt.