EF Core SQL Loglama: LogTo, TagWith, Interceptor ve Metrikler

Hangi mekanizma ne için?

Belgeler EF Core'da log üretmek, olaylara tepki vermek ve tanılama bilgisi almak için birden fazla mekanizma bulunduğunu ve birden fazlası işe yarasa bile iş için en uygun olanı seçmenin önemli olduğunu vurgular. Örneğin bir veritabanı interceptor'ı SQL loglamak için kullanılabilir, ama bu iş loglama için tasarlanmış mekanizmalarla daha iyi yapılır. Belgelerdeki hızlı başvuru tablosu şöyledir:

Simple logging: LogTo

Basit loglama, geliştirme ve hata ayıklama sırasında log almanın kolay yoludur; çok az yapılandırma ister ve ek bir NuGet paketi gerektirmez. Her tür uygulamada bağlamı yapılandırırken LogTo çağrılır; bu genellikle OnConfiguring içinde yapılır:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine);

LogTo çağrısı AddDbContext içinde ya da bağlam yapıcısına verilen bir DbContextOptions örneği oluşturulurken de yapılabilir. Belgelerin bir ipucuna göre AddDbContext kullanılsa ya da seçenekler yapıcıya verilse bile OnConfiguring yine çağrılır; bu da onu, bağlam nasıl oluşturulursa oluşturulsun uygulanacak yapılandırma için ideal bir yer yapar. Bağlam yapılandırmasının genel kuralları DbContext yapılandırma yazısında.

Logları nereye yönlendirebilirsiniz?

LogTo bir string alan bir Action<string> temsilcisi ister ve her log mesajı için bu temsilciyi çağırır; mesajla ne yapılacağı size kalmıştır. Konsol için Console.WriteLine kullanılır. Visual Studio gibi IDE'lerin Debug penceresine yazmak için Debug.WriteLine kullanılabilir; ancak Debug sınıfı release derlemelerinde derlemeden çıkarıldığı için burada lambda sözdizimi gerekir: LogTo(message => Debug.WriteLine(message)).

Dosyaya yazmak için bir StreamWriter oluşturup onun WriteLine metodunu verirsiniz. Belgeler, bağlam dispose edildiğinde yazıcının da dispose edilerek dosyanın düzgün kapatılmasını hatırlatır:

private readonly StreamWriter _logStream = new StreamWriter("mylog.txt", append: true);

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(_logStream.WriteLine);

public override void Dispose()
{
    base.Dispose();
    _logStream.Dispose();
}

public override async ValueTask DisposeAsync()
{
    await base.DisposeAsync();
    await _logStream.DisposeAsync();
}

Belgeler üretim uygulamalarında dosyaya loglama için bunun yerine Microsoft.Extensions.Logging kullanmayı düşünmenizi önerir.

Logları filtrelemek

Filtresiz basit loglama oldukça gürültülüdür: belgelere göre varsayılan olarak Debug seviyesi ve üzerindeki her mesaj yazılır. Her EF Core log mesajı LogLevel enum'undan bir seviyeye atanır. LogTo'ya daha yüksek bir minimum seviye vermek mesajları azaltır; Information vermek, veritabanı erişimi ve bazı yönetim mesajlarından oluşan asgari bir log kümesi üretir. SQL komutlarını görmek için çoğu zaman bu yeterlidir:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, LogLevel.Information);

Her mesajın ayrıca bir EventId değeri vardır. Bu kimliklere CoreEventId sınıfından, ilişkisel sağlayıcılara özgü mesajlar için RelationalEventId sınıfından erişilir; sağlayıcılar da SqlServerEventId gibi kendi sınıflarını sunabilir. LogTo yalnızca belirli olay kimliklerini loglayacak şekilde yapılandırılabilir; örneğin new[] { CoreEventId.ContextDisposed, CoreEventId.ContextInitialized } vererek yalnızca bağlamın başlatılma ve dispose edilme mesajlarını alırsınız.

Mesajlar ayrıca hiyerarşik adlandırılmış kategorilere atanır. Belgelerdeki kategorilerden bazıları şunlardır:

Yalnızca veritabanı etkileşimlerini loglamak için new[] { DbLoggerCategory.Database.Name } verilir. DbLoggerCategory sınıfı kategorileri string olarak sabit yazmak zorunda kalmamanız için hiyerarşik bir API sunar. Kategoriler hiyerarşik olduğu için Database kategorisi Database.Connection, Database.Command ve Database.Transaction alt kategorilerini de içerir.

