Protokolování a zachycení databázových operací

  • Článek

Poznámka

Pouze EF6 a novější – Funkce, rozhraní API atd. popsané na této stránce byly představeny v Entity Framework 6. Pokud používáte starší verzi, některé nebo všechny informace nemusí být platné.

Počínaje entity Framework 6 může entity Framework kdykoli odeslat příkaz do databáze, může být tento příkaz zachycen kódem aplikace. Nejčastěji se používá pro protokolování SQL, ale můžete ho také použít k úpravě nebo přerušení příkazu.

Ef konkrétně zahrnuje:

  • Vlastnost protokolu pro kontext podobný dataContext.Log v LINQ to SQL
  • Mechanismus pro přizpůsobení obsahu a formátování výstupu odeslaného do protokolu
  • Stavební bloky nízké úrovně pro průsečík poskytují větší kontrolu a flexibilitu

Vlastnost Context Log

Vlastnost DbContext.Database.Log lze nastavit na delegáta pro libovolnou metodu, která přebírá řetězec. Nejčastěji se používá s jakýmkoli TextWriter nastavením na "Write" metoda tohoto TextWriter. Všechny SQL vygenerované aktuálním kontextem budou protokolovány do daného zapisovače. Například následující kód bude protokolovat SQL do konzoly:

using (var context = new BlogContext())
{
    context.Database.Log = Console.Write;

    // Your code here...
}

Všimněte si toho kontextu. Database.Log je nastavena na Console.Write. To je vše, co je potřeba k přihlášení SQL do konzoly.

Pojďme přidat jednoduchý dotaz, vložit nebo aktualizovat kód, abychom viděli nějaký výstup:

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();
}

Tím se vygeneruje následující výstup:

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

(Všimněte si, že se jedná o výstup za předpokladu, že k inicializaci databáze již došlo. Pokud k inicializaci databáze ještě nedošlo, bude existovat mnohem více výstupu, který ukazuje, že všechny pracovní migrace probíhají pod kryty pro kontrolu nebo vytvoření nové databáze.)

Co se zaprotokoluje?

Pokud je vlastnost Log nastavena, budou zaznamenány všechny následující položky:

  • SQL pro všechny různé druhy příkazů Například:
    • Dotazy, včetně běžných dotazů LINQ, dotazů eSQL a nezpracovaných dotazů z metod, jako je SqlQuery
    • Vloží, aktualizuje a odstraní vygenerované jako součást SaveChanges.
    • Dotazy na načítání relací, jako jsou dotazy vygenerované opožděným načítáním
  • Parametry
  • Zda se příkaz spouští asynchronně
  • Časové razítko označující, kdy se spustil příkaz
  • Jestli se příkaz úspěšně dokončil, selhal vyvoláním výjimky nebo se pro asynchronní synchronizaci zrušil.
  • Některá označení výsledné hodnoty
  • Přibližná doba, kterou trvalo provedení příkazu. Všimněte si, že je to čas od odeslání příkazu k vrácení výsledného objektu zpět. Nezahrnuje čas na čtení výsledků.

Při pohledu na výše uvedený příklad výstupu jsou všechny čtyři protokolované příkazy:

  • Dotaz, který je výsledkem volání kontextu. Blogy.First
    • Všimněte si, že metoda ToString pro získání SQL by pro tento dotaz nefungovala, protože "First" neposkytuje IQueryable, na kterém by bylo možné volat ToString.
  • Dotaz, který je výsledkem opožděného načítání blogu. Příspěvky
    • Všimněte si podrobností parametru pro hodnotu klíče, pro kterou probíhá opožděné načítání.
    • Protokolují se pouze vlastnosti parametru, které jsou nastaveny na jiné než výchozí hodnoty. Například vlastnost Size je zobrazena pouze v případě, že není nula.
  • Dva příkazy, které jsou výsledkem SaveChangesAsync; jeden pro aktualizaci pro změnu názvu příspěvku, druhý pro vložení pro přidání nového příspěvku
    • Všimněte si podrobností o parametrech vlastností FK a Title.
    • Všimněte si, že se tyto příkazy spouští asynchronně.

Protokolování na různá místa

Jak je znázorněno výše, protokolování do konzoly je velmi snadné. Je také snadné protokolovat do paměti, souboru atd. pomocí různých druhů TextWriter.

Pokud jste obeznámeni s LINQ to SQL, můžete si všimnout, že v LINQ to SQL vlastnost Log je nastavena na skutečný TextWriter objekt (například Console.Out), zatímco v EF Log vlastnost je nastavena na metodu, která přijímá řetězec (například Console.Write nebo Console.Out.Write). Důvodem je oddělení EF od TextWriter přijetím libovolného delegáta, který může fungovat jako jímka pro řetězce. Představte si například, že už máte určitou architekturu protokolování a definuje metodu protokolování takto:

public class MyLogger
{
    public void Log(string component, string message)
    {
        Console.WriteLine("Component: {0} Message: {1} ", component, message);
    }
}

Můžete ho připojit k vlastnosti PROTOKOLU EF, například takto:

