Entity Framework in der Praxis (Teil 2)

Es geht nun nach dem ersten Teil weiter in die Tiefe und wir kümmern uns nun um die Konfiguration des Kontextes und das Einbinden von externen Komponenten.

Screencast

Artikel-Links

Entity Framework in der Praxis (Teil 1)

Einleitung

Im ersten Teil dieser Serie lag der Augenmerk deutlich auf den T4-seitigen Anpassungen der durch EF generierten Elemente. Nachdem dies nun abgeschlossen ist, will ich folgende typischen Szenarien beleuchten:

  • Konfiguration anpassen (allgemein)
  • Logging der Datenbankaktivität von EF professionell einbinden.
  • Reaktionen auf Commandausführungen implementieren.

Letztlich geht es darum, das EF als vermeintliche „Black box“ ein wenig näher zu verstehen und zu erkennen, an welchen Stellen man als Entwickler Einfluss auf das Standard-Verhalten nehmen kann.

Warum das Ganze?

EF deckt DB-Zugriffe und die Einrichtung des ganzen „Geraffels“ für den durchschnittlichen Use-Case ganz gut ab. Wer also immer nur mal eben schnell eine DB-Connection braucht, der wird sich diesen Artikel wahrscheinlich eher nicht durchlesen müssen. Erstaunlich schnell landet man dann aber doch in Szenarien, in denen das Standard-Verhalten nichts bringt oder sogar gefährlich ist. Ein Beispiel ist SQL Azure.

Die meisten glauben, SQL Azure wäre einfach nur ein SQL Server, der von MS in der Cloud angeboten wird. Nichts könnte weiter von der Wahrheit entfernt sein! Letztlich fühlt sich das Produkt einfach nur wie ein SQL Server an und es nutzt ähnliche Connection-Strings. Das war aber auch schon an Gemeinsamkeiten. Über die Tatsache, dass eine in der Cloud gehostete DB einfach mal von einem auf den anderen Server umzieht, sollte man sich z.B. mal ein paar Minuten Gedanken machen.

Konfigurations-Einstieg

Microsoft hat im aktuellen EF (Version 6.x) eine Konvention aufgestellt, die für die Einrichtung der Konfiguration wichtig ist:

  1. Findet EF zur Laufzeit eine Klasse in einer der geladenen Assemblies, die von „System.Data.Entity.DbConfiguration“ erbt, dann bindet EF die dortigen Anweisungen automatisch ein.
  2. Es darf wenn dann nur genau 1 von DbConfgiguration erbender Typ gefunden werden.

Um gleich in eine sinnvolle eigene Config einzusteigen, erweitern wir unser Beispiel aus Teil 1, das ja auf einer in Azure gehosteten DB aufsetzt. Wie oben beschrieben gibt es hier das sog. Transient-Error-Problem. Vereinfacht ausgedrückt geht es darum, dass man nicht die gleichen Annahmen über die Stabilität einer Azure-Verbindung treffen kann, wie bei einer dedizierten Datenbank OnPremise. Inzwischen geht man sogar davon aus, dass ein transientes Error-Handling auch bei OnPremise-Datenbanken keine schlechte Idee ist. Das kann man schön daran erkennen, dass die Klassen hierfür (früher SqlAzureTransientErrorDetectionStrategy) entsprechend umbenannt wurden (jetzt SqlDatabaseTransientErrorDetectionStrategy).

Sehen wir uns das mal im Code an:

/// <summary>
/// The existance of this type ensures that EF will configure databases properly.
/// </summary>
public class AzureConfiguration : DbConfiguration
{
    public AzureConfiguration()
    {
        SetExecutionStrategy("System.Data.SqlClient", new SqlAzureExecutionStrategy());
    }
}

Meine neue Klasse hat lediglich ein Statement im Konstruktor, das EF mitteilt, dass ich bitte eine andere sog. ExecutionStrategy anwenden möchte, als EF normalerweise verwenden würde. Die SqlAzureExecutionStrategy stamm aus dem Namespace System.Data.Entity.SqlServer und wird also direkt in EF mitgeliefert.

Listing 1 geht allerdings ein wenig gedankenlos vor. Was, wenn aus irgendeinem Grund die Nutzung von transienten Strategien nicht möglich ist (z.B., weil ich mein Projekt plötzlich doch nicht mehr in SQL Azure hoste)? Auch dafür gibt es eine Lösung:

public class AzureConfiguration : DbConfiguration
{
    public AzureConfiguration()
    {
        SetExecutionStrategy("System.Data.SqlClient", () => SupportSuspendExecutionStrategy ? (IDbExecutionStrategy)new DefaultExecutionStrategy() : new SqlAzureExecutionStrategy());
    }