Bu seçenekler yetmezse LogTo'ya özel bir filtre fonksiyonu verebilirsiniz. Belgelerdeki örnek, Information ve üzeri her mesajı ve ek olarak bağlantı açılıp kapanma mesajlarını loglar:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(
            Console.WriteLine,
            (eventId, logLevel) => logLevel >= LogLevel.Information
                                   || eventId == RelationalEventId.ConnectionOpened
                                   || eventId == RelationalEventId.ConnectionClosed);

Parametre değerleri ve hassas veri

Varsayılan olarak EF Core istisna mesajlarına ve loglara hiçbir veri değeri koymaz. Belgeler bunun nedenini açıkça yazar: bu veriler gizli olabilir ve yakalanmayan bir istisna üretimde bu değerleri ortaya çıkarabilir. Öte yandan hata ayıklarken veri değerlerini, özellikle anahtarları bilmek çok yararlıdır. Bunun için EnableSensitiveDataLogging çağrılır:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine)
        .EnableSensitiveDataLogging();

EF Core 10: satır içine gömülen sabitler de gizleniyor

EF Core parametre değerlerini varsayılan olarak loglamasa da bazı durumlarda parametreleri ayrı göndermek yerine SQL ifadesinin içine gömer (inline). Önceki sürümlerde bu durumda değerler loglarda görünüyordu. EF Core 10 bunu değiştirdi: satır içine gömülen bu değerler varsayılan olarak gizlenir ve yerlerine soru işareti yazılır. Belgelerdeki örnekte rol listesi EF.Constant(roles) ile bilerek sorguya gömülür; veritabanına gönderilen SQL'de roller açıkça yer alır, ancak EF Core 10'un logladığı SQL şöyledir (belgelerdeki örnek çıktı):

SELECT [b].[Id], [b].[Role]
FROM [Blogs] AS [b]
WHERE [b].[Role] IN (?, ?)

Normal parametrelerde olduğu gibi tam loglama EnableSensitiveDataLogging ile yeniden açılabilir. Bu değişiklik, hassas olabilecek değerlerin uygulama loglarına sızmasını önlemeye yöneliktir. EF Core 10'daki diğer güvenlik iyileştirmeleri EF Core 10 yenilikleri yazısında, ham SQL API'lerinde metin birleştirme uyarısı ise FromSql ve ham SQL yazısında anlatılıyor.

Ayrıntılı sorgu hataları

Performans nedeniyle EF Core, veritabanı sağlayıcısından her değer okuma çağrısını bir try-catch bloğuna sarmaz. Bu bazen teşhisi zor istisnalara yol açar; özellikle veritabanı, modelin izin vermediği bir yerde NULL döndürdüğünde. EnableDetailedErrors açıldığında EF Core bu try-catch bloklarını ekler ve daha ayrıntılı hatalar üretir. Varsayılan olarak kapalı olmasının nedeni performans olduğundan bu ayarı genellikle teşhis sırasında açmak mantıklıdır.

Belirli olayların davranışını değiştirmek: ConfigureWarnings

ConfigureWarnings API'si belirli bir olay gerçekleştiğinde ne olacağını değiştirmenizi sağlar. Üç seçenek vardır: olayın log seviyesini değiştirmek, olayı hiç loglamamak ya da olay gerçekleştiğinde istisna fırlatmak. Belgeler, yöntemin adının da bu son kullanımdan, yani uyarıları hataya çevirmekten geldiğini not eder.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .ConfigureWarnings(
            b => b.Log(
                (RelationalEventId.ConnectionOpened, LogLevel.Information),
                (RelationalEventId.ConnectionClosed, LogLevel.Information)))
        .LogTo(Console.WriteLine, LogLevel.Information);

Bu örnek, normalde Debug seviyesinde olan iki bağlantı olayını Information seviyesine yükselterek özel filtre örneğiyle aynı sonucu elde eder. İncelediğiniz ve anladığınız bir uyarıyı susturmak için b.Ignore(CoreEventId.DetachedLazyLoadingWarning), bir uyarıyı hataya çevirmek için b.Throw(RelationalEventId.MultipleCollectionIncludeWarning) gibi çağrılar kullanılır. İkinci örnekteki uyarı, adından da anlaşılacağı gibi birden fazla koleksiyon yükleyen sorgularla ilgilidir; split query belgelerine göre EF Core, sorgu bölme modu yapılandırılmamışken birden fazla koleksiyon yükleyen bir sorgu algıladığında uyarı üretir. Bunu geliştirme sırasında hataya çevirmek kartezyen patlama riskini erken fark ettirir; bu konu split query yazısında.

Log biçimi