var logger = new MyLogger();
context.Database.Log = s => logger.Log("EFApp", s);

Protokolování výsledků

Výchozí protokolovací protokoluje text příkazu (SQL), parametry a řádek Provádění s časovým razítkem před odesláním příkazu do databáze. Po spuštění příkazu se zaprotokoluje řádek dokončený obsahující uplynulý čas.

Všimněte si, že u asynchronních příkazů se řádek dokončený neprotokoluje, dokud asynchronní úloha ve skutečnosti nedokončí, selže nebo se zruší.

Řádek Dokončeno obsahuje různé informace v závislosti na typu příkazu a na tom, zda bylo spuštění úspěšné.

Úspěšné spuštění

U příkazů, které se úspěšně dokončily, je výstup Dokončeno v x ms s výsledkem: následované některými údaji o tom, co výsledek byl. Pro příkazy, které vracejí čtečku dat, je indikací výsledku typ DbDataReader vrácen. Příkazy vracející celočíselnou hodnotu, například příkaz update zobrazený nad výsledkem, je celé číslo.

Neúspěšné spuštění

Pro příkazy, které selžou vyvoláním výjimky, výstup obsahuje zprávu z výjimky. Například použití SqlQuery k dotazování na tabulku, která existuje, způsobí výstup protokolu přibližně takto:

SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.

Zrušené spuštění

U asynchronních příkazů, ve kterých je úloha zrušena, může dojít k selhání s výjimkou, protože to dělá základní ADO.NET poskytovatel často při pokusu o zrušení. Pokud k tomu nedojde a úloha se zruší čistě, výstup bude vypadat přibližně takto:

update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

Změna obsahu protokolu a formátování

Pod kryt Database.Log vlastnost používá DatabaseLogFormatter objektu. Tento objekt efektivně vytvoří vazbu IDbCommandInterceptor implementace (viz níže) na delegáta, který přijímá řetězce a DbContext. To znamená, že metody databaseLogFormatter se volají před a po spuštění příkazů ef. Tyto metody DatabaseLogFormatter shromažďují a formátují výstup protokolu a odesílají ho delegátovi.

Přizpůsobení databaseLogFormatter

Změnou toho, co se protokoluje a jak je formátováno, lze dosáhnout vytvořením nové třídy, která je odvozena z DatabaseLogFormatter a přepíše metody podle potřeby. Nejběžnějšími metodami přepsání jsou:

  • LogCommand – Přepište to tak, aby se změnil způsob protokolování příkazů před jejich spuštěním. Ve výchozím nastavení LogCommand volá LogParameter pro každý parametr; v přepsání nebo zpracování parametrů můžete místo toho provést totéž.
  • LogResult – Přepište to tak, aby se změnil způsob protokolování výsledku spuštění příkazu.
  • LogParameter – Přepište to tak, aby se změnilo formátování a obsah protokolování parametrů.

Předpokládejme například, že jsme chtěli protokolovat jenom jeden řádek před odesláním každého příkazu do databáze. Můžete to provést se dvěma přepsáními:

  • Přepsání logCommand pro formátování a zápis jednoho řádku SQL
  • Přepište LogResult tak, aby nic nedělaly.

Kód by vypadal přibližně takto:

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)
    {
    }
}

Pokud chcete výstup protokolovat, jednoduše zavolejte metodu Write, která odešle výstup konfigurovanému delegátu zápisu.

(Všimněte si, že tento kód zjednodušuje odebrání konců řádků stejně jako příklad. Pravděpodobně nebude fungovat dobře pro zobrazení komplexního SQL.)

Nastavení DatabaseLogFormatter

Po vytvoření nové třídy DatabaseLogFormatter je potřeba ji zaregistrovat v EF. To se provádí pomocí konfigurace založené na kódu. V maticshellu to znamená vytvoření nové třídy, která je odvozena z DbConfiguration ve stejném sestavení jako DbContext třída a potom volání SetDatabaseLogFormatter v konstruktoru této nové třídy. Příklad:

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

Použití nového formátu DatabaseLogFormatter

Tento nový DatabaseLogFormatter se teď použije vždy, když je nastaven Database.Log. Spuštění kódu z části 1 tedy bude mít za následek následující výstup:

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()'

Stavební bloky průsečíku

Zatím jsme se podívali na to, jak pomocí DbContext.Database.Log protokolovat SQL vygenerované EF. Ale tento kód je ve skutečnosti poměrně tenký fasáda nad některými stavebními bloky nízké úrovně pro obecnější průsečík.

Rozhraní průsečíku

Kód průsečíku je postaven na konceptu rozhraní průsečíku. Tato rozhraní dědí z IDbInterceptor a definují metody, které se volají, když EF provede nějakou akci. Záměrem je mít jedno rozhraní na typ zachyceného objektu. Například IDbCommandInterceptor rozhraní definuje metody, které jsou volány před EF provede volání ExecuteNonQuery, ExecuteScalar, ExecuteReader a souvisejících metod. Rozhraní také definuje metody, které se volají při dokončení každé z těchto operací. DatabaseLogFormatter třída, kterou jsme se podívali výše, implementuje toto rozhraní pro protokolování příkazů.