    /// <summary>
    /// Gets/sets if this configuration should support suspending.
    /// </summary>
    public static bool SupportSuspendExecutionStrategy
    {
        get { return (bool?)CallContext.LogicalGetData("SupportSuspendExecutionStrategy") ?? false; }
        set { CallContext.LogicalSetData("SupportSuspendExecutionStrategy", value); }
    }
}

Ich führe zunächst eine neue Property „SupportSuspendExecutionStrategy“ ein. Diese benutzt den in DbConfiguration implementierten CallContext. Letztlich bekomme ich über den CallContext also etwas über die tatsächliche aktuelle Verbindung mitgeteilt.

Die Eigenschaft „SupportSuspendExecutionStrategy“ habe ich einfach definiert, indem ich beim Erstellen meines Context einen entsprechenden Wert setze:

static DbContextUtil()
{
    AzureConfiguration.SupportSuspendExecutionStrategy = false;
}

Nur wenn diese true liefert, verwende ich nun die Azure-Strategie. Ansonsten bleibe ich bei der DefaultExecutionStrategy.

Soweit, so gut. Nun kann ich etwas beruhigter mit Azure hantieren. Es gibt zu diesem Thema weiterführende Links. Beispielsweise kann man sich hier einmal ansehen, wie man eine komplett eigene ExecutionStrategy implementiert. Das hat den Vorteil, dass man dann das Retry-Verhalten (darum geht’s letztlich bei den Strategien) komplett selbst einbauen kann.

Logging/Tracing verbessern

Im Teil 1 hatte ich in Listing 2 gezeigt, wie man EF dazu bringen kann, seine DB-Aktivitäten zu tracen. Verwendet man z.B. die Klasse „Trace“, dann kommt bei der Ausführung sowas ähnliches, wie

vstest.executionengine.x86.exe Information: 0 : Opened connection at 31.01.2015 15:33:41 +01:00

vstest.executionengine.x86.exe Information: 0 : SELECT
[GroupBy1].[A1] AS [C1]
FROM ( SELECT
COUNT(1) AS [A1]
FROM [BaseData].[VehicleType] AS [Extent1]
) AS [GroupBy1]
vstest.executionengine.x86.exe Information: 0 :

vstest.executionengine.x86.exe Information: 0 : -- Executing at 31.01.2015 15:33:42 +01:00

vstest.executionengine.x86.exe Information: 0 : -- Completed in 56 ms with result: SqlDataReader

vstest.executionengine.x86.exe Information: 0 :

vstest.executionengine.x86.exe Information: 0 : Closed connection at 31.01.2015 15:33:42 +01:00

zustande. Das ist schonmal ziemlich cool. Die Nachteile werden aber sofort klar:

  • Was sollen die Leerzeilen?
  • In einem echten Trace will man keine Zeilenumbrüche haben.
  • Ich würde vielleicht gern eigene Meldungen einbauen.

Bleibt man auf der Standard-Ebene, kann man da nicht viel machen. Es gibt aber einfache Abhilfe.

Ein eigener LogFormatter

Genau, wie ich EF bei der ExecutionStrategy hineinreden darf, kann ich das auch beim Formatieren der Logs tun. Dazu stellt DbConfiguration eine Methode SetDatabaseLogFormatter zur Verfügung. Die Methode erwartet einen Delegaten, der letztlich einen von DatabaseLogFormatter abgeleiteten Typen liefert.

Zunächst müssen wir also einen eigenen LogFormatter definieren. Dazu füge ich meinem Projekt eine neue Klasse hinzu:

public class OneLineFormatter : DatabaseLogFormatter
{
    #region constructors and destructors

    public OneLineFormatter(DbContext context, Action<string> writeAction) : base(context, writeAction)
    {
    }

    #endregion

    #region methods

    public override void LogCommand<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        var commandText = command.CommandText.Replace(Environment.NewLine, "");
        Write(string.Format(CultureInfo.InvariantCulture, "Context '{0}' is executing command '{1}'", Context.GetType().Name, commandText));
    }

    public override void LogResult<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Write(string.Format(CultureInfo.InvariantCulture, "Result of {0} operation: {1}", interceptionContext.IsAsync ? "ASYNC" : "SYNC", interceptionContext.Result));
    }

    public override void Opened(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    {
        Write(string.Format(CultureInfo.InvariantCulture, "Opened db connection at {0}.", DateTime.UtcNow));
    }

    public override void Closed(DbConnection connection, DbConnectionInterceptionContext interceptionContext)
    {
        Write(string.Format(CultureInfo.InvariantCulture, "Closed db connection at {0}.", DateTime.UtcNow));
    }

    #endregion
}

Ich überschreibe hier die Methoden für Connection-Open und -Close, sowie für das Loggen von Kommandos und Ergebnissen. Interessant ist vor allem LogResult. Hier habe ich einfach mal eingebaut, dass mir das Logging mit ausgibt, ob ein Request synchron oder asynchron erfolgt.