LogTo varsayılan olarak mesajları birden fazla satıra yayar. İlk satır meta veriyi taşır: dört karakterlik seviye öneki, geçerli kültüre göre biçimlendirilmiş yerel zaman damgası, kopyalanıp ilgili sınıfta aranabilecek biçimde EventId ve ham kimlik değeri ve olay kategorisi. Belgelerdeki örnek çıktının ilk satırı şöyledir:

info: 10/6/2020 10:52:45.581 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']

DbContextLoggerOptions değerleriyle bu biçim özelleştirilebilir. DbContextLoggerOptions.DefaultWithUtcTime kültürden bağımsız UTC zaman damgaları verir; DbContextLoggerOptions.SingleLine her mesajı tek satırda yazar; UtcTime ile SingleLine birleşimi ise meta veriyi zaman damgasına kadar azaltır. Sunucuda logları satır bazlı araçlarla aradığınızda tek satırlık biçim işinizi kolaylaştırır. Biçimlendirme üzerinde daha fazla denetim istiyorsanız belgeler yine Microsoft.Extensions.Logging önerir.

Üretim için: Microsoft.Extensions.Logging

Microsoft.Extensions.Logging, pek çok yaygın loglama sistemi için eklenti sağlayıcıları olan genişletilebilir bir loglama mekanizmasıdır ve EF Core onunla tamamen bütünleşir. ASP.NET Core uygulamalarında varsayılan olarak kullanılır: AddDbContext veya AddDbContextPool çağırmak, EF Core'un ASP.NET Core'un olağan mekanizmasıyla yapılandırılmış loglamayı otomatik kullanmasını sağlar. Diğer uygulama türleri aynı bağımlılık enjeksiyonu kalıplarını Generic Host ile kullanabilir.

Bağımlılık enjeksiyonu kullanmayan uygulamalarda bir LoggerFactory oluşturmanız gerekir. Belgelere göre bu fabrika statik veya global bir örnek olarak saklanmalı ve her bağlam oluşturulduğunda aynı örnek kullanılmalıdır; yaygın yol onu bağlam üzerinde statik bir özellik olarak tutmaktır:

public static readonly ILoggerFactory MyLoggerFactory
    = LoggerFactory.Create(builder => { builder.AddConsole(); });

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .UseLoggerFactory(MyLoggerFactory)
        .UseSqlServer(@"Server=(localdb)\mssqllocaldb;Database=EFLogging;Trusted_Connection=True;ConnectRetryCount=0");

Bu yolda filtreleme ve diğer yapılandırma .NET loglamasının kendi kurallarıyla yapılır; yukarıdaki kategori adları burada da filtre anahtarı olarak kullanılabilir. EnableSensitiveDataLogging, EnableDetailedErrors ve ConfigureWarnings aynı şekilde çalışır. ASP.NET Core tarafındaki loglama yapılandırması ayrı bir konudur.

Sorgu etiketleri: TagWith

Komut loglarının bir sorunu, SQL komutlarını kaynak LINQ sorgularıyla eşleştirmenin bazen zor olmasıdır. TagWith sorguya kısa, tanımlayıcı bir yorum ekler ve bu yorum üretilen SQL'in başına girer:

var myLocation = new Point(1, 2);
var nearestPeople = await (from f in context.People.TagWith("This is my spatial query!")
                     orderby f.Location.Distance(myLocation) descending
                     select f).Take(5).ToListAsync();

Belgelerdeki örnek çıktıda SQL -- This is my spatial query! satırıyla başlar. Etiketler birikimlidir: aynı sorguda birden fazla TagWith çağırabilirsiniz ve her biri ayrı bir yorum satırı olur; çok satırlı metinler de etiket olarak kullanılabilir. TagWithCallSite ise sorguyu, tanımlandığı kaynak dosyanın adı ve satır numarasıyla otomatik etiketler. Belgelerin not ettiği sınırlama şudur: etiketler parametreleştirilemez, EF Core onları her zaman SQL'e eklenen metin sabitleri olarak ele alır ve etiketi parametre olarak alan derlenmiş sorgulara izin verilmez. Uygulamanın önemli sorgularını bu şekilde etiketlemek komut loglarını çok daha okunur yapar.

Interceptor'lar: işlemleri yakalamak ve değiştirmek

Interceptor'lar EF Core işlemlerini yakalamanıza, değiştirmenize ve hatta bastırmanıza olanak tanır. Bu, komut çalıştırma gibi düşük seviyeli veritabanı işlemlerini de SaveChanges çağrıları gibi üst seviyeli işlemleri de kapsar. Loglama ve tanılamadan farkı, yakalanan işlemi değiştirebilmeleridir; yalnızca log almak istiyorsanız belgeler basit loglamayı veya Microsoft.Extensions.Logging'i önerir.

