تغییرات Logging در ASP.NET Core 6x

اندازه‌ی قلم متن

تخمین مدت زمان مطالعه‌ی مطلب: شش دقیقه

فرض کنید با استفاده از روش متداول زیر، کار ثبت یک واقعه را انجام داده‌اید:

public class TestController
{
    private readonly ILogger<TestController> _logger;
    public TestController(ILogger<TestController> logger)
    {
        _logger = logger;
    }

   [HttpGet("/")]
    public string Get()
    {
        _logger.LogInformation("hello world");
          return "Hello world!";
    }
}

در یک برنامه‌ی متداول ASP.NET Core، زیرساخت کار با ILogger از پیش تنظیم شده‌است. برای کار با آن فقط کافی است به نمونه‌های ILogger و یا <ILogger<T از طریق سیستم تزریق وابستگی‌ها دسترسی یافت و سپس متدهای الحاقی آن‌را مانند LogInformation فراخوانی کرد.

اگر یک چنین برنامه‌ای را به دات نت 6 ارتقاء دهید، با پیام اخطار زیر مواجه خواهید شد:

CA1848: For improved performance, use the LoggerMessage delegates instead of calling LogInformation

به صورت خلاصه، تمام متدهای پیشین LogInformation، LogDebug و امثال آن در دات نت 6 منسوخ شده درنظر گرفته می‌شوند! دلیل آن‌را در ادامه بررسی خواهیم کرد.

استفاده‌ی گسترده از source generators در دات نت 6

source generators، امکان مداخله در عملیات کامپایل برنامه را میسر کرده و امکان تولید کدهای پویایی را در زمان کامپایل، فراهم می‌کنند. هرچند این قابلیت به همراه دات نت 5 ارائه شدند، اما تا زمان دات نت 6 استفاده‌ی گسترده‌ای از آن در خود دات نت صورت نگرفت. موارد زیر، تغییراتی است که بر اساس source generators در دات نت 6 رخ داده‌اند:
- source generators مخصوص ILogger (موضوع این بحث؛ یعنی LoggerMessage source generator)
- source generators مخصوص System.Text.Json تا سربار تبدیل به JSON و یا برعکس کمتر شود.
- بازنویسی مجدد پروسه‌ی کامپایل Blazor/Razor بر اساس source generators، بجای روش دو مرحله‌ای قبلی که امکان Hot Reload را فراهم کرده‌است.

نوشتن یک source generator هرچند ساده نیست، اما چون نیاز به reflection را به حداقل می‌رساند، می‌تواند تغییرات کارآیی بسیار مثبتی را به همراه داشته باشد.

توصیه به استفاده از LoggerMessage.Define در دات نت 6

ILogger به همراه قابلیت‌هایی مانند structural logging نیز هست که امکان فرمت بهتر پیام‌های ثبت شده را میسر می‌کند تا توسط برنامه‌های جانبی که قرار است این لاگ‌ها را پردازش کنند، به سادگی قابل خواندن باشند. برای مثال رکورد زیر را در نظر بگیرید:

public record Person (int Id, string Name);

به همراه نمونه‌ای از آن:

var person = new Person(123, "Test");

خروجی لاگ زیر در این حالت:

_logger.LogInformation("hello to {Person}", person);

به صورت زیر خواهد بود:

info: TestController[0]
hello world to Person { Id = 123, Name = Test }

دقت کنید که رشته‌ی ارسالی به LogInformation به همراه $ نیست. یعنی از string interpolation استفاده نشده‌است و نام پارامتر تعریف شده (placeholder name) با حروف بزرگ شروع شده‌است.

اگر در اینجا مانند مثال زیر از string interpolation استفاده شود:

_logger.LogInformation($"hello world to {person}"); // Using interpolation instead of structured logging

هرچند کار با آن ساده‌تر است از string.Format، اما برای عملیات ثبت وقایع با کارآیی بالا توصیه نمی‌شود؛ به این دلایل:
- ویژگی «لاگ‌های ساختار یافته» را از دست می‌دهیم و دیگر توسط نرم افزارهای ثالث لاگ خوان، به سادگی پردازش نخواهند شد.
- ویژگی «قالب ثابت» پیام را نیز از دست خواهیم داد که باز هم یافتن پیام‌های مشابه را در بین انبوهی از لاگ‌های رسیده مشکل می‌کند.
- کار serialization شیء ارسالی به آن، پیش از عملیات ثبت وقایع رخ می‌دهد. اما ممکن است سطح لاگ سیستم در این حد نباشد و اصلا این پیام لاگ نشود. در این حالت یک کار اضافی صورت گرفته و بر روی کارآیی برنامه تاثیر منفی خواهد گذاشت.

برای جلوگیری از serialization و همچنین تخصیص حافظه‌ی اضافی و مشکلات عدم ساختار یافته بودن لاگ‌ها، توصیه شده‌است که ابتدا سطح لاگ مدنظر بررسی شود و همچنین از string interpolation استفاده نشود:

