From 90f8ff08a4b15c7706778eb10088cd239591e4cc Mon Sep 17 00:00:00 2001 From: Mike Bayer Date: Wed, 17 Jan 2024 21:15:37 -0500 Subject: [PATCH] remove loader depth warning, replace with logging message Replaced the "loader depth is excessively deep" warning with a shorter message added to the caching badge within SQL logging, for those statements where the ORM disabled the cache due to a too-deep chain of loader options. The condition which this warning highlights is difficult to resolve and is generally just a limitation in the ORM's application of SQL caching. A future feature may include the ability to tune the threshold where caching is disabled, but for now the warning will no longer be a nuisance. Fixes: #10896 Change-Id: Ic3be2086d1db16f9a75390323f00a43ef72aca12 --- doc/build/changelog/unreleased_20/10896.rst | 11 +++++ lib/sqlalchemy/engine/default.py | 8 +++- lib/sqlalchemy/orm/context.py | 17 ++++--- test/orm/test_recursive_loaders.py | 52 ++++++++++++++------- 4 files changed, 61 insertions(+), 27 deletions(-) create mode 100644 doc/build/changelog/unreleased_20/10896.rst diff --git a/doc/build/changelog/unreleased_20/10896.rst b/doc/build/changelog/unreleased_20/10896.rst new file mode 100644 index 00000000000..77224d974ca --- /dev/null +++ b/doc/build/changelog/unreleased_20/10896.rst @@ -0,0 +1,11 @@ +.. change:: + :tags: bug, orm + :tickets: 10896 + + Replaced the "loader depth is excessively deep" warning with a shorter + message added to the caching badge within SQL logging, for those statements + where the ORM disabled the cache due to a too-deep chain of loader options. + The condition which this warning highlights is difficult to resolve and is + generally just a limitation in the ORM's application of SQL caching. A + future feature may include the ability to tune the threshold where caching + is disabled, but for now the warning will no longer be a nuisance. diff --git a/lib/sqlalchemy/engine/default.py b/lib/sqlalchemy/engine/default.py index 213a047711e..afbda08b461 100644 --- a/lib/sqlalchemy/engine/default.py +++ b/lib/sqlalchemy/engine/default.py @@ -1583,7 +1583,13 @@ def _get_cache_stats(self) -> str: elif ch is CACHE_MISS: return "generated in %.5fs" % (now - gen_time,) elif ch is CACHING_DISABLED: - return "caching disabled %.5fs" % (now - gen_time,) + if "_cache_disable_reason" in self.execution_options: + return "caching disabled (%s) %.5fs " % ( + self.execution_options["_cache_disable_reason"], + now - gen_time, + ) + else: + return "caching disabled %.5fs" % (now - gen_time,) elif ch is NO_DIALECT_SUPPORT: return "dialect %s+%s does not support caching %.5fs" % ( self.dialect.name, diff --git a/lib/sqlalchemy/orm/context.py b/lib/sqlalchemy/orm/context.py index 7ab7e6279ea..b4178253185 100644 --- a/lib/sqlalchemy/orm/context.py +++ b/lib/sqlalchemy/orm/context.py @@ -517,15 +517,14 @@ def orm_pre_session_exec( and len(statement._compile_options._current_path) > 10 and execution_options.get("compiled_cache", True) is not None ): - util.warn( - "Loader depth for query is excessively deep; caching will " - "be disabled for additional loaders. For recursive eager " - "loaders consider using the recursion_depth feature. " - "Use the compiled_cache=None execution option to " - "skip this warning." - ) - execution_options = execution_options.union( - {"compiled_cache": None} + execution_options: util.immutabledict[ + str, Any + ] = execution_options.union( + { + "compiled_cache": None, + "_cache_disable_reason": "excess depth for " + "ORM loader options", + } ) bind_arguments["clause"] = statement diff --git a/test/orm/test_recursive_loaders.py b/test/orm/test_recursive_loaders.py index 10582e71131..e6ce5ccd7ef 100644 --- a/test/orm/test_recursive_loaders.py +++ b/test/orm/test_recursive_loaders.py @@ -1,3 +1,5 @@ +import logging.handlers + import sqlalchemy as sa from sqlalchemy import ForeignKey from sqlalchemy import Integer @@ -11,7 +13,6 @@ from sqlalchemy.orm import Session from sqlalchemy.testing import eq_ from sqlalchemy.testing import expect_raises_message -from sqlalchemy.testing import expect_warnings from sqlalchemy.testing import fixtures from sqlalchemy.testing.fixtures import fixture_session from sqlalchemy.testing.schema import Column @@ -258,13 +259,27 @@ def test_unlimited_recursion(self, loader_fn, limited_cache_conn): result = s.scalars(stmt) self._assert_depth(result.one(), 200) + @testing.fixture + def capture_log(self, testing_engine): + existing_level = logging.getLogger("sqlalchemy.engine").level + + buf = logging.handlers.BufferingHandler(100) + logging.getLogger("sqlalchemy.engine").addHandler(buf) + logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO) + yield buf + logging.getLogger("sqlalchemy.engine").setLevel(existing_level) + logging.getLogger("sqlalchemy.engine").removeHandler(buf) + @testing.combinations(selectinload, immediateload, argnames="loader_fn") @testing.combinations(4, 9, 12, 25, 41, 55, argnames="depth") @testing.variation("disable_cache", [True, False]) def test_warning_w_no_recursive_opt( - self, loader_fn, depth, limited_cache_conn, disable_cache + self, loader_fn, depth, limited_cache_conn, disable_cache, capture_log ): + buf = capture_log + connection = limited_cache_conn(27) + connection._echo = True Node = self.classes.Node @@ -280,21 +295,24 @@ def test_warning_w_no_recursive_opt( else: exec_opts = {} - # note this is a magic number, it's not important that it's exact, - # just that when someone makes a huge recursive thing, - # it warns - if depth > 8 and not disable_cache: - with expect_warnings( - "Loader depth for query is excessively deep; " - "caching will be disabled for additional loaders." - ): - with Session(connection) as s: - result = s.scalars(stmt, execution_options=exec_opts) - self._assert_depth(result.one(), depth) - else: - with Session(connection) as s: - result = s.scalars(stmt, execution_options=exec_opts) - self._assert_depth(result.one(), depth) + with Session(connection) as s: + result = s.scalars(stmt, execution_options=exec_opts) + self._assert_depth(result.one(), depth) + + if not disable_cache: + # note this is a magic number, it's not important that it's + # exact, just that when someone makes a huge recursive thing, + # it disables caching and notes in the logs + if depth > 8: + eq_( + buf.buffer[-1].message[0:55], + "[caching disabled (excess depth for " + "ORM loader options)", + ) + else: + assert buf.buffer[-1].message.startswith( + "[cached since" if i > 0 else "[generated in" + ) if disable_cache: clen = len(connection.engine._compiled_cache)