Es gibt noch viele weitere overrides, die man nach Herzenslust verwenden kann.

Nun wird es Zeit, EF mitzuteilen, dass mein OneLineFormatter verwendet werden soll. Hier meine Ergänzung aus Listing 3 im Konstruktor der DbConfiguration:;

public class AzureConfiguration : DbConfiguration
{
    public AzureConfiguration()
    {
        SetExecutionStrategy("System.Data.SqlClient", new SqlAzureExecutionStrategy());
        SetDatabaseLogFormatter((ctx, logAction) => new OneLineFormatter(ctx, logAction));
    }
}

Zeile 6 ist die einzig entscheidende.

Führe ich nun meine Kommando im Debug-Modus aus, erscheint folgendes im Trace-Fenster:

vstest.executionengine.x86.exe Information: 0 : Opened db connection at 01/31/2015 14:43:12.
vstest.executionengine.x86.exe Information: 0 : Context 'SampleEntities' is executing command 'SELECT     [GroupBy1].[A1] AS [C1]    FROM ( SELECT         COUNT(1) AS [A1]        FROM [BaseData].[VehicleType] AS [Extent1]    )  AS [GroupBy1]'
vstest.executionengine.x86.exe Information: 0 : Result of SYNC operation: System.Data.SqlClient.SqlDataReader
vstest.executionengine.x86.exe Information: 0 : Closed db connection at 01/31/2015 14:43:12.

Genau das wollte ich erreichen. Man beachte, dass die Zuweisung des Trace-Loggers aus Teil 1 Listing 2 trotzdem noch erfolgen muss!!!

Interceptors

Ein weiteres sehr mächtiges Mittel zur Erweiterung von EF sind Interceptors. Es gibt mehrere Typen von Interceptors:

  • IDbCommandInterceptor
  • IDbCommandTreeInterceptor
  • IDbConfigurationInterceptor
  • IDbConnectionInterceptor
  • IDbInterceptor
  • IDbTransactionInterceptor

Je nachdem, wo ich also einen Einsprungpunkt für meine Logik haben möchte, implementiere ich einfach das entsprechende Interface und konfiguriere dann meinen Interceptor.

Nehmen wir ein kleines Beispiel. Ich bleibe beim Logging und möchte mein Logging über NLog implementieren. Hier bietet sich der IDbCommandInterceptor hervorragend an:

public class NLogCommandInterceptor : IDbCommandInterceptor
    {
        #region static fields

        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

        #endregion

        #region methods

        public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {

        }

        public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {

        }

        public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            Logger.Debug(CultureInfo.InvariantCulture, command.CommandText.Replace(Environment.NewLine, " "));
        }

        public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {

        }

        public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {

        }

        public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {

        }

        #endregion
    }

Ich habe bewusst nur die Methode ReaderExecuted verwendet. Sie wird immer dann aufgerufen, wenn ein DbCommand mit dem Ausführen eines SQL statements fertig ist, das einen Reader liefert. Ich möchte also offenkundig nur solche Ereignisse per NLog tracen. Jetzt rufe ich also immer den von NLog stammenden Logger auf und ersetze dabei immer innerhalb des CommandText einen Zeilenumbruch durch ein Leerzeichen.

Meine NLog-Config sieht dann so aus:

<?xml version="1.0" encoding="utf-8" ?>
  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <targets async="true">
    <target xsi:type="File" name="fileLogger" fileName="c:\temp\${shortdate}.log"/>
  </targets>
  <rules>
    <logger name="*" minlevel="Trace" writeTo="fileLogger" />
  </rules>
</nlog>

Ein letzter Schritt ist nun die Erweiterung meiner DbConfiguration aus Listing 6:

public class AzureConfiguration : DbConfiguration
{
    public AzureConfiguration()
    {
        SetExecutionStrategy("System.Data.SqlClient", new SqlAzureExecutionStrategy());
        SetDatabaseLogFormatter((ctx, logAction) => new OneLineFormatter(ctx, logAction));
        AddInterceptor(new NLogCommandInterceptor());
    }
}

Sehe ich nun in C:\temp nach, finde ich nach einem erneuten Start der Anwendung folgenden Inhalt:

2015-01-31 14:36:24.9314|DEBUG|codingfreaks.EfSample.Data.Core.NLogCommandInterceptor|SELECT      [GroupBy1].[A1] AS [C1]     FROM ( SELECT          COUNT(1) AS [A1]         FROM [BaseData].[VehicleType] AS [Extent1]     )  AS [GroupBy1]
2015-01-31 14:38:35.3747|DEBUG|codingfreaks.EfSample.Data.Core.NLogCommandInterceptor|SELECT      [GroupBy1].[A1] AS [C1]     FROM ( SELECT          COUNT(1) AS [A1]         FROM [BaseData].[VehicleType] AS [Extent1]     )  AS [GroupBy1]
2015-01-31 14:42:03.5887|DEBUG|codingfreaks.EfSample.Data.Core.NLogCommandInterceptor|SELECT      [GroupBy1].[A1] AS [C1]     FROM ( SELECT          COUNT(1) AS [A1]         FROM [BaseData].[VehicleType] AS [Extent1]     )  AS [GroupBy1]