Kontext průsečíku

Při pohledu na metody definované na libovolné z rozhraní průsečíku je zřejmé, že každé volání je dán objekt typu DbInterceptionContext nebo některého typu odvozeného z tohoto, například DbCommandInterceptionContext<>. Tento objekt obsahuje kontextové informace o akci, kterou ef provádí. Pokud se například akce provádí jménem DbContext, je dbContext zahrnuta do dbInterceptionContext. Podobně u příkazů, které se spouští asynchronně, je příznak IsAsync nastaven na DbCommandInterceptionContext.

Zpracování výsledků

DbCommandInterceptionContext<> třída obsahuje vlastnosti s názvem Result, OriginalResult, Exception a OriginalException. Tyto vlastnosti jsou nastaveny na hodnotu null/nula pro volání metod průsečíku, které jsou volána před provedením operace – to znamená pro ... Provádění metod. Pokud se operace provede a bude úspěšná, nastaví se výsledek operace Result a OriginalResult. Tyto hodnoty lze pak pozorovat v metodách průsečíku, které jsou volána po provedení operace – to znamená na ... Spuštěné metody. Podobně, pokud operace vyvolá, bude vlastnost Exception a OriginalException nastavena.

Potlačení provádění

Pokud průsečík nastaví vlastnost Result před provedením příkazu (v jednom z ... Provádění metod) se ef nepokusí skutečně spustit příkaz, ale místo toho použije pouze sadu výsledků. Jinými slovy, průsečík může potlačit spuštění příkazu, ale má ef pokračovat, jako kdyby byl příkaz proveden.

Příkladem toho, jak se to dá použít, je dávkování příkazů, které se tradičně prováděly se zprostředkovatelem zabalení. Průsečík uloží příkaz pro pozdější spuštění jako dávku, ale "předstíral" ef, že příkaz provedl jako normální. Všimněte si, že k implementaci dávkování vyžaduje více, ale je to příklad, jak se může použít změna výsledku průsečíku.

Spuštění lze také potlačit nastavením exception vlastnost v některé z ... Provádění metod. To způsobí, že ef bude pokračovat, jako kdyby spuštění operace selhalo vyvoláním dané výjimky. To může samozřejmě způsobit chybové ukončení aplikace, ale může se jednat také o přechodnou výjimku nebo jinou výjimku, kterou zpracovává EF. Můžete ho například použít v testovacích prostředích k otestování chování aplikace při selhání spuštění příkazu.

Změna výsledku po provedení

Pokud průsečík nastaví vlastnost Result po provedení příkazu (v jednom z ... Provedené metody) pak EF použije změněný výsledek místo výsledku, který byl skutečně vrácen z operace. Podobně pokud průsečík nastaví vlastnost Exception po provedení příkazu, ef vyvolá nastavenou výjimku, jako kdyby operace vyvolala výjimku.

Průsečík může také nastavit vlastnost Exception na hodnotu null, která indikuje, že by neměla být vyvolán žádná výjimka. To může být užitečné v případě, že spuštění operace selhalo, ale průsečík chce, aby EF pokračoval, jako kdyby operace proběhla úspěšně. To obvykle zahrnuje také nastavení výsledku tak, aby ef má nějakou výslednou hodnotu pro práci s tím, jak pokračuje.

OriginalResult a OriginalException

Jakmile ef spustí operaci, nastaví buď vlastnosti Result a OriginalResult, pokud provádění selžou, nebo vlastnosti Exception a OriginalException, pokud spuštění selhalo s výjimkou.

Vlastnosti OriginalResult a OriginalException jsou jen pro čtení a jsou nastaveny pouze ef po skutečném provedení operace. Tyto vlastnosti nelze nastavit průsečíky. To znamená, že jakýkoli průsečík může rozlišovat mezi výjimkou výjimky nebo výsledku nastaveného jiným zachytáváním, a nikoli skutečnou výjimkou nebo výsledkem, ke kterému došlo při spuštění operace.

Registrace průsečíků

Jakmile byla vytvořena třída, která implementuje jedno nebo více rozhraní průsečíku, může být registrována v EF pomocí DbInterception třídy. Příklad:

DbInterception.Add(new NLogCommandInterceptor());

Průsečíky lze také zaregistrovat na úrovni domény aplikace pomocí konfiguračního mechanismu založeného na kódu DbConfiguration.

Příklad: Protokolování do NLogu

Pojďme to seskupit do příkladu, který používá IDbCommandInterceptor a NLog k:

  • Protokolování upozornění pro jakýkoli příkaz, který se spouští nesynchronně
  • Protokolování chyby pro jakýkoli příkaz, který se vyvolá při spuštění

Tady je třída, která provede protokolování, která by měla být registrována, jak je znázorněno výše:

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);
        }
    }
}

Všimněte si, jak tento kód používá kontext průsečíku ke zjištění, kdy se příkaz spouští nesynchronně, a ke zjištění, kdy došlo k chybě při provádění příkazu.