if (_logger.IsEnabled(LogLevel.Information))
{
   _logger.LogInformation("hello world to {Person}", person);
}

البته مشکل این روش، تکرار این if/else‌ها در تمام برنامه‌است و همچنین باید دقت داشت که LogLevel انتخابی، با متد لاگ، هماهنگی دارد.
مشکل دیگر لاگ‌های ساختار یافته، امکان فراموش کردن یکی از پارامترها است که با یک خطای زمان اجرا گوشزد خواهد شد؛ مانند مثال زیر:

_logger.LogInformation("hello world to {Person} because {Reason}", person);

اکنون در دات نت 6 با پیام اخطار CA1848 که در ابتدای بحث مشاهده کردید، توصیه می‌کنند که اگر قالب نهایی خاصی را مدنظر دارید، آن‌را توسط متد LoggerMessage.Define دقیقا مشخص کنید:

private static readonly Action<ILogger, Person, Exception?> _logHelloWorld =
    LoggerMessage.Define<Person>(
        logLevel: LogLevel.Information,
        eventId: 0,
        formatString: "hello world to {Person}");

در این روش جدید باید یک Action را برای لاگ کردن پیام‌ها تهیه کرد که از همان ابتدا LogLevel آن مشخص است (و نیازی به بررسی مجزا ندارد؛ یعنی خودش logger.IsEnabled را فراخوانی می‌کند) و همچنین از روش لاگ ساختار یافته استفاده می‌کند. مزیت این روش کش شدن قالب لاگ، در بار اول فراخوانی آن است ( برخلاف متدهای الحاقی مانند LogInformation که هربار باید این قالب‌ها را پردازش کنند) و همچنین در اینجا دیگر خبری از boxing و تبدیل نوع پارامترها نیست.

اکنون روش فراخوانی این Action با کارآیی بالا به صورت زیر است:

[HttpGet("/")]
public string Get()
{
    var person = new Person(123, "Test");
    _logHelloWorld(_logger, person, null);
      return "Hello world!";
}

همانطور که مشاهده می‌کنید اینبار دیگر حتی امکان فراموش کردن پارامتری وجود ندارد (مشکلی که می‌تواند با LogInformation متداول رخ دهد).

معرفی [LoggerMessage] source generator در دات نت 6

هرچند LoggerMessage.Define، مزایای قابل توجهی مانند کش شدن قالب لاگ، عدم نیاز به بررسی ضرورت لاگ شدن پیام و ارسال تعداد پارامترهای صحیح را به همراه دارد، اما ... کار کردن با آن مشکل است و برای کار با آن باید کدهای زیادی را نوشت. به همین جهت با استفاده از قابلیت source generators، امکان تولید خودکار این نوع کدها در زمان کامپایل برنامه پیش‌بینی شده‌است:

public partial class TestController
{
   [LoggerMessage(0, LogLevel.Information, "hello world to {Person}")]
   partial void LogHelloWorld(Person person);
}

این قطعه کد، LoggerMessage.Define را به صورت خودکار برای ما تولید می‌کند. برای اینکار باید یک متد partial را تهیه کرد و سپس آن‌را به ویژگی جدید LoggerMessage مزین کرد. پس از آن source generator، مابقی کارها را در زمان کامپایل برنامه انجام می‌دهد.
ویژگی partial method، امکان تعریف یک متد را در یک فایل و سپس ارائه‌ی پیاده سازی آن‌را در فایلی دیگر میسر می‌کند که البته در اینجا آن فایل دیگر، توسط source generator تولید می‌شود.
باید دقت داشت که در اینجا TestController را نیز باید به صورت partial تعریف کرد تا آن نیز قابلیت بسط در چند فایل را پیدا کند. همچنین متد فوق را به صورت static partial void نیز می‌توان نوشت.

یکی از مزایای کار با source generator که خودش در اصل یک آنالایزر هم هست، بررسی تعداد پارامترهای ارسالی و تعریف شده‌است:

[LoggerMessage(0, LogLevel.Information, "hello world to {Person} with a {Reason}")]
partial void LogHelloWorld(Person person);

برای مثال در اینجا متد LogHelloWorld یک پارامتر دارد اما LoggerMessage آن به همراه دو پارامتر تعریف شده‌است که این مشکل در زمان کامپایل تشخیص داده شده و گوشزد می‌شود (برخلاف روش‌های پیشین که در زمان اجرا این نوع مشکلات نمایان می‌شدند).

در این روش، امکان ذکر پارامتر اختیاری LogLevel هم وجود دارد؛ اگر نیاز است مقدار آن به صورت پویا تغییر کند:

[LoggerMessage(Message = "hello world to {Person}")]
partial void LogHelloWorld(LogLevel logLevel, Person person);

تغییرات Logging در ASP.NET Core 6x

مطالب مشابه