Registrazione e intercettazione delle operazioni di database

Articolo
09/12/2023

Nota

Solo EF6 e versioni successive: funzionalità, API e altri argomenti discussi in questa pagina sono stati introdotti in Entity Framework 6. Se si usa una versione precedente, le informazioni qui riportate, o parte di esse, non sono applicabili.

A partire da Entity Framework 6, ogni volta che Entity Framework invia un comando al database, questo comando può essere intercettato dal codice dell'applicazione. Questa operazione viene usata più comunemente per la registrazione di SQL, ma può essere usata anche per modificare o interrompere il comando.

In particolare, Entity Framework include:

Proprietà Log per il contesto simile a DataContext.Log in LINQ to SQL
Meccanismo per personalizzare il contenuto e la formattazione dell'output inviato al log
Blocchi predefiniti di basso livello per l'intercettazione offrendo maggiore controllo/flessibilità

Proprietà Log del contesto

La proprietà DbContext.Database.Log può essere impostata su un delegato per qualsiasi metodo che accetta una stringa. In genere viene usato con qualsiasi TextWriter impostandolo sul metodo "Write" di tale TextWriter. Tutti i dati SQL generati dal contesto corrente verranno registrati nel writer. Ad esempio, il codice seguente registra SQL nella console:

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

    // Your code here...
}

Si noti che il contesto. Database.Log è impostato su Console.Write. Questo è tutto ciò che è necessario per registrare SQL nella console.

Si aggiungerà ora un semplice codice di query/inserimento/aggiornamento in modo da poter visualizzare alcuni output:

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

Verrà generato l'output seguente:

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

Si noti che si tratta dell'output presupponendo che sia già stata eseguita un'inizializzazione del database. Se l'inizializzazione del database non fosse già stata eseguita, ci sarebbe un output molto maggiore che mostra tutte le migrazioni di lavoro eseguite sotto le quinte per verificare o creare un nuovo database.

Cosa viene registrato?

Quando la proprietà Log è impostata, verranno registrate tutte le operazioni seguenti:

SQL per tutti i diversi tipi di comandi. Ad esempio:
- Query, incluse query LINQ normali, query eSQL e query non elaborate da metodi come SqlQuery
- Inserisce, aggiorna ed eliminazioni generate come parte di SaveChanges
- Caricamento di relazioni di query, ad esempio quelle generate dal caricamento differita
Parametri
Indica se il comando viene eseguito in modo asincrono
Timestamp che indica quando il comando ha avviato l'esecuzione
Indica se il comando è stato completato correttamente, non riuscito generando un'eccezione o, per async, è stato annullato
Indicazione del valore del risultato
Quantità approssimativa di tempo impiegato per eseguire il comando. Si noti che questo è il momento dell'invio del comando al recupero dell'oggetto risultato. Non include il tempo necessario per leggere i risultati.

Esaminando l'output di esempio precedente, ognuno dei quattro comandi registrati è:

Query risultante dalla chiamata al contesto. Blogs.First
- Si noti che il metodo ToString di ottenere SQL non avrebbe funzionato per questa query perché "First" non fornisce un IQueryable in cui è possibile chiamare ToString
Query risultante dal caricamento differita del blog. Messaggi
- Si notino i dettagli del parametro per il valore della chiave per il quale si sta verificando il caricamento differita
- Vengono registrate solo le proprietà del parametro impostate su valori non predefiniti. Ad esempio, la proprietà Size viene visualizzata solo se è diversa da zero.
Due comandi risultanti da SaveChangesAsync; uno per l'aggiornamento per modificare un titolo post, l'altro per un inserimento per aggiungere un nuovo post
- Si notino i dettagli del parametro per le proprietà FK e Title
- Si noti che questi comandi vengono eseguiti in modo asincrono

Registrazione in posizioni diverse

Come illustrato in precedenza, la registrazione alla console è molto semplice. È anche facile accedere alla memoria, al file e così via usando diversi tipi di TextWriter.

Se si ha familiarità con LINQ to SQL, è possibile notare che in LINQ to SQL la proprietà Log è impostata sull'oggetto TextWriter effettivo ,ad esempio Console.Out, mentre in EF la proprietà Log è impostata su un metodo che accetta una stringa, ad esempio Console.Write o Console.Out.Write. Il motivo è quello di disaccoppiare EF da TextWriter accettando qualsiasi delegato che possa fungere da sink per le stringhe. Si supponga, ad esempio, di avere già un framework di registrazione e di definire un metodo di registrazione simile al seguente:

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

Questa operazione può essere associata alla proprietà Log di Entity Framework come illustrato di seguito:

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

Registrazione dei risultati

Il logger predefinito registra il testo del comando (SQL), i parametri e la riga "Esecuzione" con un timestamp prima dell'invio del comando al database. Una riga "completata" contenente il tempo trascorso viene registrata dopo l'esecuzione del comando.

Si noti che per i comandi asincroni la riga "completata" non viene registrata finché l'attività asincrona non viene effettivamente completata, non riesce o viene annullata.

