From bc3780560eb8db43ad2afafcea9c52ebf0f8c6f2 Mon Sep 17 00:00:00 2001 From: Gavin D'souza Date: Thu, 16 Jun 2022 14:07:10 +0530 Subject: [PATCH] perf: Use lazy mogrified query for logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit For parameterized queries, there's an improvement of ~30% in query execution via frappe.db.sql - from 58.6 µs ± 2.37 µs to 44.6 µs ± 1.56 µs --- frappe/database/database.py | 38 ++++++++++++++++++--------------- frappe/database/utils.py | 42 +++++++++++++++++++++++++++++++++++++ frappe/recorder.py | 3 +-- 3 files changed, 64 insertions(+), 19 deletions(-) create mode 100644 frappe/database/utils.py diff --git a/frappe/database/database.py b/frappe/database/database.py index 7a4953c333..1bba2c871e 100644 --- a/frappe/database/database.py +++ b/frappe/database/database.py @@ -19,6 +19,7 @@ import frappe.defaults import frappe.model.meta from frappe import _ from frappe.database.query import Query as FilterEngine +from frappe.database.utils import LazyMogrify, Query, QueryValues, is_query_type from frappe.exceptions import DoesNotExistError from frappe.model.utils.link_count import flush_local_link_count from frappe.query_builder.functions import Count @@ -31,13 +32,6 @@ INDEX_PATTERN = re.compile(r"\s*\([^)]+\)\s*") SINGLE_WORD_PATTERN = re.compile(r'([`"]?)(tab([A-Z]\w+))\1') MULTI_WORD_PATTERN = re.compile(r'([`"])(tab([A-Z]\w+)( [A-Z]\w+)+)\1') -Query = Union[str, frappe.qb] -QueryValues = Union[Tuple, List, Dict, NoneType] - - -def is_query_type(query: str, query_type: Union[str, Tuple[str]]) -> bool: - return query.lstrip().split(maxsplit=1)[0].lower().startswith(query_type) - class Database(object): """ @@ -78,7 +72,7 @@ class Database(object): self.password = password or frappe.conf.db_password self.value_cache = {} - # self.last_query last sql query executed + # self.last_query lazy attribute of last sql query executed @property def query(self): @@ -238,19 +232,25 @@ class Database(object): def _log_query(self, mogrified_query: str, debug: bool = False, explain: bool = False) -> None: """Takes the query and logs it to various interfaces according to the settings.""" - if frappe.conf.get("allow_tests") and frappe.cache().get_value("flag_print_sql"): - print(mogrified_query) + _query = None + + if frappe.conf.allow_tests and frappe.cache().get_value("flag_print_sql"): + _query = _query or str(mogrified_query) + print(_query) if debug: - if explain and is_query_type(mogrified_query, "select"): - self.explain_query(mogrified_query) - frappe.errprint(mogrified_query) + _query = _query or str(mogrified_query) + if explain and is_query_type(_query, "select"): + self.explain_query(_query) + frappe.errprint(_query) if frappe.conf.logging == 2: - frappe.log(f"<<<< query\n{mogrified_query}\n>>>>") + _query = _query or str(mogrified_query) + frappe.log(f"<<<< query\n{_query}\n>>>>") if frappe.flags.in_migrate: - self.log_touched_tables(mogrified_query) + _query = _query or str(mogrified_query) + self.log_touched_tables(_query) def log_query( self, query: str, values: QueryValues = None, debug: bool = False, explain: bool = False @@ -258,11 +258,11 @@ class Database(object): # TODO: Use mogrify until MariaDB Connector/C 1.1 is released and we can fetch something # like cursor._transformed_statement from the cursor object. We can also avoid setting # mogrified_query if we don't need to log it. - mogrified_query = self.mogrify(query, values) + mogrified_query = self.lazy_mogrify(query, values) self._log_query(mogrified_query, debug, explain) return mogrified_query - def mogrify(self, query, values): + def mogrify(self, query: Query, values: QueryValues): """build the query string with values""" if not values: return query @@ -276,6 +276,10 @@ class Database(object): return query % tuple(frappe.db.escape(v) if isinstance(v, str) else v for v in values) return (query, values) + def lazy_mogrify(self, query: Query, values: QueryValues) -> LazyMogrify: + """Wrap the object with str to generate mogrified query.""" + return LazyMogrify(query, values) + def explain_query(self, query, values=None): """Print `EXPLAIN` in error log.""" frappe.errprint("--- query explain ---") diff --git a/frappe/database/utils.py b/frappe/database/utils.py new file mode 100644 index 0000000000..47a5222ede --- /dev/null +++ b/frappe/database/utils.py @@ -0,0 +1,42 @@ +# Copyright (c) 2022, Frappe Technologies Pvt. Ltd. and Contributors +# License: MIT. See LICENSE + +from functools import cached_property +from types import NoneType +from typing import Dict, List, Tuple, Union + +import frappe +from frappe.query_builder.builder import MariaDB, Postgres + +Query = Union[str, MariaDB, Postgres] +QueryValues = Union[Tuple, List, Dict, NoneType] + + +def is_query_type(query: str, query_type: Union[str, Tuple[str]]) -> bool: + return query.lstrip().split(maxsplit=1)[0].lower().startswith(query_type) + + +class LazyString: + def _setup(self) -> None: + raise NotImplementedError + + @cached_property + def value(self) -> str: + return self._setup() + + def __str__(self) -> str: + return self.value + + def __repr__(self) -> str: + return f"'{self.value}'" + + +class LazyMogrify(LazyString): + __slots__ = () + + def __init__(self, query, values) -> None: + self.query = query + self.values = values + + def _setup(self) -> str: + return frappe.db.mogrify(self.query, self.values) diff --git a/frappe/recorder.py b/frappe/recorder.py index ff64c082bc..3ecf2b2b96 100644 --- a/frappe/recorder.py +++ b/frappe/recorder.py @@ -26,8 +26,7 @@ def sql(*args, **kwargs): end_time = time.time() stack = list(get_current_stack_frames()) - last_query = frappe.db.last_query - query = sqlparse.format(last_query.strip(), keyword_case="upper", reindent=True) + query = sqlparse.format(str(frappe.db.last_query).strip(), keyword_case="upper", reindent=True) # Collect EXPLAIN for executed query if is_query_type(query, ("select", "update", "delete")):