Interceptor'lar bağlam yapılandırılırken AddInterceptors ile kaydedilir. Çoğu interceptor durum taşımadığı için tek bir örnek bütün bağlam örneklerinde kullanılabilir. Tabloda singleton olarak işaretlenen interceptor'lar için bu bir öneri değil zorunluluktur: bunlar EF Core'un iç servis sağlayıcısında singleton olarak kaydedilir ve her farklı örnek yeni bir iç servis sağlayıcısının oluşturulmasına yol açar. Belgelere göre AddDbContext içinde her seferinde new ile yeni bir örnek vermek sonunda bir ManyServiceProvidersCreatedWarning uyarısını tetikler ve performansı düşürür. Aynı örneği yeniden kullanın, örneğin statik bir alanda tutun; singleton interceptor'ların iş parçacığı güvenli olması ve genellikle değişken durum tutmaması gerekir.

Örnek: etiketli sorgulara SQL ipucu eklemek

Belgelerdeki komut interceptor'ı örneği, etiketlerle interceptor'ları birleştirir. Değiştirilecek sorgu TagWith("Use hint: robust plan") ile etiketlenir; etiket her zaman komut metninin ilk satırında yorum olarak yer aldığı için interceptor onu güvenle tanıyabilir. SQL'i ayrıştırmaya çalışmak ise kırılgan bir yöntemdir.

public class TaggedQueryCommandInterceptor : DbCommandInterceptor
{
    public override InterceptionResult<DbDataReader> ReaderExecuting(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<DbDataReader> result)
    {
        ManipulateCommand(command);

        return result;
    }

    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<DbDataReader> result,
        CancellationToken cancellationToken = default)
    {
        ManipulateCommand(command);

        return new ValueTask<InterceptionResult<DbDataReader>>(result);
    }

    private static void ManipulateCommand(DbCommand command)
    {
        if (command.CommandText.StartsWith("-- Use hint: robust plan", StringComparison.Ordinal))
        {
            command.CommandText += " OPTION (ROBUST PLAN)";
        }
    }
}

Bu örnekte üç noktaya dikkat edin. Interceptor, arayüzdeki her metodu yazmak zorunda kalmamak için boş varsayılan uygulamalar içeren DbCommandInterceptor temel sınıfından türetilir. Hem senkron hem async metotlar uygulanır, böylece ipucu iki tür sorguya da eklenir. Kullanılan Executing metotları SQL veritabanına gönderilmeden önce, Executed metotları ise veritabanı çağrısı döndükten sonra çağrılır. Belgelerin örnek çıktısında etiketli sorgunun sonuna OPTION (ROBUST PLAN) eklenir, etiketsiz sorgular değişmeden gider. Veritabanı interceptor'larının yalnızca ilişkisel sağlayıcılarda kullanılabildiğini de unutmayın.

CommandEventData üzerindeki CommandSource özelliği, komutun EF Core'un hangi bölümünden geldiğini gösterir; örneğin yalnızca CommandSource.SaveChanges kaynaklı komutlarla ilgilenen bir interceptor yazabilirsiniz. SaveChanges düzeyinde yakalama için ISaveChangesInterceptor ve SaveChangesInterceptor temel sınıfı vardır; ancak belgeler pek çok durumda SaveChanges metodunu ezmenin ya da bağlamın .NET olaylarını kullanmanın daha kolay olabileceğini hatırlatır.

.NET olayları ve diagnostic listener'lar

EF Core, belirli şeyler olduğunda geri çağrı işlevi gören .NET olayları da yayımlar. Olaylar interceptor'lardan daha basittir ve daha esnek kayıt imkânı sunar: bağlam örneği başına, herhangi bir anda kaydedilebilirler. Ancak yalnızca senkrondurlar, yani bloke etmeyen async G/Ç yapamazlar. Belgelerde listelenen olaylar DbContext.SavingChanges, DbContext.SavedChanges, DbContext.SaveChangesFailed, ChangeTracker.Tracked ve ChangeTracker.StateChanged olaylarıdır. Belgelerdeki örnek, Tracked ve StateChanged olaylarıyla entity'lere eklenme, silinme ve güncellenme zaman damgası basar.

Diagnostic listener'lar ise mevcut .NET sürecinde gerçekleşen her EF Core olayını dinlemenizi sağlar ve DiagnosticListener sınıfı üzerinden çalışan, .NET genelindeki ortak bir mekanizmanın parçasıdır. Belgelere göre tek bir bağlam örneğinden olay almak için uygun değildir; aynı olaylara bağlam başına kayıtla interceptor'lar üzerinden erişilir. Loglama için de tasarlanmamıştır. Uygulama genelinde tanılama verisi toplamak istediğinizde düşünülecek araçtır.