La riga "completata" contiene informazioni diverse a seconda del tipo di comando e se l'esecuzione è riuscita o meno.

Esecuzione riuscita

Per i comandi che completano correttamente l'output è "Completato in x ms con risultato: " seguito da un'indicazione del risultato. Per i comandi che restituiscono un lettore di dati, l'indicazione del risultato è il tipo di DbDataReader restituito. Per i comandi che restituiscono un valore intero, ad esempio il comando update illustrato sopra il risultato visualizzato è l'intero.

Esecuzione non riuscita

Per i comandi che hanno esito negativo generando un'eccezione, l'output contiene il messaggio dell'eccezione. Ad esempio, l'uso di SqlQuery per eseguire una query su una tabella esistente comporterà un output del log simile al seguente:

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

Esecuzione annullata

Per i comandi asincroni in cui l'attività viene annullata, il risultato potrebbe non riuscire con un'eccezione, poiché questo è ciò che il provider di ADO.NET sottostante esegue spesso quando viene effettuato un tentativo di annullamento. Se questo non accade e l'attività viene annullata in modo pulito, l'output sarà simile al seguente:

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

Modifica del contenuto e della formattazione del log

Sotto le quinte la proprietà Database.Log usa un oggetto DatabaseLogFormatter. Questo oggetto associa in modo efficace un'implementazione di IDbCommandInterceptor (vedere di seguito) a un delegato che accetta stringhe e dbContext. Ciò significa che i metodi in DatabaseLogFormatter vengono chiamati prima e dopo l'esecuzione dei comandi da EF. Questi metodi DatabaseLogFormatter raccolgono e formattano l'output del log e lo inviano al delegato.

Personalizzazione di DatabaseLogFormatter

La modifica di ciò che viene registrato e il modo in cui viene formattata può essere ottenuta creando una nuova classe che deriva da DatabaseLogFormatter ed esegue l'override dei metodi in base alle esigenze. I metodi più comuni per eseguire l'override sono:

LogCommand: eseguire l'override di questa opzione per modificare la modalità di registrazione dei comandi prima dell'esecuzione. Per impostazione predefinita, LogCommand chiama LogParameter per ogni parametro; è possibile scegliere di eseguire la stessa operazione nell'override o gestire i parametri in modo diverso.
LogResult: eseguire l'override di questa opzione per modificare la modalità di registrazione del risultato dall'esecuzione di un comando.
LogParameter: eseguire l'override di questa opzione per modificare la formattazione e il contenuto della registrazione dei parametri.

Si supponga, ad esempio, di voler registrare una sola riga prima che ogni comando venga inviato al database. Questa operazione può essere eseguita con due sostituzioni:

Eseguire l'override di LogCommand per formattare e scrivere la singola riga di SQL
Eseguire l'override di LogResult per non eseguire alcuna operazione.

Il codice sarà simile al seguente:

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

Per registrare l'output è sufficiente chiamare il metodo Write che invierà l'output al delegato di scrittura configurato.

Si noti che questo codice esegue la rimozione semplicistica delle interruzioni di riga come esempio. Probabilmente non funziona correttamente per la visualizzazione di SQL complessi.

Impostazione di DatabaseLogFormatter

Dopo aver creato una nuova classe DatabaseLogFormatter, è necessario registrarla con ENTITY Framework. Questa operazione viene eseguita usando la configurazione basata su codice. In breve questo significa creare una nuova classe che deriva da DbConfiguration nello stesso assembly della classe DbContext e quindi chiamare SetDatabaseLogFormatter nel costruttore di questa nuova classe. Ad esempio:

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

Uso del nuovo DatabaseLogFormatter

Il nuovo DatabaseLogFormatter verrà ora usato ogni volta che è impostato Database.Log. L'esecuzione del codice della parte 1 comporterà quindi l'output seguente:

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

Blocchi predefiniti di intercettazione

Finora è stato illustrato come usare DbContext.Database.Log per registrare il codice SQL generato da ENTITY. Ma questo codice è in realtà una facciata relativamente sottile su alcuni blocchi predefiniti di basso livello per l'intercettazione più generale.

Interfacce di intercettazione

Il codice di intercettazione si basa sul concetto di interfacce di intercettazione. Queste interfacce ereditano da IDbInterceptor e definiscono i metodi chiamati quando EF esegue un'azione. La finalità consiste nell'avere un'interfaccia per ogni tipo di oggetto intercettato. Ad esempio, l'interfaccia IDbCommandInterceptor definisce i metodi che vengono chiamati prima che EF effettui una chiamata a ExecuteNonQuery, ExecuteScalar, ExecuteReader e metodi correlati. Analogamente, l'interfaccia definisce i metodi che vengono chiamati al completamento di ognuna di queste operazioni. La classe DatabaseLogFormatter esaminata in precedenza implementa questa interfaccia per registrare i comandi.

Contesto di intercettazione

