From 3c183344aa501cce26b2f5df33db1d321fcc1135 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Thu, 1 Feb 2024 22:16:06 +0530 Subject: [PATCH 1/4] feat: profile requests using recorder WIP: - [x] Basic working feature - [ ] Make this optional, this has insanely high overhead. - [ ] Specify requests/function filter to profile/record. This will allow better recording in production sites. - [ ] Make SQL profiling optional too --- frappe/core/doctype/recorder/recorder.json | 16 ++++++++++++++-- frappe/core/doctype/recorder/recorder.py | 1 + frappe/recorder.py | 14 ++++++++++++++ 3 files changed, 29 insertions(+), 2 deletions(-) diff --git a/frappe/core/doctype/recorder/recorder.json b/frappe/core/doctype/recorder/recorder.json index 391f808f31..72291dbfe2 100644 --- a/frappe/core/doctype/recorder/recorder.json +++ b/frappe/core/doctype/recorder/recorder.json @@ -20,7 +20,9 @@ "section_break_sgro", "form_dict", "section_break_9jhm", - "sql_queries" + "sql_queries", + "section_break_optn", + "profile" ], "fields": [ { @@ -107,6 +109,16 @@ "fieldtype": "Data", "hidden": 1, "label": "Event Type" + }, + { + "fieldname": "section_break_optn", + "fieldtype": "Section Break" + }, + { + "fieldname": "profile", + "fieldtype": "Code", + "label": "cProfile Output", + "read_only": 1 } ], "hide_toolbar": 1, @@ -114,7 +126,7 @@ "index_web_pages_for_search": 1, "is_virtual": 1, "links": [], - "modified": "2024-01-03 16:45:47.110048", + "modified": "2024-02-01 22:13:26.505174", "modified_by": "Administrator", "module": "Core", "name": "Recorder", diff --git a/frappe/core/doctype/recorder/recorder.py b/frappe/core/doctype/recorder/recorder.py index 347a237743..26ccfcf378 100644 --- a/frappe/core/doctype/recorder/recorder.py +++ b/frappe/core/doctype/recorder/recorder.py @@ -24,6 +24,7 @@ class Recorder(Document): method: DF.Literal["GET", "POST", "PUT", "DELETE", "PATCH", "HEAD", "OPTIONS"] number_of_queries: DF.Int path: DF.Data | None + profile: DF.Code | None request_headers: DF.Code | None sql_queries: DF.Table[RecorderQuery] time: DF.Datetime | None diff --git a/frappe/recorder.py b/frappe/recorder.py index 3094f83ad6..bb47304fe5 100644 --- a/frappe/recorder.py +++ b/frappe/recorder.py @@ -1,9 +1,12 @@ # Copyright (c) 2018, Frappe Technologies Pvt. Ltd. and Contributors # License: MIT. See LICENSE +import cProfile import datetime import functools import inspect +import io import json +import pstats import re import time from collections import Counter @@ -148,6 +151,8 @@ class Recorder: self.uuid = frappe.generate_hash(length=10) self.time = datetime.datetime.now() self.calls = [] + self.profiler = cProfile.Profile() + self.profiler.enable() if frappe.request: self.path = frappe.request.path self.cmd = frappe.local.form_dict.cmd or "" @@ -176,6 +181,13 @@ class Recorder: self.calls.append(data) def dump(self): + self.profiler.disable() + + profiler_output = io.StringIO() + pstats.Stats(self.profiler, stream=profiler_output).strip_dirs().sort_stats( + "cumulative" + ).print_stats() + request_data = { "uuid": self.uuid, "path": self.path, @@ -197,6 +209,8 @@ 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() frappe.cache.hset(RECORDER_REQUEST_HASH, self.uuid, request_data) From e494cb4f6e3b3c1b306546759b2e2ff4522c68a3 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Sat, 3 Feb 2024 12:16:25 +0530 Subject: [PATCH 2/4] 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 From 009b06d97447da4017f3109b90c775e4368be415 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Sat, 3 Feb 2024 14:46:55 +0530 Subject: [PATCH 3/4] feat: Jobs/Request filtering --- frappe/core/doctype/recorder/recorder_list.js | 66 +++++++++++++------ frappe/recorder.py | 66 +++++++++++-------- 2 files changed, 86 insertions(+), 46 deletions(-) diff --git a/frappe/core/doctype/recorder/recorder_list.js b/frappe/core/doctype/recorder/recorder_list.js index 528ebc5089..8ec9f2ae40 100644 --- a/frappe/core/doctype/recorder/recorder_list.js +++ b/frappe/core/doctype/recorder/recorder_list.js @@ -10,12 +10,7 @@ frappe.listview_settings["Recorder"] = { } listview.page.add_button(__("Clear"), () => { - frappe.call({ - method: "frappe.recorder.delete", - callback: function () { - listview.refresh(); - }, - }); + frappe.xcall("frappe.recorder.delete").then(listview.refresh); }); listview.page.add_menu_item(__("Import"), () => { @@ -111,6 +106,51 @@ frappe.listview_settings["Recorder"] = { let me = this; frappe.prompt( [ + { + fieldtype: "Section Break", + fieldname: "req_job_section", + }, + { + fieldtype: "Column Break", + fieldname: "web_request_columns", + label: "Web Requests", + }, + { + fieldname: "record_requests", + fieldtype: "Check", + label: "Record Web Requests", + default: 1, + }, + { + fieldname: "request_filter", + fieldtype: "Data", + label: "Request path filter", + default: "/", + depends_on: "record_requests", + 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", + }, + { + fieldtype: "Column Break", + fieldname: "background_col", + label: "Background Jobs", + }, + + { + fieldname: "record_jobs", + fieldtype: "Check", + label: "Record Background Jobs", + default: 1, + }, + { + fieldname: "jobs_filter", + fieldtype: "Data", + label: "Background Jobs filter", + default: "", + depends_on: "record_jobs", + description: + "This will be used for filtering jobs which will be recorded. You can use this to avoid slowing down other jobs. e.g. email_queue.pull", + }, { fieldtype: "Section Break", fieldname: "sql_section", @@ -119,7 +159,7 @@ frappe.listview_settings["Recorder"] = { { fieldname: "record_sql", fieldtype: "Check", - label: "Record SQL Queries", + label: "Record SQL queries", default: 1, }, { @@ -147,18 +187,6 @@ frappe.listview_settings["Recorder"] = { 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(() => { diff --git a/frappe/recorder.py b/frappe/recorder.py index b9301c30ac..bcc3f55b9e 100644 --- a/frappe/recorder.py +++ b/frappe/recorder.py @@ -29,11 +29,18 @@ RECORDER_AUTO_DISABLE = 5 * 60 @dataclass class RecorderConfig: - record_sql: bool = True - capture_stack: bool = True - profile: bool = False - explain: bool = True - filter: str = "/" + record_requests: bool = True # Record web request + record_jobs: bool = True # record background jobs + record_sql: bool = True # Record SQL queries + capture_stack: bool = True # Recod call stack of SQL queries + profile: bool = False # Run cProfile + explain: bool = True # Provide explain output of SQL queries + request_filter: str = "/" # Filter request paths + jobs_filter: str = "" # Filter background jobs + + def __post_init__(self): + if not (self.record_jobs or self.record_requests): + frappe.throw("You must record one of jobs or requests") def store(self): frappe.cache.set_value(RECORDER_CONFIG_FLAG, self, expires_in_sec=RECORDER_AUTO_DISABLE) @@ -171,24 +178,23 @@ 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._patched_sql = False - self.profiler = None - if self.config.profile: - self.profiler = cProfile.Profile() - self.profiler.enable() + self._recording = True - if frappe.request: + if ( + self.config.record_requests + and frappe.request + and self.config.request_filter in frappe.request.path + ): self.path = frappe.request.path self.cmd = frappe.local.form_dict.cmd or "" self.method = frappe.request.method self.headers = dict(frappe.local.request.headers) self.form_dict = frappe.local.form_dict self.event_type = "HTTP Request" - elif frappe.job: + elif self.config.record_jobs and frappe.job and self.config.jobs_filter in frappe.job.method: self.event_type = "Background Job" self.path = frappe.job.method self.cmd = None @@ -196,17 +202,20 @@ class Recorder: self.headers = None self.form_dict = None else: - self.event_type = None - self.path = None - self.cmd = None - self.method = None - self.headers = None - self.form_dict = None + self._recording = False + return + + self.uuid = frappe.generate_hash(length=10) + self.time = datetime.datetime.now() if self.config.record_sql: self._patch_sql() self._patched_sql = True + if self.config.profile: + self.profiler = cProfile.Profile() + self.profiler.enable() + def register(self, data): self.calls.append(data) @@ -228,6 +237,8 @@ class Recorder: return profile def dump(self): + if not self._recording: + return profiler_output = self.process_profiler() request_data = { @@ -242,11 +253,6 @@ class Recorder: "event_type": self.event_type, } frappe.cache.hset(RECORDER_REQUEST_SPARSE_HASH, self.uuid, request_data) - frappe.publish_realtime( - event="recorder-dump-event", - message=json.dumps(request_data, default=str), - user="Administrator", - ) request_data["calls"] = self.calls request_data["headers"] = self.headers @@ -299,22 +305,28 @@ def status(*args, **kwargs): @do_not_record @administrator_only def start( + record_jobs: bool = True, + record_requests: bool = True, record_sql: bool = True, profile: bool = False, capture_stack: bool = True, explain: bool = True, - filter: str = "/", + request_filter: str = "/", + jobs_filter: str = "", *args, **kwargs, ): - frappe.cache.set_value(RECORDER_INTERCEPT_FLAG, 1, expires_in_sec=RECORDER_AUTO_DISABLE) RecorderConfig( + record_requests=int(record_requests), + record_jobs=int(record_jobs), record_sql=int(record_sql), profile=int(profile), capture_stack=int(capture_stack), explain=int(explain), - filter=filter, + request_filter=request_filter, + jobs_filter=jobs_filter, ).store() + frappe.cache.set_value(RECORDER_INTERCEPT_FLAG, 1, expires_in_sec=RECORDER_AUTO_DISABLE) @frappe.whitelist() From 9107627dac250f67057fed95b3739c1326dd7125 Mon Sep 17 00:00:00 2001 From: Ankush Menat Date: Sat, 3 Feb 2024 15:48:06 +0530 Subject: [PATCH 4/4] fix: recorder timezone bug use system timezone to avoid showing incorrect timestamp --- frappe/core/doctype/recorder/recorder_list.js | 10 +++++--- frappe/recorder.py | 25 ++++++++++++++----- 2 files changed, 25 insertions(+), 10 deletions(-) diff --git a/frappe/core/doctype/recorder/recorder_list.js b/frappe/core/doctype/recorder/recorder_list.js index 8ec9f2ae40..35498032ed 100644 --- a/frappe/core/doctype/recorder/recorder_list.js +++ b/frappe/core/doctype/recorder/recorder_list.js @@ -127,8 +127,9 @@ frappe.listview_settings["Recorder"] = { label: "Request path filter", default: "/", depends_on: "record_requests", - 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", + 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. Leave it empty to record every request.`, }, { fieldtype: "Column Break", @@ -148,8 +149,9 @@ frappe.listview_settings["Recorder"] = { label: "Background Jobs filter", default: "", depends_on: "record_jobs", - description: - "This will be used for filtering jobs which will be recorded. You can use this to avoid slowing down other jobs. e.g. email_queue.pull", + description: `This will be used for filtering jobs which will be recorded. + You can use this to avoid slowing down other jobs. e.g. email_queue.pull. + Leave it empty to record every job.`, }, { fieldtype: "Section Break", diff --git a/frappe/recorder.py b/frappe/recorder.py index bcc3f55b9e..a0b4c17880 100644 --- a/frappe/recorder.py +++ b/frappe/recorder.py @@ -1,7 +1,6 @@ # Copyright (c) 2018, Frappe Technologies Pvt. Ltd. and Contributors # License: MIT. See LICENSE import cProfile -import datetime import functools import inspect import io @@ -18,6 +17,7 @@ import sqlparse import frappe from frappe import _ from frappe.database.database import is_query_type +from frappe.utils import now_datetime RECORDER_INTERCEPT_FLAG = "recorder-intercept" RECORDER_CONFIG_FLAG = "recorder-config" @@ -49,6 +49,10 @@ class RecorderConfig: def retrieve(cls): return frappe.cache.get_value(RECORDER_CONFIG_FLAG) or cls() + @staticmethod + def delete(): + frappe.cache.delete_value(RECORDER_CONFIG_FLAG) + def record_sql(*args, **kwargs): start_time = time.monotonic() @@ -120,6 +124,8 @@ def post_process(): mark_duplicates(request) frappe.cache.hset(RECORDER_REQUEST_HASH, request["uuid"], request) + config.delete() + def mark_duplicates(request): exact_duplicates = Counter([call["query"] for call in request["calls"]]) @@ -166,7 +172,7 @@ def normalize_query(query: str) -> str: def record(force=False): if __debug__: if frappe.cache.get_value(RECORDER_INTERCEPT_FLAG) or force: - frappe.local._recorder = Recorder() + frappe.local._recorder = Recorder(force=force) def dump(): @@ -176,12 +182,17 @@ def dump(): class Recorder: - def __init__(self): + def __init__(self, force=False): self.config = RecorderConfig.retrieve() self.calls = [] self._patched_sql = False self.profiler = None self._recording = True + self.force = force + self.cmd = None + self.method = None + self.headers = None + self.form_dict = None if ( self.config.record_requests @@ -201,12 +212,14 @@ class Recorder: self.method = None self.headers = None self.form_dict = None - else: + elif not self.force: self._recording = False return + else: + self.event_type = "Function Call" self.uuid = frappe.generate_hash(length=10) - self.time = datetime.datetime.now() + self.time = now_datetime() if self.config.record_sql: self._patch_sql() @@ -248,7 +261,7 @@ class Recorder: "time": self.time, "queries": len(self.calls), "time_queries": float("{:0.3f}".format(sum(call["duration"] for call in self.calls))), - "duration": float(f"{(datetime.datetime.now() - self.time).total_seconds() * 1000:0.3f}"), + "duration": float(f"{(now_datetime() - self.time).total_seconds() * 1000:0.3f}"), "method": self.method, "event_type": self.event_type, }