Metrikler

EF Core sürekli sayısal metrikler yayımlar ve bunlar programın sağlığı hakkında iyi bir gösterge sağlar: gerçek zamanlı veritabanı yükünü izlemek, performansı düşüren kodlama alışkanlıklarını ortaya çıkarmak ve anormal davranışları yakalamak. Metrikler standart System.Diagnostics.Metrics API'si üzerinden Microsoft.EntityFrameworkCore adlı meter ile raporlanır; belgelere göre bu özellik EF Core 9.0 ile geldi. Listelenen metrikler etkin bağlam sayısı (active_dbcontexts), çalıştırılan sorgular, kaydedilen değişiklikler, derlenmiş sorgu önbelleği isabet ve ıskaları, execution strategy işlem hataları ve iyimser eşzamanlılık hatalarıdır.

Bu metriklerin ikisi sunucu tarafında özellikle değerlidir. Etkin bağlam sayısı sürekli artıyorsa bağlamlar düzgün dispose edilmiyor olabilir; context pooling etkinse bu sayı havuzdaki kullanılmayan örnekleri de içerir. Sorgu önbelleği isabet oranı ise normal bir uygulamada ısınma döneminden sonra yüzde 100'e oturmalıdır; sürekli bunun altında kalıyorsa tekrar tekrar derlenen dinamik sorgular olabilir. Belgeler eski sürümler için dotnet-counters aracıyla izlenebilen event counter'ları da anlatır. Bu bulguların nasıl yorumlanacağı EF Core performans ve DbContext pooling ve compiled query yazılarında.

Sık yapılan hatalar

• Üretimde EnableSensitiveDataLogging bırakmak: Parametre değerleri loglara düşer. Yalnızca geliştirme ortamında açın.
• Filtresiz LogTo ile çalışmak: Varsayılan seviye Debug olduğu için loglar çok gürültülüdür; SQL için LogLevel.Information ya da DbLoggerCategory.Database.Command kategorisi çoğu zaman yeterlidir.
• Filtrelemeyi temsilcinin içinde yapmak: Mesaj yine oluşturulur; LogTo filtre parametrelerini kullanın.
• Singleton interceptor'ı her seferinde new ile vermek: Yeni iç servis sağlayıcıları oluşur ve performans düşer. Tek bir örneği yeniden kullanın.
• Loglama için interceptor veya diagnostic listener kullanmak: Bu mekanizmalar loglama için tasarlanmamıştır; amaç SQL görmekse LogTo veya Microsoft.Extensions.Logging kullanın.
• Komut loglamasını üretimde sürekli açık tutmak: Uygulamayı yavaşlatır ve diski doldurabilir; kısa süreli veya üretim öncesi ortamda kullanın.

Sık Sorulan Sorular

EF Core'un ürettiği SQL'i nasıl görürüm?

Geliştirme sırasında optionsBuilder.LogTo(Console.WriteLine, LogLevel.Information) en kısa yoldur. ASP.NET Core uygulamasında AddDbContext ile kaydedilen bağlam, uygulamanın loglama yapılandırmasını kullanır; Microsoft.EntityFrameworkCore.Database.Command kategorisinin seviyesini ayarlamanız yeterlidir.

Loglarda parametre değerleri neden görünmüyor?

Güvenlik nedeniyle EF Core varsayılan olarak veri değerlerini loglamaz; EF Core 10 ile satır içine gömülen sabitler de soru işaretiyle gizlenir. Geliştirme sırasında görmek için EnableSensitiveDataLogging açın.

TagWith performansı etkiler mi?

Etiket SQL'e bir yorum olarak eklenen bir metin sabitidir. Belgelerin belirttiği sınırlama, etiketlerin parametreleştirilememesi ve etiketi parametre olarak alan derlenmiş sorgulara izin verilmemesidir; sabit bir etiket metni kullanın.

Interceptor ile olay arasında nasıl seçim yaparım?

Yalnızca bir şey olduğunda tepki vermek istiyorsanız ve senkron çalışmak yeterliyse olaylar daha basittir. İşlemi değiştirmeniz, bastırmanız ya da async G/Ç yapmanız gerekiyorsa interceptor kullanın.

Marka adları sahiplerine aittir. Bu yazı bağımsız bir teknik rehberdir; adı geçen kuruluşlarla bayilik veya ortaklık ilişkisi bulunduğu anlamına gelmez.

İlgili içerikler: EF Core öğrenme rehberi · EF Core performans · Change tracker ve DebugView · DbContext yapılandırma · FromSql ve ham SQL