Esaminando i metodi definiti in qualsiasi interfaccia dell'intercettore, è evidente che a ogni chiamata viene assegnato un oggetto di tipo DbInterceptionContext o un tipo derivato da questo, ad esempio DbCommandInterceptionContext<>. Questo oggetto contiene informazioni contestuali sull'azione eseguita da Entity Framework. Ad esempio, se l'azione viene eseguita per conto di un Oggetto DbContext, dbContext viene incluso in DbInterceptionContext. Analogamente, per i comandi eseguiti in modo asincrono, il flag IsAsync viene impostato su DbCommandInterceptionContext.

Gestione dei risultati

La classe DbCommandInterceptionContext<> contiene proprietà denominate Result, OriginalResult, Exception e OriginalException. Queste proprietà sono impostate su null/zero per le chiamate ai metodi di intercettazione chiamati prima dell'esecuzione dell'operazione, ovvero per ... Esecuzione di metodi. Se l'operazione viene eseguita e ha esito positivo, Result e OriginalResult vengono impostati sul risultato dell'operazione. Questi valori possono quindi essere osservati nei metodi di intercettazione chiamati dopo l'esecuzione dell'operazione, ovvero in ... Metodi eseguiti. Analogamente, se l'operazione genera un'eccezione, verranno impostate le proprietà Exception e OriginalException.

Eliminazione dell'esecuzione

Se un intercettore imposta la proprietà Result prima dell'esecuzione del comando (in uno dei ... L'esecuzione di metodi) ef non tenterà di eseguire effettivamente il comando, ma userà semplicemente il set di risultati. In altre parole, l'intercettore può eliminare l'esecuzione del comando, ma avere Entity Framework continuare come se il comando fosse stato eseguito.

Un esempio di come può essere usato è l'invio in batch dei comandi che tradizionalmente è stato eseguito con un provider di wrapping. L'intercettore archiviava il comando per un'esecuzione successiva come batch, ma "pretendeva" a EF che il comando fosse stato eseguito normalmente. Si noti che è necessario più di questo per implementare l'invio in batch, ma questo è un esempio di come modificare il risultato dell'intercettazione potrebbe essere usato.

L'esecuzione può anche essere eliminata impostando la proprietà Exception in uno dei ... Esecuzione di metodi. In questo modo Ef continua come se l'esecuzione dell'operazione non fosse riuscita generando l'eccezione specificata. Ciò può naturalmente causare l'arresto anomalo dell'applicazione, ma può anche trattarsi di un'eccezione temporanea o di un'altra eccezione gestita da Entity Framework. Ad esempio, questo può essere usato negli ambienti di test per testare il comportamento di un'applicazione quando l'esecuzione del comando non riesce.

Modifica del risultato dopo l'esecuzione

Se un intercettore imposta la proprietà Result dopo l'esecuzione del comando (in uno dei ... Metodi eseguiti) Ef userà quindi il risultato modificato anziché il risultato effettivamente restituito dall'operazione. Analogamente, se un intercettore imposta la proprietà Exception dopo l'esecuzione del comando, EF genererà l'eccezione impostata come se l'operazione avesse generato l'eccezione.

Un intercettore può anche impostare la proprietà Exception su null per indicare che non deve essere generata alcuna eccezione. Ciò può essere utile se l'esecuzione dell'operazione non è riuscita, ma l'intercettore desidera che ENTITY continui come se l'operazione fosse riuscita. Questo comporta in genere anche l'impostazione del risultato in modo che EF abbia un valore di risultato da usare man mano che continua.

OriginalResult e OriginalException

Dopo che EF ha eseguito un'operazione, verranno impostate le proprietà Result e OriginalResult se l'esecuzione non ha avuto esito negativo o le proprietà Exception e OriginalException se l'esecuzione non è riuscita con un'eccezione.

Le proprietà OriginalResult e OriginalException sono di sola lettura e vengono impostate solo da EF dopo l'esecuzione effettiva di un'operazione. Queste proprietà non possono essere impostate dagli intercettori. Ciò significa che qualsiasi intercettore può distinguere tra un'eccezione o un risultato impostato da un altro intercettore anziché l'eccezione reale o il risultato che si è verificato quando l'operazione è stata eseguita.

Registrazione degli intercettori

Dopo aver creato una classe che implementa una o più interfacce di intercettazione, è possibile registrarla con Entity Framework usando la classe DbInterception. Ad esempio:

DbInterception.Add(new NLogCommandInterceptor());

Gli intercettori possono anche essere registrati a livello di dominio dell'app usando il meccanismo di configurazione basato sul codice DbConfiguration.

Esempio: Registrazione a NLog

Di seguito è riportato un esempio che usa IDbCommandInterceptor e NLog per:

Registrare un avviso per qualsiasi comando eseguito in modo non asincrono
Registrare un errore per qualsiasi comando che genera un'eccezione durante l'esecuzione

Ecco la classe che esegue la registrazione, che deve essere registrata come illustrato in precedenza:

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

Si noti che questo codice usa il contesto di intercettazione per individuare quando un comando viene eseguito in modo non asincrono e individuare quando si è verificato un errore durante l'esecuzione di un comando.

Condividi tramite