Commit a867ccc4 authored by Nicolas Chauvat's avatar Nicolas Chauvat
Browse files

fix: do not consume a lot of time to collect debug data if no one is listening

parent 21a59f6d1d52
Pipeline #67236 passed with stages
in 30 minutes and 32 seconds
......@@ -38,7 +38,7 @@ from rql import RQLHelper
from yams.constraints import BASE_CONVERTERS
from cubicweb import _
from cubicweb.debug import emit_to_debug_channel
from cubicweb.debug import debug_channel_has_subscribers, emit_to_debug_channel
from cubicweb import (
CW_SOFTWARE_ROOT,
ETYPE_NAME_MAP,
......@@ -84,7 +84,8 @@ class CWRegistry(Registry):
"""
super().__init__(True)
self.vreg = vreg
self.add_select_best_listener(self._emit_registry_debug_information)
if debug_channel_has_subscribers("registry_decisions"):
self.add_select_best_listener(self._emit_registry_debug_information)
def _emit_registry_debug_information(self, debug_registry_select_best):
emit_to_debug_channel("registry_decisions", debug_registry_select_best)
......
......@@ -30,6 +30,10 @@ SUBSCRIBERS = {
}
def debug_channel_has_subscribers(channel):
return len(SUBSCRIBERS.get(channel, [])) > 0
def subscribe_to_debug_channel(channel, subscriber):
"""
Allow to subscribe a callable to one of the debug channels.
......
......@@ -43,7 +43,7 @@ from cubicweb import ValidationError, Unauthorized, UnknownEid, QueryError
from cubicweb.rqlrewrite import RQLRelationRewriter
from cubicweb import Binary, server
from cubicweb.rset import ResultSet
from cubicweb.debug import emit_to_debug_channel
from cubicweb.debug import debug_channel_has_subscribers, emit_to_debug_channel
from cubicweb.utils import RepeatList
from cubicweb.misc.source_highlight import highlight_terminal
......@@ -544,6 +544,8 @@ class QuerierHelper:
always use substitute arguments in queries (i.e. avoid query such as
'Any X WHERE X eid 123'!)
"""
use_debug_channel = debug_channel_has_subscribers("rql")
if server.DEBUG & (server.DBG_RQL | server.DBG_SQL):
if server.DEBUG & (server.DBG_MORE | server.DBG_SQL):
print("*" * 80)
......@@ -583,14 +585,15 @@ class QuerierHelper:
plan.rql_query_tracing_token = str(uuid.uuid4())
prepare_plan(plan, self.schema, self._repo.vreg.rqlhelper)
query_debug_informations = {
"rql": rql,
"rql_query_tracing_token": plan.rql_query_tracing_token,
"args": args,
# remove the last part of the stack which is: this line
"callstack": "".join(traceback.format_stack()[:-1]),
"description": "",
}
if use_debug_channel:
query_debug_informations = {
"rql": rql,
"rql_query_tracing_token": plan.rql_query_tracing_token,
"args": args,
# remove the last part of the stack which is: this line
"callstack": "".join(traceback.format_stack()[:-1]),
"description": "",
}
start = time.time()
# execute the plan
......@@ -609,8 +612,9 @@ class QuerierHelper:
cnx.commit_state = "uncommitable"
raise
query_debug_informations["time"] = (time.time() - start) * 1000
query_debug_informations["result"] = results
if use_debug_channel:
query_debug_informations["time"] = (time.time() - start) * 1000
query_debug_informations["result"] = results
# build a description for the results if necessary
descr = ()
......@@ -640,9 +644,11 @@ class QuerierHelper:
descr = _build_descr(cnx, results, basedescr, todetermine)
# FIXME: get number of affected entities / relations on non
# selection queries ?
query_debug_informations["description"] = descr
if use_debug_channel:
query_debug_informations["description"] = descr
emit_to_debug_channel("rql", query_debug_informations)
if use_debug_channel:
emit_to_debug_channel("rql", query_debug_informations)
# return a result set object
return ResultSet(results, rql, args, descr, variables)
......
......@@ -49,7 +49,7 @@ from cubicweb import (
ViolatedConstraint,
)
from cubicweb import transaction as tx, server, neg_role, _
from cubicweb.debug import emit_to_debug_channel
from cubicweb.debug import debug_channel_has_subscribers, emit_to_debug_channel
from cubicweb.schema import VIRTUAL_RTYPES
from cubicweb.cwconfig import CubicWebNoAppConfiguration
from cubicweb.server import hook
......@@ -792,14 +792,15 @@ class NativeSQLSource(SQLAdapterMixIn, AbstractSource):
"""Execute a query.
it's a function just so that it shows up in profiling
"""
query_debug_informations = {
"sql": query,
"args": args,
"rollback": False,
"callstack": "".join(traceback.format_stack()[:-1]),
"rql_query_tracing_token": rql_query_tracing_token,
}
use_debug_channel = debug_channel_has_subscribers("sql")
if use_debug_channel:
query_debug_informations = {
"sql": query,
"args": args,
"rollback": False,
"callstack": "".join(traceback.format_stack()[:-1]),
"rql_query_tracing_token": rql_query_tracing_token,
}
start = time.time()
......@@ -819,7 +820,8 @@ class NativeSQLSource(SQLAdapterMixIn, AbstractSource):
if rollback:
try:
cnx.cnxset.rollback()
query_debug_informations["rollback"] = True
if use_debug_channel:
query_debug_informations["rollback"] = True
if self.repo.config.mode != "test":
self.debug("transaction has been rolled back")
except Exception as rollback_exc:
......@@ -872,8 +874,9 @@ class NativeSQLSource(SQLAdapterMixIn, AbstractSource):
)
raise
finally:
query_debug_informations["time"] = (time.time() - start) * 1000
emit_to_debug_channel("sql", query_debug_informations)
if use_debug_channel:
query_debug_informations["time"] = (time.time() - start) * 1000
emit_to_debug_channel("sql", query_debug_informations)
return cursor
def doexecmany(self, cnx, query, args):
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment