From e494cb4f6e3b3c1b306546759b2e2ff4522c68a3 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Sat, 3 Feb 2024 12:16:25 +0530 Subject: [PATCH] feat: configurable recording Configurable behaviours: - Record SQL queries - Explain queries - Record stack frames - Run profiler - Filter some requests --- frappe/core/doctype/recorder/recorder_list.js | 88 ++++++++++++-- frappe/recorder.py | 107 ++++++++++++++---- 2 files changed, 163 insertions(+), 32 deletions(-) diff --git a/frappe/core/doctype/recorder/recorder_list.js b/frappe/core/doctype/recorder/recorder_list.js index a0eadae260..528ebc5089 100644 --- a/frappe/core/doctype/recorder/recorder_list.js +++ b/frappe/core/doctype/recorder/recorder_list.js @@ -88,18 +88,90 @@ frappe.listview_settings["Recorder"] = { }, setup_recorder_controls(listview) { + let me = this; listview.page.set_primary_action(listview.enabled ? __("Stop") : __("Start"), () => { - frappe.call({ - method: listview.enabled ? "frappe.recorder.stop" : "frappe.recorder.start", - callback: function () { - listview.refresh(); - }, - }); - listview.enabled = !listview.enabled; - this.refresh_controls(listview); + if (listview.enabled) { + me.stop_recorder(listview); + } else { + me.start_recorder(listview); + } }); }, + stop_recorder(listview) { + let me = this; + frappe.xcall("frappe.recorder.stop", {}).then(() => { + listview.refresh(); + listview.enabled = false; + me.refresh_controls(listview); + }); + }, + + start_recorder(listview) { + let me = this; + frappe.prompt( + [ + { + fieldtype: "Section Break", + fieldname: "sql_section", + label: "SQL", + }, + { + fieldname: "record_sql", + fieldtype: "Check", + label: "Record SQL Queries", + default: 1, + }, + { + fieldname: "explain", + fieldtype: "Check", + label: "Generate EXPLAIN for SQL queries", + default: 1, + }, + { + fieldname: "capture_stack", + fieldtype: "Check", + label: "Capture callstack of SQL queries", + default: 1, + }, + { + fieldtype: "Section Break", + fieldname: "python_section", + label: "Python", + }, + { + fieldname: "profile", + fieldtype: "Check", + label: "Run cProfile", + default: 0, + description: + "Warning: cProfile adds a lot of overhead. For best results, disable stack capturing when using cProfile.", + }, + { + fieldtype: "Section Break", + fieldname: "filter_section", + }, + { + fieldname: "filter", + fieldtype: "Data", + label: "Filter Path", + default: "/", + description: + "This will be used for filtering paths which will be recorded. You can use this to avoid slowing down other traffic. e.g. /api/method/erpnext", + }, + ], + (values) => { + frappe.xcall("frappe.recorder.start", values).then(() => { + listview.refresh(); + listview.enabled = true; + me.refresh_controls(listview); + }); + }, + __("Configure Recorder"), + __("Start Recordig") + ); + }, + update_indicators(listview) { if (listview.enabled) { listview.page.set_indicator(__("Active"), "green"); diff --git a/frappe/recorder.py b/frappe/recorder.py index bb47304fe5..b9301c30ac 100644 --- a/frappe/recorder.py +++ b/frappe/recorder.py @@ -11,6 +11,7 @@ import re import time from collections import Counter from collections.abc import Callable +from dataclasses import dataclass import sqlparse @@ -19,17 +20,37 @@ from frappe import _ from frappe.database.database import is_query_type RECORDER_INTERCEPT_FLAG = "recorder-intercept" +RECORDER_CONFIG_FLAG = "recorder-config" RECORDER_REQUEST_SPARSE_HASH = "recorder-requests-sparse" RECORDER_REQUEST_HASH = "recorder-requests" TRACEBACK_PATH_PATTERN = re.compile(".*/apps/") +RECORDER_AUTO_DISABLE = 5 * 60 -def sql(*args, **kwargs): +@dataclass +class RecorderConfig: + record_sql: bool = True + capture_stack: bool = True + profile: bool = False + explain: bool = True + filter: str = "/" + + def store(self): + frappe.cache.set_value(RECORDER_CONFIG_FLAG, self, expires_in_sec=RECORDER_AUTO_DISABLE) + + @classmethod + def retrieve(cls): + return frappe.cache.get_value(RECORDER_CONFIG_FLAG) or cls() + + +def record_sql(*args, **kwargs): start_time = time.monotonic() result = frappe.db._sql(*args, **kwargs) end_time = time.monotonic() - stack = list(get_current_stack_frames()) + stack = [] + if frappe.local._recorder.config.capture_stack: + stack = list(get_current_stack_frames()) data = { "query": str(frappe.db.last_query), @@ -72,6 +93,7 @@ def post_process(): frappe.db.rollback() frappe.db.begin(read_only=True) # Explicitly start read only transaction + config = RecorderConfig.retrieve() result = list(frappe.cache.hgetall(RECORDER_REQUEST_HASH).values()) for request in result: @@ -82,7 +104,7 @@ def post_process(): call["query"] = formatted_query # Collect EXPLAIN for executed query - if is_query_type(formatted_query, ("select", "update", "delete")): + if config.explain and is_query_type(formatted_query, ("select", "update", "delete")): # Only SELECT/UPDATE/DELETE queries can be "EXPLAIN"ed try: call["explain_result"] = frappe.db.sql(f"EXPLAIN {formatted_query}", as_dict=True) @@ -148,11 +170,17 @@ def dump(): class Recorder: def __init__(self): + self.config = RecorderConfig.retrieve() self.uuid = frappe.generate_hash(length=10) self.time = datetime.datetime.now() self.calls = [] - self.profiler = cProfile.Profile() - self.profiler.enable() + self._patched_sql = False + + self.profiler = None + if self.config.profile: + self.profiler = cProfile.Profile() + self.profiler.enable() + if frappe.request: self.path = frappe.request.path self.cmd = frappe.local.form_dict.cmd or "" @@ -175,18 +203,32 @@ class Recorder: self.headers = None self.form_dict = None - _patch() + if self.config.record_sql: + self._patch_sql() + self._patched_sql = True def register(self, data): self.calls.append(data) - def dump(self): - self.profiler.disable() + def cleanup(self): + if self.profiler: + self.profiler.disable() + if self._patched_sql: + self._unpatch_sql() - profiler_output = io.StringIO() - pstats.Stats(self.profiler, stream=profiler_output).strip_dirs().sort_stats( - "cumulative" - ).print_stats() + def process_profiler(self): + if self.config.profile or self.profiler: + self.profiler.disable() + profiler_output = io.StringIO() + pstats.Stats(self.profiler, stream=profiler_output).strip_dirs().sort_stats( + "cumulative" + ).print_stats() + profile = profiler_output.getvalue() + profiler_output.close() + return profile + + def dump(self): + profiler_output = self.process_profiler() request_data = { "uuid": self.uuid, @@ -209,26 +251,28 @@ class Recorder: request_data["calls"] = self.calls request_data["headers"] = self.headers request_data["form_dict"] = self.form_dict - request_data["profile"] = profiler_output.getvalue() - profiler_output.close() + request_data["profile"] = profiler_output frappe.cache.hset(RECORDER_REQUEST_HASH, self.uuid, request_data) + if self.config.record_sql: + self._unpatch_sql() -def _patch(): - frappe.db._sql = frappe.db.sql - frappe.db.sql = sql + @staticmethod + def _patch_sql(): + frappe.db._sql = frappe.db.sql + frappe.db.sql = record_sql - -def _unpatch(): - frappe.db.sql = frappe.db._sql + @staticmethod + def _unpatch_sql(): + frappe.db.sql = frappe.db._sql def do_not_record(function): @functools.wraps(function) def wrapper(*args, **kwargs): if hasattr(frappe.local, "_recorder"): + frappe.local._recorder.cleanup() del frappe.local._recorder - frappe.db.sql = frappe.db._sql return function(*args, **kwargs) return wrapper @@ -254,8 +298,23 @@ def status(*args, **kwargs): @frappe.whitelist() @do_not_record @administrator_only -def start(*args, **kwargs): - frappe.cache.set_value(RECORDER_INTERCEPT_FLAG, 1, expires_in_sec=60 * 60) +def start( + record_sql: bool = True, + profile: bool = False, + capture_stack: bool = True, + explain: bool = True, + filter: str = "/", + *args, + **kwargs, +): + frappe.cache.set_value(RECORDER_INTERCEPT_FLAG, 1, expires_in_sec=RECORDER_AUTO_DISABLE) + RecorderConfig( + record_sql=int(record_sql), + profile=int(profile), + capture_stack=int(capture_stack), + explain=int(explain), + filter=filter, + ).store() @frappe.whitelist() @@ -301,7 +360,7 @@ def record_queries(func: Callable): frappe.local._recorder.path = f"Function call: {func.__module__}.{func.__qualname__}" ret = func(*args, **kwargs) dump() - _unpatch() + Recorder._unpatch_sql() post_process() print("Recorded queries, open recorder to view them.") return ret