opentelemetry-sdk: add additional logs benchmarks & make additional perf improvements

.changelog/5784.added

@@ -0,0 +1 @@
+`opentelemetry-sdk`: add additional logs benchmarks and improve performance for disabled loggers

opentelemetry-api/src/opentelemetry/_logs/_internal/__init__.py

@@ -53,6 +53,21 @@ class LogRecord(ABC):
     pertinent to the event being logged.
     """
 
+    __slots__ = (
+        "timestamp",
+        "observed_timestamp",
+        "context",
+        "trace_id",
+        "span_id",
+        "trace_flags",
+        "severity_text",
+        "severity_number",
+        "body",
+        "attributes",
+        "event_name",
+        "exception",
+    )
+
     @overload
     def __init__(
         self,

opentelemetry-api/tests/logs/test_log_record.py

@@ -5,8 +5,21 @@
 from unittest.mock import patch
 
 from opentelemetry._logs import LogRecord
+from opentelemetry.trace import (
+    NonRecordingSpan,
+    SpanContext,
+    TraceFlags,
+    set_span_in_context,
+    use_span,
+)
 
 OBSERVED_TIMESTAMP = "OBSERVED_TIMESTAMP"
+SPAN_CONTEXT = SpanContext(
+    trace_id=0x000000000000000000000000DEADBEEF,
+    span_id=0x00000000DEADBEF0,
+    is_remote=False,
+    trace_flags=TraceFlags(TraceFlags.SAMPLED),
+)
 
 
 class TestLogRecord(unittest.TestCase):
@@ -19,3 +32,26 @@ def test_log_record_exception(self):
         exc = ValueError("boom")
         log_record = LogRecord(exception=exc)
         self.assertIs(log_record.exception, exc)
+
+    def test_log_record_span_context_fields_from_context(self):
+        log_record = LogRecord(context=set_span_in_context(NonRecordingSpan(SPAN_CONTEXT)))
+        self.assertEqual(log_record.trace_id, SPAN_CONTEXT.trace_id)
+        self.assertEqual(log_record.span_id, SPAN_CONTEXT.span_id)
+        self.assertEqual(log_record.trace_flags, SPAN_CONTEXT.trace_flags)
+
+    def test_log_record_explicit_span_context_fields(self):
+        span_context = SpanContext(
+            trace_id=SPAN_CONTEXT.trace_id,
+            span_id=SPAN_CONTEXT.span_id,
+            is_remote=False,
+            trace_flags=TraceFlags(TraceFlags.DEFAULT),
+        )
+        with use_span(NonRecordingSpan(span_context)):
+            log_record = LogRecord(
+                trace_id=1,
+                span_id=2,
+                trace_flags=TraceFlags(TraceFlags.SAMPLED),
+            )
+        self.assertEqual(log_record.trace_id, 1)
+        self.assertEqual(log_record.span_id, 2)
+        self.assertEqual(log_record.trace_flags, TraceFlags(TraceFlags.SAMPLED))

opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py

@@ -3,14 +3,15 @@
 
 import pytest
 
-from opentelemetry._logs import SeverityNumber
+from opentelemetry._logs import LogRecord, SeverityNumber
 from opentelemetry.sdk._logs import LoggerProvider
 from opentelemetry.sdk._logs.export import (
     BatchLogRecordProcessor,
     InMemoryLogRecordExporter,
     SimpleLogRecordProcessor,
 )
 from opentelemetry.sdk.resources import Resource
+from opentelemetry.sdk.trace import TracerProvider
 
 resource = Resource(
     {
@@ -70,3 +71,60 @@ def benchmark_get_logger():
         )
 
     benchmark(benchmark_get_logger)
+
+
+def test_emit_with_exception(benchmark):
+    try:
+        raise ValueError("benchmark exception")
+    except ValueError as exc:
+        exception = exc
+
+    def benchmark_emit():
+        simple_logger.emit(
+            severity_number=SeverityNumber.ERROR,
+            body="benchmark log message",
+            # pylint: disable-next=used-before-assignment
+            exception=exception,
+        )
+
+    benchmark(benchmark_emit)
+
+
+def test_emit_in_active_span(benchmark):
+    tracer = TracerProvider(resource=resource, shutdown_on_exit=False).get_tracer("benchmark_tracer")
+
+    def benchmark_emit():
+        simple_logger.emit(
+            severity_number=SeverityNumber.INFO,
+            body="benchmark log message",
+            event_name="test.event",
+        )
+
+    with tracer.start_as_current_span("benchmark_span"):
+        benchmark(benchmark_emit)
+
+
+@pytest.mark.parametrize("style", ["kwargs", "log_record"])
+def test_emit_log_record_vs_kwargs(benchmark, style):
+    benchmark.group = "emit-log-record-vs-kwargs"
+    attributes = {f"key{i}": f"value{i}" for i in range(5)}
+
+    def benchmark_emit_kwargs():
+        simple_logger.emit(
+            severity_number=SeverityNumber.INFO,
+            body="benchmark log message",
+            attributes=attributes,
+            event_name="test.event",
+        )
+
+    def benchmark_emit_log_record():
+        simple_logger.emit(
+            LogRecord(
+                severity_number=SeverityNumber.INFO,
+                body="benchmark log message",
+                attributes=attributes,
+                event_name="test.event",
+            )
+        )
+
+    benchmark(benchmark_emit_kwargs if style == "kwargs" else benchmark_emit_log_record)

opentelemetry-sdk/benchmarks/logs/test_benchmark_logs_enabled.py

@@ -0,0 +1,185 @@
+# Copyright The OpenTelemetry Authors
+# SPDX-License-Identifier: Apache-2.0
+
+import gc
+import os
+import tracemalloc
+from unittest import mock
+
+import pytest
+
+from opentelemetry._logs import LogRecord, SeverityNumber
+from opentelemetry._logs._internal import ProxyLogger
+from opentelemetry.sdk._logs import LoggerProvider, LogRecordProcessor
+from opentelemetry.sdk._logs._internal import _disable_logger_configurator
+from opentelemetry.sdk.environment_variables import OTEL_SDK_DISABLED
+
+
+class _SeverityFilteringProcessor(LogRecordProcessor):
+    """Processor that only accepts records at or above ``min_severity``.
+
+    ``on_emit`` does no export work so the benchmarks measure the SDK
+    overhead of creating and dispatching the record.
+    """
+
+    def __init__(self, min_severity):
+        self._min_severity = min_severity
+
+    def on_emit(self, log_record):
+        pass
+
+    def enabled(
+        self,
+        *,
+        context=None,
+        instrumentation_scope=None,
+        severity_number=None,
+        event_name=None,
+    ):
+        return severity_number is None or severity_number.value >= self._min_severity.value
+
+    def shutdown(self):
+        pass
+
+    def force_flush(self, timeout_millis=30000):
+        return True
+
+
+def _make_disabled_logger(mechanism):
+    """Returns a logger for which an INFO record is disabled."""
+    if mechanism == "logger_config":
+        provider = LoggerProvider(
+            shutdown_on_exit=False,
+            _logger_configurator=_disable_logger_configurator,
+        )
+        provider.add_log_record_processor(_SeverityFilteringProcessor(SeverityNumber.INFO))
+        return provider.get_logger("bench")
+    if mechanism == "processor_filter":
+        provider = LoggerProvider(shutdown_on_exit=False)
+        provider.add_log_record_processor(_SeverityFilteringProcessor(SeverityNumber.WARN))
+        return provider.get_logger("bench")
+    if mechanism == "no_processors":
+        return LoggerProvider(shutdown_on_exit=False).get_logger("bench")
+    if mechanism == "sdk_disabled":
+        with mock.patch.dict(os.environ, {OTEL_SDK_DISABLED: "true"}):
+            provider = LoggerProvider(shutdown_on_exit=False)
+        return provider.get_logger("bench")
+    if mechanism == "api_proxy_noop":
+        return ProxyLogger("bench")
+    raise ValueError(f"unknown mechanism: {mechanism}")
+
+
+def _emit_unguarded(logger, index):
+    logger.emit(
+        severity_number=SeverityNumber.INFO,
+        body=f"benchmark log message {index}",
+        attributes={
+            "http.request.method": "GET",
+            "http.route": "/users/{id}",
+            "http.response.status_code": 200,
+            "user.id": index,
+            "server.address": "example.com",
+        },
+        event_name="test.event",
+    )
+
+
+def _emit_guarded(logger, index):
+    if logger.enabled(severity_number=SeverityNumber.INFO, event_name="test.event"):
+        _emit_unguarded(logger, index)
+
+
+def _emit_log_record_unguarded(logger, index):
+    logger.emit(
+        LogRecord(
+            severity_number=SeverityNumber.INFO,
+            body=f"benchmark log message {index}",
+            attributes={
+                "http.request.method": "GET",
+                "http.route": "/users/{id}",
+                "http.response.status_code": 200,
+                "user.id": index,
+                "server.address": "example.com",
+            },
+            event_name="test.event",
+        )
+    )
+
+
+def _emit_log_record_guarded(logger, index):
+    if logger.enabled(severity_number=SeverityNumber.INFO, event_name="test.event"):
+        logger.emit(
+            LogRecord(
+                severity_number=SeverityNumber.INFO,
+                body=f"benchmark log message {index}",
+                attributes={
+                    "http.request.method": "GET",
+                    "http.route": "/users/{id}",
+                    "http.response.status_code": 200,
+                    "user.id": index,
+                    "server.address": "example.com",
+                },
+                event_name="test.event",
+            )
+        )
+
+
+_EMIT_FUNCTIONS = {
+    ("kwargs", False): _emit_unguarded,
+    ("kwargs", True): _emit_guarded,
+    ("log_record", False): _emit_log_record_unguarded,
+    ("log_record", True): _emit_log_record_guarded,
+}
+
+
+def _measure_allocations(benchmark, emit, logger):
+    for index in range(100):
+        emit(logger, index)
+
+    peaks = []
+    for index in range(200):
+        tracemalloc.start()
+        emit(logger, index)
+        _, peak = tracemalloc.get_traced_memory()
+        tracemalloc.stop()
+        peaks.append(peak)
+    benchmark.extra_info["mean_alloc_bytes"] = sum(peaks) / len(peaks)
+
+    # Measure gen-0 collections before/after emitting 10,000 log records
+    gc.collect()
+    collections_before = gc.get_stats()[0]["collections"]
+    for index in range(10_000):
+        emit(logger, index)
+    benchmark.extra_info["gc_gen0_collections_per_10k"] = gc.get_stats()[0]["collections"] - collections_before
+
+
+@pytest.mark.parametrize("guarded", [False, True], ids=["unguarded", "guarded"])
+@pytest.mark.parametrize("style", ["kwargs", "log_record"])
+@pytest.mark.parametrize(
+    "mechanism",
+    [
+        "logger_config",
+        "processor_filter",
+        "no_processors",
+        "sdk_disabled",
+        "api_proxy_noop",
+    ],
+)
+def test_disabled_emit(benchmark, mechanism, style, guarded):
+    benchmark.group = f"disabled-{mechanism}-{style}"
+    logger = _make_disabled_logger(mechanism)
+    emit = _EMIT_FUNCTIONS[(style, guarded)]
+    _measure_allocations(benchmark, emit, logger)
+
+    benchmark(emit, logger, 42)
+
+
+@pytest.mark.parametrize("guarded", [False, True], ids=["unguarded", "guarded"])
+def test_enabled_emit(benchmark, guarded):
+    benchmark.group = "enabled-guard-overhead"
+    provider = LoggerProvider(shutdown_on_exit=False)
+    provider.add_log_record_processor(_SeverityFilteringProcessor(SeverityNumber.INFO))
+    logger = provider.get_logger("bench")
+    emit = _emit_guarded if guarded else _emit_unguarded
+
+    benchmark(emit, logger, 42)