From 1d425394d73646dc4017ec87c829aabbe5814c3a Mon Sep 17 00:00:00 2001 From: Tom Monk Date: Sat, 23 Mar 2024 16:52:08 -0700 Subject: [PATCH 01/11] Fix issue 2485 enable caching for get_logger calls Cache one Logger object per Python logger name in LoggingHandler --- .../sdk/_logs/_internal/__init__.py | 16 +++++----- opentelemetry-sdk/tests/logs/test_export.py | 32 +++++++++++++++++++ 2 files changed, 40 insertions(+), 8 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 245db0ad1d..fe35b416bf 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -20,6 +20,7 @@ import threading import traceback import warnings +from functools import lru_cache from os import environ from time import time_ns from typing import Any, Callable, Optional, Tuple, Union # noqa @@ -471,9 +472,6 @@ def __init__( ) -> None: super().__init__(level=level) self._logger_provider = logger_provider or get_logger_provider() - self._logger = get_logger( - __name__, logger_provider=self._logger_provider - ) @staticmethod def _get_attributes(record: logging.LogRecord) -> Attributes: @@ -558,6 +556,7 @@ def _translate(self, record: logging.LogRecord) -> LogRecord: "WARN" if record.levelname == "WARNING" else record.levelname ) + logger = get_logger(record.name, logger_provider=self._logger_provider) return LogRecord( timestamp=timestamp, observed_timestamp=observered_timestamp, @@ -567,7 +566,7 @@ def _translate(self, record: logging.LogRecord) -> LogRecord: severity_text=level_name, severity_number=severity_number, body=body, - resource=self._logger.resource, + resource=logger.resource, attributes=attributes, ) @@ -577,15 +576,15 @@ def emit(self, record: logging.LogRecord) -> None: The record is translated to OTel format, and then sent across the pipeline. """ - if not isinstance(self._logger, NoOpLogger): - self._logger.emit(self._translate(record)) + logger = get_logger(record.name, logger_provider=self._logger_provider) + if not isinstance(logger, NoOpLogger): + logger.emit(self._translate(record)) def flush(self) -> None: """ Flushes the logging output. Skip flushing if logger is NoOp. """ - if not isinstance(self._logger, NoOpLogger): - self._logger_provider.force_flush() + self._logger_provider.force_flush() class Logger(APILogger): @@ -647,6 +646,7 @@ def __init__( def resource(self): return self._resource + @lru_cache(maxsize=None) def get_logger( self, name: str, diff --git a/opentelemetry-sdk/tests/logs/test_export.py b/opentelemetry-sdk/tests/logs/test_export.py index 0998ecfa5d..ce31d3991f 100644 --- a/opentelemetry-sdk/tests/logs/test_export.py +++ b/opentelemetry-sdk/tests/logs/test_export.py @@ -71,6 +71,9 @@ def test_simple_log_record_processor_default_level(self): self.assertEqual( warning_log_record.severity_number, SeverityNumber.WARN ) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, "default_level" + ) def test_simple_log_record_processor_custom_level(self): exporter = InMemoryLogExporter() @@ -104,6 +107,12 @@ def test_simple_log_record_processor_custom_level(self): self.assertEqual( fatal_log_record.severity_number, SeverityNumber.FATAL ) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, "custom_level" + ) + self.assertEqual( + finished_logs[1].instrumentation_scope.name, "custom_level" + ) def test_simple_log_record_processor_trace_correlation(self): exporter = InMemoryLogExporter() @@ -129,6 +138,9 @@ def test_simple_log_record_processor_trace_correlation(self): self.assertEqual( log_record.trace_flags, INVALID_SPAN_CONTEXT.trace_flags ) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, "trace_correlation" + ) exporter.clear() tracer = trace.TracerProvider().get_tracer(__name__) @@ -140,6 +152,10 @@ def test_simple_log_record_processor_trace_correlation(self): self.assertEqual(log_record.body, "Critical message within span") self.assertEqual(log_record.severity_text, "CRITICAL") self.assertEqual(log_record.severity_number, SeverityNumber.FATAL) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, + "trace_correlation", + ) span_context = span.get_span_context() self.assertEqual(log_record.trace_id, span_context.trace_id) self.assertEqual(log_record.span_id, span_context.span_id) @@ -166,6 +182,9 @@ def test_simple_log_record_processor_shutdown(self): self.assertEqual( warning_log_record.severity_number, SeverityNumber.WARN ) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, "shutdown" + ) exporter.clear() logger_provider.shutdown() with self.assertLogs(level=logging.WARNING): @@ -206,6 +225,10 @@ def test_simple_log_record_processor_different_msg_types(self): for item in finished_logs ] self.assertEqual(expected, emitted) + for item in finished_logs: + self.assertEqual( + item.instrumentation_scope.name, "different_msg_types" + ) def test_simple_log_record_processor_different_msg_types_with_formatter( self, @@ -428,6 +451,8 @@ def test_shutdown(self): for item in finished_logs ] self.assertEqual(expected, emitted) + for item in finished_logs: + self.assertEqual(item.instrumentation_scope.name, "shutdown") def test_force_flush(self): exporter = InMemoryLogExporter() @@ -447,6 +472,9 @@ def test_force_flush(self): log_record = finished_logs[0].log_record self.assertEqual(log_record.body, "Earth is burning") self.assertEqual(log_record.severity_number, SeverityNumber.FATAL) + self.assertEqual( + finished_logs[0].instrumentation_scope.name, "force_flush" + ) def test_log_record_processor_too_many_logs(self): exporter = InMemoryLogExporter() @@ -465,6 +493,8 @@ def test_log_record_processor_too_many_logs(self): self.assertTrue(log_record_processor.force_flush()) finised_logs = exporter.get_finished_logs() self.assertEqual(len(finised_logs), 1000) + for item in finised_logs: + self.assertEqual(item.instrumentation_scope.name, "many_logs") def test_with_multiple_threads(self): exporter = InMemoryLogExporter() @@ -492,6 +522,8 @@ def bulk_log_and_flush(num_logs): finished_logs = exporter.get_finished_logs() self.assertEqual(len(finished_logs), 2415) + for item in finished_logs: + self.assertEqual(item.instrumentation_scope.name, "threads") @unittest.skipUnless( hasattr(os, "fork"), From 8259ec58df1ff1c0d031e2bfaeff36eb1a103764 Mon Sep 17 00:00:00 2001 From: Tom Monk Date: Mon, 25 Mar 2024 08:36:43 -0700 Subject: [PATCH 02/11] Add entry to CHANGELOG.md --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 86739f645f..40fb9a66f2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -172,6 +172,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#3778](https://github.com/open-telemetry/opentelemetry-python/pull/3778)) - Fix license field in pyproject.toml files ([#3803](https://github.com/open-telemetry/opentelemetry-python/pull/3803)) +- Record logger name as the instrumentation scope name + ([#3810](https://github.com/open-telemetry/opentelemetry-python/pull/3810)) ## Version 1.23.0/0.44b0 (2024-02-23) From 18eaa374817d0ce3821afa124b5d6cac49536f08 Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Tue, 1 Oct 2024 14:01:36 -0700 Subject: [PATCH 03/11] Add logger caching by name, version, schema_url --- .../benchmarks/logs/test_benchmark_logs.py | 38 ++++++++++ .../sdk/_logs/_internal/__init__.py | 44 +++++++---- .../tests/logs/test_log_provider_cache.py | 74 +++++++++++++++++++ 3 files changed, 142 insertions(+), 14 deletions(-) create mode 100644 opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py create mode 100644 opentelemetry-sdk/tests/logs/test_log_provider_cache.py diff --git a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py new file mode 100644 index 0000000000..197e053eaf --- /dev/null +++ b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py @@ -0,0 +1,38 @@ +import logging + +import pytest + +from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler +from opentelemetry.sdk._logs.export import ( + InMemoryLogExporter, + SimpleLogRecordProcessor, +) + + +def set_up_logging_handler(level): + logger_provider = LoggerProvider() + exporter = InMemoryLogExporter() + processor = SimpleLogRecordProcessor(exporter=exporter) + logger_provider.add_log_record_processor(processor) + handler = LoggingHandler(level=level, logger_provider=logger_provider) + return handler + + +def create_logger(handler, name): + logger = logging.getLogger(name) + logger.addHandler(handler) + return logger + + +@pytest.mark.parametrize("num_loggers", [1, 10, 100, 1000, 10000]) +def test_simple_get_logger_different_names(benchmark, num_loggers): + handler = set_up_logging_handler(level=logging.DEBUG) + loggers = [ + create_logger(handler, str(f"logger_{i}")) for i in range(num_loggers) + ] + + def benchmark_get_logger(): + for i in range(10000): + loggers[i % num_loggers].warning("test message") + + benchmark(benchmark_get_logger) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index fe35b416bf..ceb7283188 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -20,8 +20,8 @@ import threading import traceback import warnings -from functools import lru_cache from os import environ +from threading import Lock from time import time_ns from typing import Any, Callable, Optional, Tuple, Union # noqa @@ -582,9 +582,12 @@ def emit(self, record: logging.LogRecord) -> None: def flush(self) -> None: """ - Flushes the logging output. Skip flushing if logger is NoOp. + Flushes the logging output. Skip flushing if logging_provider has no force_flush method. """ - self._logger_provider.force_flush() + if hasattr(self._logger_provider, "force_flush") and callable( + self._logger_provider.force_flush + ): + self._logger_provider.force_flush() class Logger(APILogger): @@ -641,12 +644,13 @@ def __init__( self._at_exit_handler = None if shutdown_on_exit: self._at_exit_handler = atexit.register(self.shutdown) + self._logger_cache = {} + self._logger_cache_lock = Lock() @property def resource(self): return self._resource - @lru_cache(maxsize=None) def get_logger( self, name: str, @@ -662,16 +666,28 @@ def get_logger( schema_url=schema_url, attributes=attributes, ) - return Logger( - self._resource, - self._multi_log_record_processor, - InstrumentationScope( - name, - version, - schema_url, - attributes, - ), - ) + key = (name, version, schema_url) + # Fast path if the logger is already in the cache, return it + if key in self._logger_cache: + return self._logger_cache[key] + + # Lock to prevent race conditions when registering loggers with the same key + with self._logger_cache_lock: + # Check again in case another thread added the logger while waiting + if key in self._logger_cache: + return self._logger_cache[key] + + self._logger_cache[key] = Logger( + self._resource, + self._multi_log_record_processor, + InstrumentationScope( + name, + version, + schema_url, + attributes, + ), + ) + return self._logger_cache[key] def add_log_record_processor( self, log_record_processor: LogRecordProcessor diff --git a/opentelemetry-sdk/tests/logs/test_log_provider_cache.py b/opentelemetry-sdk/tests/logs/test_log_provider_cache.py new file mode 100644 index 0000000000..61ebf1d14b --- /dev/null +++ b/opentelemetry-sdk/tests/logs/test_log_provider_cache.py @@ -0,0 +1,74 @@ +import logging +import unittest + +from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler +from opentelemetry.sdk._logs.export import ( + InMemoryLogExporter, + SimpleLogRecordProcessor, +) + + +def set_up_logging_handler(level): + logger_provider = LoggerProvider() + exporter = InMemoryLogExporter() + processor = SimpleLogRecordProcessor(exporter=exporter) + logger_provider.add_log_record_processor(processor) + handler = LoggingHandler(level=level, logger_provider=logger_provider) + return handler, logger_provider + + +def create_logger(handler, name): + logger = logging.getLogger(name) + logger.addHandler(handler) + return logger + + +class TestLogProviderCache(unittest.TestCase): + + def test_get_logger_single_handler(self): + handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) + + logger = create_logger(handler, "test_logger") + + logger.warning("test message") + + self.assertEqual(1, len(logger_provider._logger_cache)) + self.assertTrue( + ("test_logger", "", None) in logger_provider._logger_cache + ) + + rounds = 100 + for _ in range(rounds): + logger.warning("test message") + + self.assertEqual(1, len(logger_provider._logger_cache)) + self.assertTrue( + ("test_logger", "", None) in logger_provider._logger_cache + ) + + def test_get_logger_multiple_loggers(self): + handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) + + num_loggers = 10 + loggers = [create_logger(handler, str(i)) for i in range(num_loggers)] + + for logger in loggers: + logger.warning("test message") + + self.assertEqual(num_loggers, len(logger_provider._logger_cache)) + print(logger_provider._logger_cache) + for logger in loggers: + self.assertTrue( + (logger.name, "", None) in logger_provider._logger_cache + ) + + rounds = 100 + for _ in range(rounds): + for logger in loggers: + logger.warning("test message") + + self.assertEqual(num_loggers, len(logger_provider._logger_cache)) + for logger in loggers: + self.assertTrue( + (logger.name, "", None) in logger_provider._logger_cache + ) From 386835f92ee6141be484f51878f59b235d51715a Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Tue, 1 Oct 2024 14:40:30 -0700 Subject: [PATCH 04/11] Update CHANGELOG.md --- CHANGELOG.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 40fb9a66f2..25fe2f905e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#4094](https://github.com/open-telemetry/opentelemetry-python/pull/4094)) - Implement events sdk ([#4176](https://github.com/open-telemetry/opentelemetry-python/pull/4176)) +- Record logger name as the instrumentation scope name + ([#4208](https://github.com/open-telemetry/opentelemetry-python/pull/4208)) ## Version 1.27.0/0.48b0 (2024-08-28) @@ -172,8 +174,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#3778](https://github.com/open-telemetry/opentelemetry-python/pull/3778)) - Fix license field in pyproject.toml files ([#3803](https://github.com/open-telemetry/opentelemetry-python/pull/3803)) -- Record logger name as the instrumentation scope name - ([#3810](https://github.com/open-telemetry/opentelemetry-python/pull/3810)) ## Version 1.23.0/0.44b0 (2024-02-23) From 95a162be55ae1368430562b0a57e1da8e0fc3f92 Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Wed, 2 Oct 2024 10:29:33 -0700 Subject: [PATCH 05/11] Update benchmark --- .../benchmarks/logs/test_benchmark_logs.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py index 197e053eaf..aef0f1655a 100644 --- a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py +++ b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py @@ -9,7 +9,7 @@ ) -def set_up_logging_handler(level): +def _set_up_logging_handler(level): logger_provider = LoggerProvider() exporter = InMemoryLogExporter() processor = SimpleLogRecordProcessor(exporter=exporter) @@ -18,21 +18,21 @@ def set_up_logging_handler(level): return handler -def create_logger(handler, name): +def _create_logger(handler, name): logger = logging.getLogger(name) logger.addHandler(handler) return logger -@pytest.mark.parametrize("num_loggers", [1, 10, 100, 1000, 10000]) +@pytest.mark.parametrize("num_loggers", [1, 10, 100, 1000]) def test_simple_get_logger_different_names(benchmark, num_loggers): - handler = set_up_logging_handler(level=logging.DEBUG) + handler = _set_up_logging_handler(level=logging.DEBUG) loggers = [ - create_logger(handler, str(f"logger_{i}")) for i in range(num_loggers) + _create_logger(handler, str(f"logger_{i}")) for i in range(num_loggers) ] def benchmark_get_logger(): - for i in range(10000): + for i in range(1000): loggers[i % num_loggers].warning("test message") benchmark(benchmark_get_logger) From c072fe30cc69a69f965f2a8ae83fdbcafaee0f11 Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Mon, 7 Oct 2024 09:40:00 -0700 Subject: [PATCH 06/11] Attributes make logger unique --- .../benchmarks/logs/test_benchmark_logs.py | 4 +- .../sdk/_logs/_internal/__init__.py | 66 ++++++++++++------- .../tests/logs/test_log_provider_cache.py | 44 +++++++------ 3 files changed, 69 insertions(+), 45 deletions(-) diff --git a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py index aef0f1655a..d1e8c4e39f 100644 --- a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py +++ b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py @@ -32,7 +32,7 @@ def test_simple_get_logger_different_names(benchmark, num_loggers): ] def benchmark_get_logger(): - for i in range(1000): - loggers[i % num_loggers].warning("test message") + for index in range(1000): + loggers[index % num_loggers].warning("test message") benchmark(benchmark_get_logger) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 342641f8f4..81536d3cf3 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -20,8 +20,8 @@ import threading import traceback import warnings +from functools import lru_cache from os import environ -from threading import Lock from time import time_ns from typing import Any, Callable, Optional, Tuple, Union # noqa @@ -644,13 +644,47 @@ def __init__( self._at_exit_handler = None if shutdown_on_exit: self._at_exit_handler = atexit.register(self.shutdown) - self._logger_cache = {} - self._logger_cache_lock = Lock() @property def resource(self): return self._resource + def _get_logger_no_cache( + self, + name: str, + version: Optional[str] = None, + schema_url: Optional[str] = None, + attributes: Optional[Attributes] = None, + ) -> Logger: + return Logger( + self._resource, + self._multi_log_record_processor, + InstrumentationScope( + name, + version, + schema_url, + attributes, + ), + ) + + @lru_cache(maxsize=None) + def _get_logger_cached( + self, + name: str, + version: Optional[str] = None, + schema_url: Optional[str] = None, + ) -> Logger: + return Logger( + self._resource, + self._multi_log_record_processor, + InstrumentationScope( + name, + version, + schema_url, + None, + ), + ) + def get_logger( self, name: str, @@ -666,28 +700,12 @@ def get_logger( schema_url=schema_url, attributes=attributes, ) - key = (name, version, schema_url) - # Fast path if the logger is already in the cache, return it - if key in self._logger_cache: - return self._logger_cache[key] - - # Lock to prevent race conditions when registering loggers with the same key - with self._logger_cache_lock: - # Check again in case another thread added the logger while waiting - if key in self._logger_cache: - return self._logger_cache[key] - - self._logger_cache[key] = Logger( - self._resource, - self._multi_log_record_processor, - InstrumentationScope( - name, - version, - schema_url, - attributes, - ), + if attributes is None: + return self._get_logger_cached(name, version, schema_url) + else: + return self._get_logger_no_cache( + name, version, schema_url, attributes ) - return self._logger_cache[key] def add_log_record_processor( self, log_record_processor: LogRecordProcessor diff --git a/opentelemetry-sdk/tests/logs/test_log_provider_cache.py b/opentelemetry-sdk/tests/logs/test_log_provider_cache.py index 61ebf1d14b..992fb9807d 100644 --- a/opentelemetry-sdk/tests/logs/test_log_provider_cache.py +++ b/opentelemetry-sdk/tests/logs/test_log_provider_cache.py @@ -28,47 +28,53 @@ class TestLogProviderCache(unittest.TestCase): def test_get_logger_single_handler(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) + cache_info = logger_provider._get_logger_cached.cache_clear() + logger = create_logger(handler, "test_logger") + # Ensure logger is lazily cached + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(0, cache_info.currsize) + logger.warning("test message") - self.assertEqual(1, len(logger_provider._logger_cache)) - self.assertTrue( - ("test_logger", "", None) in logger_provider._logger_cache - ) + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(1, cache_info.currsize) + self.assertEqual(1, cache_info.misses) + # Ensure only one logger is cached rounds = 100 for _ in range(rounds): logger.warning("test message") - self.assertEqual(1, len(logger_provider._logger_cache)) - self.assertTrue( - ("test_logger", "", None) in logger_provider._logger_cache - ) + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(1, cache_info.currsize) + self.assertEqual(1, cache_info.misses) def test_get_logger_multiple_loggers(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) + cache_info = logger_provider._get_logger_cached.cache_clear() + num_loggers = 10 loggers = [create_logger(handler, str(i)) for i in range(num_loggers)] + # Ensure loggers are lazily cached + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(0, cache_info.currsize) + for logger in loggers: logger.warning("test message") - self.assertEqual(num_loggers, len(logger_provider._logger_cache)) - print(logger_provider._logger_cache) - for logger in loggers: - self.assertTrue( - (logger.name, "", None) in logger_provider._logger_cache - ) + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(num_loggers, cache_info.currsize) + self.assertEqual(num_loggers, cache_info.misses) rounds = 100 for _ in range(rounds): for logger in loggers: logger.warning("test message") - self.assertEqual(num_loggers, len(logger_provider._logger_cache)) - for logger in loggers: - self.assertTrue( - (logger.name, "", None) in logger_provider._logger_cache - ) + cache_info = logger_provider._get_logger_cached.cache_info() + self.assertEqual(num_loggers, cache_info.currsize) + self.assertEqual(num_loggers, cache_info.misses) From 8357f41d3c8efdd0a73b53949950f44a5616dca9 Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Mon, 7 Oct 2024 11:02:13 -0700 Subject: [PATCH 07/11] Do not use lru_cache on method --- ...s.py => test_benchmark_logging_handler.py} | 0 .../sdk/_logs/_internal/__init__.py | 39 +++++++++++-------- ...cache.py => test_logger_provider_cache.py} | 28 ++++--------- 3 files changed, 30 insertions(+), 37 deletions(-) rename opentelemetry-sdk/benchmarks/logs/{test_benchmark_logs.py => test_benchmark_logging_handler.py} (100%) rename opentelemetry-sdk/tests/logs/{test_log_provider_cache.py => test_logger_provider_cache.py} (58%) diff --git a/opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py b/opentelemetry-sdk/benchmarks/logs/test_benchmark_logging_handler.py similarity index 100% rename from opentelemetry-sdk/benchmarks/logs/test_benchmark_logs.py rename to opentelemetry-sdk/benchmarks/logs/test_benchmark_logging_handler.py diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 81536d3cf3..9711676ac5 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -20,8 +20,8 @@ import threading import traceback import warnings -from functools import lru_cache from os import environ +from threading import Lock from time import time_ns from typing import Any, Callable, Optional, Tuple, Union # noqa @@ -644,6 +644,8 @@ def __init__( self._at_exit_handler = None if shutdown_on_exit: self._at_exit_handler = atexit.register(self.shutdown) + self._logger_cache = {} + self._logger_cache_lock = Lock() @property def resource(self): @@ -667,23 +669,31 @@ def _get_logger_no_cache( ), ) - @lru_cache(maxsize=None) def _get_logger_cached( self, name: str, version: Optional[str] = None, schema_url: Optional[str] = None, ) -> Logger: - return Logger( - self._resource, - self._multi_log_record_processor, - InstrumentationScope( - name, - version, - schema_url, - None, - ), - ) + key = (name, version, schema_url) + if key in self._logger_cache: + return self._logger_cache[key] + + with self._logger_cache_lock: + if key in self._logger_cache: + return self._logger_cache[key] + + self._logger_cache[key] = Logger( + self._resource, + self._multi_log_record_processor, + InstrumentationScope( + name, + version, + schema_url, + None, + ), + ) + return self._logger_cache[key] def get_logger( self, @@ -702,10 +712,7 @@ def get_logger( ) if attributes is None: return self._get_logger_cached(name, version, schema_url) - else: - return self._get_logger_no_cache( - name, version, schema_url, attributes - ) + return self._get_logger_no_cache(name, version, schema_url, attributes) def add_log_record_processor( self, log_record_processor: LogRecordProcessor diff --git a/opentelemetry-sdk/tests/logs/test_log_provider_cache.py b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py similarity index 58% rename from opentelemetry-sdk/tests/logs/test_log_provider_cache.py rename to opentelemetry-sdk/tests/logs/test_logger_provider_cache.py index 992fb9807d..ba57838e61 100644 --- a/opentelemetry-sdk/tests/logs/test_log_provider_cache.py +++ b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py @@ -23,58 +23,44 @@ def create_logger(handler, name): return logger -class TestLogProviderCache(unittest.TestCase): +class TestLoggerProviderCache(unittest.TestCase): def test_get_logger_single_handler(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) - cache_info = logger_provider._get_logger_cached.cache_clear() - logger = create_logger(handler, "test_logger") # Ensure logger is lazily cached - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(0, cache_info.currsize) + self.assertEqual(0, len(logger_provider._logger_cache)) logger.warning("test message") - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(1, cache_info.currsize) - self.assertEqual(1, cache_info.misses) + self.assertEqual(1, len(logger_provider._logger_cache)) # Ensure only one logger is cached rounds = 100 for _ in range(rounds): logger.warning("test message") - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(1, cache_info.currsize) - self.assertEqual(1, cache_info.misses) + self.assertEqual(1, len(logger_provider._logger_cache)) def test_get_logger_multiple_loggers(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) - cache_info = logger_provider._get_logger_cached.cache_clear() - num_loggers = 10 loggers = [create_logger(handler, str(i)) for i in range(num_loggers)] # Ensure loggers are lazily cached - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(0, cache_info.currsize) + self.assertEqual(0, len(logger_provider._logger_cache)) for logger in loggers: logger.warning("test message") - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(num_loggers, cache_info.currsize) - self.assertEqual(num_loggers, cache_info.misses) + self.assertEqual(num_loggers, len(logger_provider._logger_cache)) rounds = 100 for _ in range(rounds): for logger in loggers: logger.warning("test message") - cache_info = logger_provider._get_logger_cached.cache_info() - self.assertEqual(num_loggers, cache_info.currsize) - self.assertEqual(num_loggers, cache_info.misses) + self.assertEqual(num_loggers, len(logger_provider._logger_cache)) From f055bfb57f13885420e1957344ccf29d0c05e7fa Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Mon, 7 Oct 2024 14:56:41 -0700 Subject: [PATCH 08/11] Fix linter for test --- .../tests/logs/test_logger_provider_cache.py | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py index ba57838e61..524ff62448 100644 --- a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py +++ b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py @@ -27,40 +27,43 @@ class TestLoggerProviderCache(unittest.TestCase): def test_get_logger_single_handler(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) - + # pylint: disable=protected-access + logger_cache = logger_provider._logger_cache logger = create_logger(handler, "test_logger") # Ensure logger is lazily cached - self.assertEqual(0, len(logger_provider._logger_cache)) + self.assertEqual(0, len(logger_cache)) logger.warning("test message") - self.assertEqual(1, len(logger_provider._logger_cache)) + self.assertEqual(1, len(logger_cache)) # Ensure only one logger is cached rounds = 100 for _ in range(rounds): logger.warning("test message") - self.assertEqual(1, len(logger_provider._logger_cache)) + self.assertEqual(1, len(logger_cache)) def test_get_logger_multiple_loggers(self): handler, logger_provider = set_up_logging_handler(level=logging.DEBUG) + # pylint: disable=protected-access + logger_cache = logger_provider._logger_cache num_loggers = 10 loggers = [create_logger(handler, str(i)) for i in range(num_loggers)] # Ensure loggers are lazily cached - self.assertEqual(0, len(logger_provider._logger_cache)) + self.assertEqual(0, len(logger_cache)) for logger in loggers: logger.warning("test message") - self.assertEqual(num_loggers, len(logger_provider._logger_cache)) + self.assertEqual(num_loggers, len(logger_cache)) rounds = 100 for _ in range(rounds): for logger in loggers: logger.warning("test message") - self.assertEqual(num_loggers, len(logger_provider._logger_cache)) + self.assertEqual(num_loggers, len(logger_cache)) From 5a155ab7212ede78e6922220c3451c3a5a4f5f42 Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Wed, 9 Oct 2024 10:01:49 -0700 Subject: [PATCH 09/11] fix nit --- .../sdk/_logs/_internal/__init__.py | 16 +++------------- 1 file changed, 3 insertions(+), 13 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 9711676ac5..dc054f50e3 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -675,23 +675,13 @@ def _get_logger_cached( version: Optional[str] = None, schema_url: Optional[str] = None, ) -> Logger: - key = (name, version, schema_url) - if key in self._logger_cache: - return self._logger_cache[key] - with self._logger_cache_lock: + key = (name, version, schema_url) if key in self._logger_cache: return self._logger_cache[key] - self._logger_cache[key] = Logger( - self._resource, - self._multi_log_record_processor, - InstrumentationScope( - name, - version, - schema_url, - None, - ), + self._logger_cache[key] = self._get_logger_no_cache( + name, version, schema_url ) return self._logger_cache[key] From 2b7835c7b0923811bff3ffc6004d55328ebd3efc Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Sat, 12 Oct 2024 19:43:44 -0700 Subject: [PATCH 10/11] add no cache get_logger test --- .../tests/logs/test_logger_provider_cache.py | 38 +++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py index 524ff62448..0bb25b6104 100644 --- a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py +++ b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py @@ -67,3 +67,41 @@ def test_get_logger_multiple_loggers(self): logger.warning("test message") self.assertEqual(num_loggers, len(logger_cache)) + + def test_provider_get_logger_no_cache(self): + _, logger_provider = set_up_logging_handler(level=logging.DEBUG) + # pylint: disable=protected-access + logger_cache = logger_provider._logger_cache + + logger_provider.get_logger( + name="test_logger", + version="version", + schema_url="schema_url", + attributes={"key": "value"}, + ) + + # Ensure logger is not cached if attributes is set + self.assertEqual(0, len(logger_cache)) + + def test_provider_get_logger_cached(self): + _, logger_provider = set_up_logging_handler(level=logging.DEBUG) + # pylint: disable=protected-access + logger_cache = logger_provider._logger_cache + + logger_provider.get_logger( + name="test_logger", + version="version", + schema_url="schema_url", + ) + + # Ensure only one logger is cached + self.assertEqual(1, len(logger_cache)) + + logger_provider.get_logger( + name="test_logger", + version="version", + schema_url="schema_url", + ) + + # Ensure only one logger is cached + self.assertEqual(1, len(logger_cache)) From 26090eabc152812ba4af602dbdab8c3b7830a01c Mon Sep 17 00:00:00 2001 From: Jeevan Opel Date: Mon, 14 Oct 2024 12:37:31 -0700 Subject: [PATCH 11/11] catch logs in test --- .../tests/logs/test_logger_provider_cache.py | 24 +++++++++++-------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py index 0bb25b6104..920c667904 100644 --- a/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py +++ b/opentelemetry-sdk/tests/logs/test_logger_provider_cache.py @@ -34,14 +34,16 @@ def test_get_logger_single_handler(self): # Ensure logger is lazily cached self.assertEqual(0, len(logger_cache)) - logger.warning("test message") + with self.assertLogs(level=logging.WARNING): + logger.warning("test message") self.assertEqual(1, len(logger_cache)) # Ensure only one logger is cached - rounds = 100 - for _ in range(rounds): - logger.warning("test message") + with self.assertLogs(level=logging.WARNING): + rounds = 100 + for _ in range(rounds): + logger.warning("test message") self.assertEqual(1, len(logger_cache)) @@ -56,15 +58,17 @@ def test_get_logger_multiple_loggers(self): # Ensure loggers are lazily cached self.assertEqual(0, len(logger_cache)) - for logger in loggers: - logger.warning("test message") + with self.assertLogs(level=logging.WARNING): + for logger in loggers: + logger.warning("test message") self.assertEqual(num_loggers, len(logger_cache)) - rounds = 100 - for _ in range(rounds): - for logger in loggers: - logger.warning("test message") + with self.assertLogs(level=logging.WARNING): + rounds = 100 + for _ in range(rounds): + for logger in loggers: + logger.warning("test message") self.assertEqual(num_loggers, len(logger_cache))