Hinweis: ich muss hier ein eigenes string-replace durchführen, weil ich im Interceptor nicht hinter dem LogFormatter hänge. Ein Interceptor ist sozusagen eine Ebene näher am Kern von EF, als der LogFormatter. Das gibt mir mehr Möglichkeiten, umgeht aber den Formatter komplett. Es wäre aber kein Problem, den Formatter hier zu verwenden.

Noch mehr Methoden liefert vor allem der IDbConnectionInterceptor. Das Muster ist dabei allerdings immer das gleiche: Es gibt sozusagen eine Methode für den Davor-Moment und eine für den Danach-Moment. Das ist also ganz ähnlich zu den Patterns für Events in UI-Frameworks.

Dependency Injection und Probleme damit

Wer sich Listing 9 kritisch ansieht, wird zu Recht anmerken, dass das Setzen des Interceptors hier nicht besonders elegant ist. Eigentlich sollte das per Dependency Injection (DI) am besten konfigurierbar möglich sein.

Das funktioniert sogar in einer einfachen Version recht simpel. Ich erstelle mir dazu eine Klasse, die IDbDependencyResolver implementiert:

public class CustomDependencyResolver : IDbDependencyResolver
{
    #region methods

    public object GetService(Type type, object key)
    {
        if (type == typeof(IDbCommandInterceptor))
        {
            return new NLogCommandInterceptor();
        }
        return null;
    }

    public IEnumerable<object> GetServices(Type type, object key)
    {
        var service = GetService(type, key);
        return service == null ? Enumerable.Empty<object>() : new[] { service };
    }

    #endregion
}

und konfiguriere diesen anstatt der direkten Zuweisung des Interceptors aus Listing 9:

public class AzureConfiguration : DbConfiguration
{
    public AzureConfiguration()
    {
        SetExecutionStrategy("System.Data.SqlClient", new SqlAzureExecutionStrategy());
        SetDatabaseLogFormatter((ctx, logAction) => new OneLineFormatter(ctx, logAction));
        AddDefaultResolver(new CustomDependencyResolver());
    }
}

Das funktioniert auch technisch, nur nicht logisch, weil in GetService in Listing 11 die Variable „type“ niemals ein IDbCommandInterceptor ist. Ich bekomme Anfragen für IDbInterceptor, DbProviderFactory und auch IDbProviderFactoryResolver. Aber ich bekomme keine Anfrage für IDbCommandInterceptor.

Hier habe ich selbst noch Verständnis-Lücken und bin auf Euer Feedback dazu gespannt.

Fazit

EF kann man sehr viel tiefgreifender anpassen, als das die meisten Leute wissen geschweige denn tun. Es ist wie so oft: Die vermeintliche Simplizität, die durch einfache Bedienung suggeriert wird, erzeugt beim Benutzen das Gefühl, etwas simples vor sich zu haben. EF ist eine mächtige Waffe im Kampf gegen unnötige Programmier-Arbeiten – man muss sie aber auch zu handhaben wissen.

4 Antworten auf „Entity Framework in der Praxis (Teil 2)“

  1. Hallo sprinter, vielen Dank für diesen Artikel. Interceptors sind genau, was ich gerade brauche (Stichwort: „soft delete“ beim SELECT / UPDATE / DELETE berücksichtigen und nicht einfach nur setzen, wofür es genügend [immer gleiche] Beispiele gibt).

    Hast Du Erfahrungen bzgl. möglicher Performance-Einbußen beim Einsatz von Interceptors?

    1. Hallo Volker, freut mich, dass das Thema Interesse weckt. Zu den Performance-Betrachtungen fehlte bislang die Zeit. Ich denke, dass es hier wie bei anderen Technologien auch ist. Wenn man Interceptors einsetzt, sollte man bei langwierigen Operationen so schnell wie möglich in einen neuen Thread wechseln und möglichst keine Abhängigkeit für das EF einbauen. Wenn ich also z.B. Logging einbaue, dann tunlichst so, dass ich die Kontrolle möglichst schnell wieder an Core-EF zurück gebe.

  2. Hallo sprinter, erstmal Super Beschreibung.

    Zu dem Problem mit dem IDbCommandInterceptor:

    IDbCommandInterceptor ist abgeleitet vom Interface IDbInterceptor.

    Du könntest auch prüfen:
    if(type is IDbCommandInterceptor)

Schreibe einen Kommentar zu NeuroNet Antworten abbrechen

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert.