OpenTelemetryLoggerProvider is now unaffected by changes to OpenTelemetryLoggerOptions after the LoggerFactory is built.

[TimothyMothra]

Fixes #2902.

Changes

• OpenTelemetryLoggerProvider will now copy the values from OpenTelemetryLoggerOptions. This prevents changes to the Provider after being initialized.
• Updated tests. Some tests that were testing both true/false values needed to be broken up into two tests.
• Added new tests to verify that changing Options after initializing the Provider don't affect the Provider.

Please provide a brief description of the changes here.

For significant contributions please make sure you have completed the following items:

• Appropriate CHANGELOG.md updated for non-trivial changes
• Design discussion issue #
• Changes in public API reviewed

Options

I investigated 3 options.

• Option 1,
  ctor of LoggerProvider copies Options to local fields.
  Logger.Log references this.provider.<local fields>.
  This introduces an ldfld.

• Option 2,
  ctor of LoggerProvider copies Options to local fields.
  ctor of Logger copies Options to local fields.
  Logger.Log references this.<local fields>.

• Option 3,
  ctor of LoggerProvider copies Options to local fields.
  Logger.Log first creates a local var for the provider var provider = this.provider then references all other properties/fields from the local var provider.<local fields>.
  This was done in an attempt to mitigate the ldfld.

Benchmarks

Test

For this test, I initialized the Provider and Logger.
For the benchmark, I invoke the hotpath (Logger.Log) which accesses the Options.

(ran benchmarks twice) 

|              Method |     Mean |    Error |   StdDev |  Gen 0 | Allocated |
|-------------------- |---------:|---------:|---------:|-------:|----------:|
|           Unchanged | 47.29 ns | 0.654 ns | 0.580 ns | 0.0102 |      64 B |
|       Option1_ldfld | 48.05 ns | 0.452 ns | 0.401 ns | 0.0102 |      64 B |
|   Option2_localCopy | 48.77 ns | 0.311 ns | 0.291 ns | 0.0102 |      64 B |
| Option3_varProvider | 46.99 ns | 0.411 ns | 0.385 ns | 0.0102 |      64 B |


|              Method |     Mean |    Error |   StdDev |  Gen 0 | Allocated |
|-------------------- |---------:|---------:|---------:|-------:|----------:|
|           Unchanged | 45.71 ns | 0.504 ns | 0.472 ns | 0.0102 |      64 B |
|       Option1_ldfld | 47.41 ns | 0.529 ns | 0.495 ns | 0.0102 |      64 B |
|   Option2_localCopy | 45.70 ns | 0.443 ns | 0.393 ns | 0.0102 |      64 B |
| Option3_varProvider | 46.18 ns | 0.567 ns | 0.531 ns | 0.0102 |      64 B |

The results are inconclusive, I'm seeing a negligible difference between implementations.

Benchmark code

  [MemoryDiagnoser]
  public class LogBenchmarks2
  {
      private readonly ILogger loggerUnchanged;
      private readonly ILogger loggerLdfld;
      private readonly ILogger loggerLocalCopy;
      private readonly ILogger loggerVarProvider;

      public LogBenchmarks2()
      {
          var options = new OpenTelemetryLoggerOptions
          {
              IncludeFormattedMessage = true,
              IncludeScopes = true,
              ParseStateValues = true,
          };

          var provider = new OpenTelemetryLoggerProvider(options);
          this.loggerUnchanged = new OpenTelemetryLogger("categoryName", provider);

          var provider2 = new OpenTelemetryLoggerProvider2(options);
          this.loggerLdfld = new OpenTelemetryLogger_LDFLD("categoryName", provider2);
          this.loggerLocalCopy = new OpenTelemetryLogger_LocalCopy("categoryName", provider2);
          this.loggerVarProvider = new OpenTelemetryLogger_VarProvider("categoryName", provider2);
      }

      [Benchmark]
      public void Unchanged()
      {
          this.loggerUnchanged.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
      }

      [Benchmark]
      public void Option1_ldfld()
      {
          this.loggerLdfld.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
      }

      [Benchmark]
      public void Option2_localCopy()
      {
          this.loggerLocalCopy.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
      }

      [Benchmark]
      public void Option3_varProvider()
      {
          this.loggerVarProvider.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
      }
  }

Option 1:

internal class OpenTelemetryLogger_LDFLD : ILogger

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
    if (!this.IsEnabled(logLevel)
        || Sdk.SuppressInstrumentation)
    {
        return;
    }

    var processor = this.provider.Processor;
    if (processor != null)
    {
        var record = new LogRecord(
            this.provider.IncludeScopes ? this.ScopeProvider : null,
            DateTime.UtcNow,
            this.categoryName,
            logLevel,
            eventId,
            this.provider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null,
            this.provider.ParseStateValues ? null : state,
            exception,
            this.provider.ParseStateValues ? this.ParseState(state) : null);

        processor.OnEnd(record);

        record.ScopeProvider = null;
    }
}

Option 2:

internal class OpenTelemetryLogger_LocalCopy : ILogger

internal OpenTelemetryLogger_LocalCopy(string categoryName, OpenTelemetryLoggerProvider2 provider)
{
    Guard.ThrowIfNull(categoryName);
    Guard.ThrowIfNull(provider);

    this.categoryName = categoryName;
    this.provider = provider;

    this.IncludeScopes = provider.IncludeScopes;
    this.IncludeFormattedMessage = provider.IncludeFormattedMessage;
    this.ParseStateValues = provider.ParseStateValues;
}

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
    if (!this.IsEnabled(logLevel)
        || Sdk.SuppressInstrumentation)
    {
        return;
    }

    var processor = this.provider.Processor;
    if (processor != null)
    {
        var record = new LogRecord(
            this.IncludeScopes ? this.ScopeProvider : null,
            DateTime.UtcNow,
            this.categoryName,
            logLevel,
            eventId,
            this.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null,
            this.ParseStateValues ? null : state,
            exception,
            this.ParseStateValues ? this.ParseState(state) : null);

        processor.OnEnd(record);

        record.ScopeProvider = null;
    }
}

Option 3

internal class OpenTelemetryLogger_VarProvider : ILogger

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
    if (!this.IsEnabled(logLevel)
        || Sdk.SuppressInstrumentation)
    {
        return;
    }

    var provider = this.provider;
    var processor = provider.Processor;
    if (processor != null)
    {
        var record = new LogRecord(
            provider.IncludeScopes ? this.ScopeProvider : null,
            DateTime.UtcNow,
            this.categoryName,
            logLevel,
            eventId,
            provider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null,
            provider.ParseStateValues ? null : state,
            exception,
            provider.ParseStateValues ? this.ParseState(state) : null);

        processor.OnEnd(record);

        record.ScopeProvider = null;
    }
}

IL

The IL code is a bit more revealing.
Option 1 introduces additional ldfld when accessing every field.

Original, Option 2, and Option 3 are nearly identical.

ORIGINAL
	IL_002d: callvirt instance bool OpenTelemetry.Logs.OpenTelemetryLoggerOptions::get_IncludeScopes()

OPTION 1: LDFLD
	IL_0024: ldfld class OpenTelemetry.Logs.OpenTelemetryLoggerProvider2 OpenTelemetry.Logs.OpenTelemetryLogger_LDFLD::provider
	IL_0029: ldfld bool OpenTelemetry.Logs.OpenTelemetryLoggerProvider2::IncludeScopes

OPTION 2: LOCAL COPY
	IL_0021: ldfld bool OpenTelemetry.Logs.OpenTelemetryLogger_LocalCopy::IncludeScopes

OPTION 3: VAR PROVIDER
	IL_0023: ldfld bool OpenTelemetry.Logs.OpenTelemetryLoggerProvider2::IncludeScopes

Considering this, I'm recommending Option 3.

[codecov]

Codecov Report

❗ No coverage uploaded for pull request base (main@add7eee). Click here to learn what that means.
The diff coverage is 100.00%.

@@           Coverage Diff           @@
##             main    #3055   +/-   ##
=======================================
  Coverage        ?   84.78%           
=======================================
  Files           ?      259           
  Lines           ?     9187           
  Branches        ?        0           
=======================================
  Hits            ?     7789           
  Misses          ?     1398           
  Partials        ?        0           

Impacted Files	Coverage Δ
src/OpenTelemetry/Logs/OpenTelemetryLogger.cs	94.44% <100.00%> (ø)
.../OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs	82.35% <100.00%> (ø)

[cijothomas]

LGTM once a changelog entry is added

[reyang]

Perf concern on hotpath https://github.com/open-telemetry/opentelemetry-dotnet/pull/3055/files#r830227799

#3055 (comment)

[reyang]

LGTM.

[cijothomas]

The loggerfactory was disposed in IDisposable impln. It does not look like factory is disposed in the new tests.

[TimothyMothra]

changed the helper method to return the factory. calling method is responsible for using using

[cijothomas]

Code changes looks good (Thanks for addressing the perf issues !)
The test changes does not seem to be disposing the factory. This needs to be fixed before we merge.

[cijothomas]

why do we have to have the helper method create a ILogger? It can just do what it claims to do (from the name) - initialize and return a loggerfactory, configured as per the configure action given to it.

[TimothyMothra]

This was meant to simplify the individual tests by removing a dozen lines of identical boilerplate code.
I can move some or all of this into every test, but I don't think that improves the value of the tests themselves.

[cijothomas]

The name of the helper method did not indicate its intended purpose. The latest commit looks better.
(if we want to achieve less duplication in tests, we can do that, with aptly named helper. but this looks good for me now)