Protokollieren und Abfangen von Datenbankvorgängen
Hinweis
Nur EF6 und höher: Die Features, APIs usw., die auf dieser Seite erläutert werden, wurden in Entity Framework 6 eingeführt. Wenn Sie eine frühere Version verwenden, gelten manche Informationen nicht.
Ab Entity Framework 6 kann dieser Befehl von Anwendungscode abgefangen werden, wenn Entity Framework einen Befehl an die Datenbank sendet. Diese Methode wird am häufigsten für die Protokollierung von SQL verwendet, kann aber auch verwendet werden, um den Befehl zu ändern oder abzubrechen.
Insbesondere umfasst EF Folgendes:
- Eine Protokolleigenschaft für den Kontext ähnlich wie „DataContext.Log“ in LINQ to SQL
- Einen Mechanismus zum Anpassen des Inhalts und zur Formatierung der an das Protokoll gesendeten Ausgabe
- Bausteine auf niedriger Ebene für das Abfangen, die mehr Kontrolle/Flexibilität ermöglichen
Context Log-Eigenschaft
Die DbContext.Database.Log-Eigenschaft kann für jede Methode, die eine Zeichenfolge verwendet, auf einen Delegaten festgelegt werden. Am häufigsten wird sie mit jedem TextWriter verwendet, indem sie auf die Write-Methode dieses TextWriter-Objekts festgelegt wird. Alle vom aktuellen Kontext generierten SQL-Dateien werden an diesen Writer protokolliert. Der folgende Code protokolliert z. B. SQL in der Konsole:
using (var context = new BlogContext())
{
context.Database.Log = Console.Write;
// Your code here...
}
Beachten Sie, dass „context.Database.Log“ auf „Console.Write“ festgelegt ist. Dies ist alles, was erforderlich ist, um SQL in der Konsole zu protokollieren.
Fügen wir nun einen einfachen Abfrage-/Einfüge-/Aktualisierungscode hinzu, damit wir einige Ausgaben sehen können:
using (var context = new BlogContext())
{
context.Database.Log = Console.Write;
var blog = context.Blogs.First(b => b.Title == "One Unicorn");
blog.Posts.First().Title = "Green Eggs and Ham";
blog.Posts.Add(new Post { Title = "I do not like them!" });
context.SaveChanges();
}
Dadurch wird die folgende Ausgabe generiert:
SELECT TOP (1)
[Extent1].[Id] AS [Id],
[Extent1].[Title] AS [Title]
FROM [dbo].[Blogs] AS [Extent1]
WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 4 ms with result: SqlDataReader
SELECT
[Extent1].[Id] AS [Id],
[Extent1].[Title] AS [Title],
[Extent1].[BlogId] AS [BlogId]
FROM [dbo].[Posts] AS [Extent1]
WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: '1' (Type = Int32)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader
UPDATE [dbo].[Posts]
SET [Title] = @0
WHERE ([Id] = @1)
-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 ms with result: 1
INSERT [dbo].[Posts]([Title], [BlogId])
VALUES (@0, @1)
SELECT [Id]
FROM [dbo].[Posts]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()
-- @0: 'I do not like them!' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader
(Beachten Sie, dass dies die Ausgabe ist, sofern bereits eine Datenbankinitialisierung erfolgt ist. Wenn die Datenbankinitialisierung noch nicht erfolgt ist, wäre viel mehr Ausgabe vorhanden, in der alle Arbeitsmigrationen unter der Haube ausgeführt werden, um nach einer neuen Datenbank zu suchen oder eine zu erstellen.)
Was wird protokolliert?
Wenn die Protokolleigenschaft festgelegt ist, wird Folgendes protokolliert:
- SQL für verschiedene Arten von Befehlen. Beispiel:
- Abfragen, einschließlich normaler LINQ-Abfragen, eSQL-Abfragen und Rohabfragen aus Methoden wie SqlQuery
- Einfügevorgänge, Aktualisierungen und Löschvorgänge, die als Teil von SaveChanges generiert werden
- Abfragen zum Laden von Beziehung, zum Beispiel jene, die von Lazy Loading generiert werden
- Parameter
- Ob der Befehl asynchron ausgeführt wird oder nicht
- Ein Zeitstempel, der angibt, wann der Befehl ausgeführt wurde
- Ob der Befehl erfolgreich abgeschlossen wurde oder fehlgeschlagen ist, indem eine Ausnahme ausgelöst oder für asynchrone Vorgänge abgebrochen wurde
- Ein Hinweis auf den Ergebniswert
- Die ungefähre Zeitspanne, die zum Ausführen des Befehls benötigt wurde. Beachten Sie, dass damit der Zeitraum vom Senden des Befehls bis zum Abrufen des Ergebnisobjekts gemeint ist. Darin ist nicht die Zeit zum Lesen der Ergebnisse enthalten.
In der Beispielausgabe oben sind alle vier protokollierten Befehle wie folgt:
- Die Abfrage, die sich aus dem Aufruf von „context.Blogs.First“ ergibt
- Beachten Sie, dass die ToString-Methode zum Abrufen der strukturierten Abfragesprache für diese Abfrage nicht funktioniert hätte, da „First“ keine IQueryable bereitstellt, für die ToString aufgerufen werden könnte.
- Die Abfrage, die sich aus dem verzögerten Laden (Lazy Loading) von „blog.Posts“ ergibt
- Beachten Sie die Parameterdetails für den Schlüsselwert, für den verzögertes Laden stattfindet.
- Es werden nur Eigenschaften des Parameters protokolliert, die auf Nicht-Standardwerte festgelegt sind. Die Size-Eigenschaft wird beispielsweise nur angezeigt, wenn sie ungleich 0 ist.
- Zwei Befehle, die sich aus SaveChangesAsync ergeben; einer für das Update zum Ändern eines Beitragstitels, der andere für einen Einfügevorgang zum Hinzufügen eines neuen Beitrags
- Beachten Sie die Parameterdetails für die Eigenschaften FK und Title.
- Beachten Sie, dass diese Befehle asynchron ausgeführt werden.
Protokollierung an verschiedenen Stellen
Wie oben gezeigt, ist die Anmeldung bei der Konsole sehr einfach. Es ist auch einfach, sich beispielsweise im Arbeitsspeicher oder in der Datei mit verschiedenen TextWriter-Typen anzumelden.
Wenn Sie mit LINQ to SQL vertraut sind, stellen Sie möglicherweise fest, dass in LINQ to SQL die Protokolleigenschaft auf das tatsächliche TextWriter-Objekt (z. B. Console.Out) festgelegt ist, während in EF die Log-Eigenschaft auf eine Methode festgelegt ist, die eine Zeichenfolge akzeptiert (z. B. Console.Write oder Console.Out.Write). Der Grund dafür ist, dass EF von TextWriter entkoppelt wird, indem jeder Delegat akzeptiert wird, der als Senke für Zeichenfolgen fungieren kann. Angenommen, Sie verfügen bereits über ein Protokollierungsframework, und dieses definiert eine Protokollierungsmethode wie folgt:
public class MyLogger
{
public void Log(string component, string message)
{
Console.WriteLine("Component: {0} Message: {1} ", component, message);
}
}
Dies kann wie folgt mit der EF Log-Eigenschaft verknüpft werden:
var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);
Ergebnisprotokollierung
Die Standardprotokollierung protokolliert Befehlstext (SQL), Parameter und die „ausführende“ Zeile mit einem Zeitstempel, bevor der Befehl an die Datenbank gesendet wird. Eine „abgeschlossene“ Zeile, die verstrichene Zeit enthält, wird nach der Ausführung des Befehls protokolliert.
Beachten Sie, dass bei asynchronen Befehlen die „abgeschlossene“ Zeile erst protokolliert wird, wenn die asynchrone Aufgabe tatsächlich abgeschlossen wird, fehlschlägt oder abgebrochen wird.
Die „abgeschlossene“ Zeile enthält je nach Befehlstyp unterschiedliche Informationen und ob die Ausführung erfolgreich war.
Erfolgreiche Ausführung
Für Befehle, die die Ausgabe erfolgreich abgeschlossen haben, lautet die Ausgabe „Completed in x ms with result:“ gefolgt von einem Hinweis darauf, was das Ergebnis war. Bei Befehlen, die einen Datenleser zurückgeben, ist die Ergebnisanzeige der Typ des zurückgegebenen DbDataReader-Elements. Für Befehle, die einen ganzzahligen Wert zurückgeben, z. B. den oben gezeigten Aktualisierungsbefehl, entspricht das angezeigte Ergebnis diesem Integerwert.
Fehler bei der Ausführung
Bei Befehlen, die durch Auslösen einer Ausnahme fehlschlagen, enthält die Ausgabe die Meldung aus der Ausnahme. Wenn Sie z. B. SqlQuery verwenden, um eine Tabelle abzufragen, die vorhanden ist, führt dies zu einer Protokollausgabe wie der folgenden:
SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.
Abgebrochene Ausführung
Bei asynchronen Befehlen, bei denen die Aufgabe abgebrochen wird, kann das Ergebnis mit einer Ausnahme fehlschlagen, da dies der zugrunde liegende ADO.NET-Anbieter häufig tut, wenn versucht wird, den Vorgang abzubrechen. Wenn dies nicht geschieht und die Aufgabe ordnungsgemäß abgebrochen wird, sieht die Ausgabe ungefähr wie folgt aus:
update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms
Ändern von Protokollinhalten und -formatierungen
Unter der Haube verwendet die Database.Log-Eigenschaft ein DatabaseLogFormatter-Objekt. Dieses Objekt bindet effektiv eine IDbCommandInterceptor-Implementierung (siehe unten) an einen Delegaten, der Zeichenfolgen und eine DbContext-Klasse akzeptiert. Dies bedeutet, dass Methoden für DatabaseLogFormatter vor und nach der Ausführung von Befehlen von EF aufgerufen werden. Diese DatabaseLogFormatter-Methoden erfassen und formatieren die Protokollausgabe und senden sie an den Delegaten.
Anpassen von DatabaseLogFormatter
Eine Änderung der Protokollierung und der Formatierung kann erreicht werden, indem eine neue Klasse erstellt wird, die von DatabaseLogFormatter abgeleitet wird und Methoden nach Bedarf außer Kraft setzt. Die häufigsten Methoden zur Außerkraftsetzung sind:
- LogCommand: Setzen Sie diese Methode außer Kraft, um zu ändern, wie Befehle vor der Ausführung protokolliert werden. Standardmäßig ruft die LogCommand-Methode LogParameter für jeden Parameter auf. Sie können dies auch in Ihrer Außerkraftsetzung tun oder Parameter anders behandeln.
- LogResult: Setzen Sie diese Methode außer Kraft, um zu ändern, wie das Ergebnis der Ausführung eines Befehls protokolliert wird.
- LogParameter: Setzen Sie diese Methode außer Kraft, um die Formatierung und den Inhalt der Parameterprotokollierung zu ändern.
Angenommen, wir wollten nur eine einzelne Zeile protokollieren, bevor jeder Befehl an die Datenbank gesendet wird. Dies kann mit zwei Außerkraftsetzungen erfolgen:
- Außerkraftsetzung von LogCommand zum Formatieren und Schreiben der einzelnen Zeile von SQL
- Außerkraftsetzung von LogResult, um nichts zu tun
Der Code sähe in etwa so aus:
public class OneLineFormatter : DatabaseLogFormatter
{
public OneLineFormatter(DbContext context, Action<string> writeAction)
: base(context, writeAction)
{
}
public override void LogCommand<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
Write(string.Format(
"Context '{0}' is executing command '{1}'{2}",
Context.GetType().Name,
command.CommandText.Replace(Environment.NewLine, ""),
Environment.NewLine));
}
public override void LogResult<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
}
}
Um die Ausgabe zu protokollieren, rufen Sie einfach die Write-Methode auf, die die Ausgabe an den konfigurierten Schreibdelegat sendet.
(Beachten Sie, dass dieser Code das einfache Entfernen von Zeilenumbrüchen nur als Beispiel veranschaulicht. Zum Anzeigen komplexer strukturierter Abfragesprache funktioniert dies eher weniger gut.)
Festlegen des DatabaseLogFormatter-Parameters
Nachdem eine neue DatabaseLogFormatter-Klasse erstellt wurde, muss sie bei EF registriert werden. Dies erfolgt mithilfe der codebasierten Konfiguration. Kurz gesagt bedeutet dies, dass eine neue Klasse erstellt wird, die von DbConfiguration in derselben Assembly wie Ihre DbContext-Klasse abgeleitet wird, und dann SetDatabaseLogFormatter im Konstruktor dieser neuen Klasse aufruft. Beispiel:
public class MyDbConfiguration : DbConfiguration
{
public MyDbConfiguration()
{
SetDatabaseLogFormatter(
(context, writeAction) => new OneLineFormatter(context, writeAction));
}
}
Verwenden der neuen DatabaseLogFormatter-Klasse
Diese neue DatabaseLogFormatter-Klasse wird jetzt verwendet, wenn Database.Log festgelegt ist. Das Ausführen des Codes aus Teil 1 führt nun zu der folgenden Ausgabe:
Context 'BlogContext' is executing command 'SELECT TOP (1) [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'
Abfangen von Bausteinen
Bisher haben wir uns die Verwendung von DbContext.Database.Log zum Protokollieren der von EF generierten strukturierten Abfragesprache angesehen. Dieser Code ist jedoch tatsächlich eine relativ dünne Schicht über einigen Bausteinen auf niedriger Ebene für einen allgemeineren Abfangvorgang.
Schnittstellen für den Abfangvorgang
Der Code für den Abfangvorgang basiert auf dem Konzept von Abfangschnittstellen. Diese Schnittstellen erben von IDbInterceptor und definieren Methoden, die aufgerufen werden, wenn EF eine Aktion ausführt. Die Absicht besteht darin, dass eine Schnittstelle pro Objekttyp vorhanden ist, der abgefangen wird. Beispielsweise definiert die IDbCommandInterceptor-Schnittstelle Methoden, die aufgerufen werden, bevor EF einen Aufruf von ExecuteNonQuery, ExecuteScalar, ExecuteReader und verwandten Methoden durchführt. Ebenso definiert die Schnittstelle Methoden, die aufgerufen werden, wenn jeder dieser Vorgänge abgeschlossen ist. Die DatabaseLogFormatter-Klasse, die wir oben betrachtet haben, implementiert diese Schnittstelle zum Protokollieren von Befehlen.
Der Abfangkontext
Wenn Sie sich die Methoden ansehen, die für eine der Interceptorschnittstellen definiert sind, ist ersichtlich, dass jeder Aufruf ein Objekt vom Typ „DbInterceptionContext“ oder einen davon abgeleiteten Typ erhält, z. B. „DbCommandInterceptionContext“<>. Dieses Objekt enthält kontextbezogene Informationen zu der Aktion, die von EF ausgeführt werden. Wenn die Aktion beispielsweise im Auftrag einer DbContext-Klasse ausgeführt wird, wird die DbContext-Klasse in DbInterceptionContext eingeschlossen. Ebenso wird für Befehle, die asynchron ausgeführt werden, das IsAsync-Flag für DbCommandInterceptionContext festgelegt.
Ergebnisverarbeitung
Die DbCommandInterceptionContext<>-Klasse enthält Eigenschaften namens „Result“, „OriginalResult“, „Exception“ und „OriginalException“. Diese Eigenschaften werden für Aufrufe der Abfangmethoden, die aufgerufen werden, auf NULL/0 (null) festgelegt, bevor der Vorgang ausgeführt wird, d. h. für die „...Executing“-Methoden. Wenn der Vorgang erfolgreich ausgeführt wird, werden „Result“ und „OriginalResult“ auf das Ergebnis des Vorgangs festgelegt. Diese Werte können dann in den Abfangmethoden beobachtet werden, die aufgerufen werden, nachdem der Vorgang ausgeführt wurde, d. h. für die „...Executed“-Methoden. Entsprechend werden die Eigenschaften „Exception“ und „OriginalException“ festgelegt, wenn der Vorgang ausgelöst wird.
Unterdrücken der Ausführung
Wenn ein Interceptor die Result-Eigenschaft festlegt, bevor der Befehl ausgeführt wurde (in einem der „…Executing“-Methoden) versucht EF nicht, den Befehl tatsächlich auszuführen, sondern verwendet stattdessen nur das Resultset. Der Interceptor kann also die Ausführung des Befehls unterdrücken, aber EF wird so fortgesetzt, als ob der Befehl ausgeführt wurde.
Ein Beispiel dafür, wie dieser Ansatz verwendet werden kann, ist die Befehlsbatchverarbeitung, die traditionell mit einem Wrappinganbieter durchgeführt wurde. Der Interceptor speichert den Befehl für die spätere Ausführung als Batch, tut für EF aber so, als ob der Befehl normal ausgeführt wurde. Beachten Sie, dass mehr zum Implementieren der Batchverarbeitung erforderlich ist, aber dies ist ein Beispiel dafür, wie das Ändern des Abfangergebnisses verwendet werden kann.
Die Ausführung kann auch unterdrückt werden, indem die Exception-Eigenschaft in einer der „...Executing“-Methoden festgelegt wird. Dies führt dazu, dass EF fortgesetzt wird, als ob die Ausführung des Vorgangs fehlschlug, indem die angegebene Ausnahme ausgelöst wurde. Dies kann natürlich dazu führen, dass die Anwendung abstürzt, aber es kann auch eine vorübergehende Ausnahme oder eine andere Ausnahme sein, die von EF verarbeitet wird. Dieser Ansatz kann beispielsweise in Testumgebungen verwendet werden, um das Verhalten einer Anwendung zu testen, wenn die Ausführung von Befehlen fehlschlägt.
Ändern des Ergebnisses nach der Ausführung
Wenn ein Interceptor die Result-Eigenschaft festlegt, nachdem der Befehl ausgeführt wurde (in einem der „...Executed“-Methoden) dann verwendet EF das geänderte Ergebnis anstelle des Ergebnisses, das tatsächlich vom Vorgang zurückgegeben wurde. Wenn ein Interceptor die Exception-Eigenschaft festlegt, nachdem der Befehl ausgeführt wurde, löst EF die festgelegte Ausnahme aus, als ob der Vorgang die Ausnahme ausgelöst hatte.
Ein Interceptor kann die Exception-Eigenschaft auch auf NULL festlegen, um anzugeben, dass keine Ausnahme ausgelöst werden soll. Dies kann nützlich sein, wenn die Ausführung des Vorgangs fehlgeschlagen ist, aber der Interceptor möchte, dass EF fortgesetzt werden soll, so als ob der Vorgang erfolgreich war. Dies umfasst in der Regel auch das Festlegen von „Result“, sodass EF einen Ergebniswert aufweist, mit dem weiterhin gearbeitet werden kann.
OriginalResult und OriginalException
Nachdem EF einen Vorgang ausgeführt hat, werden entweder die Eigenschaften „Result“ und „OriginalResult“ festgelegt, wenn die Ausführung nicht erfolgreich war, oder die Eigenschaften „Exception“ und „OriginalException“, wenn die Ausführung mit einer Ausnahme fehlgeschlagen ist.
Die Eigenschaften „OriginalResult“ und „OriginalException“ sind schreibgeschützt und werden nur von EF festgelegt, nachdem ein Vorgang tatsächlich ausgeführt wurde. Diese Eigenschaften können nicht von Interceptors festgelegt werden. Dies bedeutet, dass jeder Interceptor zwischen einer Ausnahme oder einem Ergebnis unterscheiden kann, die bzw. das von einem anderen Interceptor festgelegt wurde, im Gegensatz zu der tatsächlichen Ausnahme oder dem Ergebnis, die bzw. das beim Ausführen des Vorgangs aufgetreten ist.
Registrieren von Abfangfunktionen
Sobald eine Klasse erstellt wurde, die eine oder mehrere der Abfangschnittstellen implementiert, kann sie mithilfe der DbInterception-Klasse bei EF registriert werden. Beispiel:
DbInterception.Add(new NLogCommandInterceptor());
Interceptors können auch auf App-Domänenebene mithilfe des codebasierten DbConfiguration-Konfigurationsmechanismus registriert werden.
Beispiel: Protokollierung bei NLog
Lassen Sie uns all das nun in einem Beispiel zusammenführen, und verwenden Sie IdbCommandInterceptor und NLog für folgende Vorgänge:
- Protokollieren einer Warnung für alle Befehle, die nicht asynchron ausgeführt werden
- Protokollieren eines Fehlers für alle Befehle, die beim Ausführen ausgelöst werden
Dies ist die Klasse, die die Protokollierung durchführt, die wie oben gezeigt registriert werden sollte:
public class NLogCommandInterceptor : IDbCommandInterceptor
{
private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
public void NonQueryExecuting(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void NonQueryExecuted(
DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
LogIfError(command, interceptionContext);
}
public void ReaderExecuting(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void ReaderExecuted(
DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
LogIfError(command, interceptionContext);
}
public void ScalarExecuting(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
LogIfNonAsync(command, interceptionContext);
}
public void ScalarExecuted(
DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
LogIfError(command, interceptionContext);
}
private void LogIfNonAsync<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
if (!interceptionContext.IsAsync)
{
Logger.Warn("Non-async command used: {0}", command.CommandText);
}
}
private void LogIfError<TResult>(
DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
if (interceptionContext.Exception != null)
{
Logger.Error("Command {0} failed with exception {1}",
command.CommandText, interceptionContext.Exception);
}
}
}
Beachten Sie, dass dieser Code den Abfangkontext verwendet, um zu ermitteln, wann ein Befehl nicht asynchron ausgeführt wird und wann ein Fehler beim Ausführen eines Befehls aufgetreten ist.