FazBrowse GitHub Viewer | Trending |
URL:
| Home
Tools: [Download Repo ZIP]   [Original HTTPS Page]

Python: CG trace: Improve performance by only logging when needed · github/codeql@3ead2e3 · GitHub

/ codeql Public

Commit 3ead2e3

Browse files
RasmusWL
committed
Python: CG trace: Improve performance by only logging when needed
Seems like a 2x performance overall wcwidth: - DEBUG=True 5.78 seconds - DEBUG=False 2.70 seconds youtube-dl - DEBUG=True 238.90 seconds - DEBUG=False 120.70 seconds
1 parent fbd9391 commit 3ead2e3

5 files changed

Lines changed: 51 additions & 28 deletions

File tree

‎python/tools/recorded-call-graph-metrics/src/cg_trace/bytecode_reconstructor.py‎

Lines changed: 22 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
from types import FrameType
66
from typing import Any, List
77

8+
from cg_trace.settings import DEBUG, FAIL_ON_UNKNOWN_BYTECODE
89
from cg_trace.utils import better_compare_for_dataclass
910

1011
LOGGER = logging.getLogger(__name__)
@@ -155,23 +156,26 @@ def expr_that_added_elem_to_stack(
155156
immediately. (since correctly process the bytecode when faced with jumps is not as
156157
straight forward).
157158
"""
158-
LOGGER.debug(
159-
f"find_inst_that_added_elem_to_stack start_index={start_index} stack_pos={stack_pos}"
160-
)
159+
if DEBUG:
160+
LOGGER.debug(
161+
f"find_inst_that_added_elem_to_stack start_index={start_index} stack_pos={stack_pos}"
162+
)
161163
assert stack_pos >= 0
162164
for inst in reversed(instructions[: start_index + 1]):
163165
# Return immediately if faced with a jump
164166
if inst.opcode in dis.hasjabs or inst.opcode in dis.hasjrel:
165167
return SomethingInvolvingScaryBytecodeJump(inst.opname)
166168

167169
if stack_pos == 0:
168-
LOGGER.debug(f"Found it: {inst}")
170+
if DEBUG:
171+
LOGGER.debug(f"Found it: {inst}")
169172
found_index = instructions.index(inst)
170173
break
171174
old = stack_pos
172175
stack_pos -= dis.stack_effect(inst.opcode, inst.arg)
173176
new = stack_pos
174-
LOGGER.debug(f"Skipping ({old} -> {new}) {inst}")
177+
if DEBUG:
178+
LOGGER.debug(f"Skipping ({old} -> {new}) {inst}")
175179
else:
176180
raise Exception("inst_index_for_stack_diff failed")
177181

@@ -181,7 +185,8 @@ def expr_that_added_elem_to_stack(
181185
def expr_from_instruction(instructions: List[Instruction], index: int) -> BytecodeExpr:
182186
inst = instructions[index]
183187

184-
LOGGER.debug(f"expr_from_instruction: {inst} index={index}")
188+
if DEBUG:
189+
LOGGER.debug(f"expr_from_instruction: {inst} index={index}")
185190

186191
if inst.opname in ["LOAD_GLOBAL", "LOAD_FAST", "LOAD_NAME", "LOAD_DEREF"]:
187192
return BytecodeVariableName(inst.argval)
@@ -247,24 +252,23 @@ def expr_from_instruction(instructions: List[Instruction], index: int) -> Byteco
247252
# - LOAD_BUILD_CLASS: Called when constructing a class.
248253
# - IMPORT_NAME: Observed to result in a call to filename='<frozen
249254
# importlib._bootstrap>', linenum=389, funcname='parent'
250-
if inst.opname not in ["LOAD_BUILD_CLASS", "IMPORT_NAME"] + WITH_OPNAMES:
251-
LOGGER.warning(
252-
f"Don't know how to handle this type of instruction: {inst.opname}"
253-
)
254-
# Uncomment to stop execution when encountering non-ignored unknown instruction
255-
# class MyBytecodeException(BaseException):
256-
# pass
257-
#
258-
# raise MyBytecodeException()
255+
if FAIL_ON_UNKNOWN_BYTECODE:
256+
if inst.opname not in ["LOAD_BUILD_CLASS", "IMPORT_NAME"] + WITH_OPNAMES:
257+
LOGGER.warning(
258+
f"Don't know how to handle this type of instruction: {inst.opname}"
259+
)
260+
raise BaseException()
261+
259262
return BytecodeUnknown(inst.opname)
260263

261264

262265
def expr_from_frame(frame: FrameType) -> BytecodeExpr:
263266
bytecode = dis.Bytecode(frame.f_code, current_offset=frame.f_lasti)
264267

265-
LOGGER.debug(
266-
f"{frame.f_code.co_filename}:{frame.f_lineno}: bytecode: \n{bytecode.dis()}"
267-
)
268+
if DEBUG:
269+
LOGGER.debug(
270+
f"{frame.f_code.co_filename}:{frame.f_lineno}: bytecode: \n{bytecode.dis()}"
271+
)
268272

269273
instructions = list(iter(bytecode))
270274
last_instruction_index = [inst.offset for inst in instructions].index(frame.f_lasti)

‎python/tools/recorded-call-graph-metrics/src/cg_trace/cmdline.py‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,10 @@
44
def parse(args):
55
parser = argparse.ArgumentParser()
66

7+
parser.add_argument(
8+
"--debug", action="store_true", default=False, help="Enable debug logging"
9+
)
10+
711
parser.add_argument("--xml")
812

913
parser.add_argument(

‎python/tools/recorded-call-graph-metrics/src/cg_trace/main.py‎

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@
66
from datetime import datetime
77
from io import StringIO
88

9-
from cg_trace import __version__, cmdline, tracer
9+
from cg_trace import __version__, cmdline, settings, tracer
1010
from cg_trace.exporter import XMLExporter
1111

1212

@@ -31,18 +31,17 @@ def record_calls(code, globals):
3131
return all_calls_sorted, captured_stdout, captured_stderr, exit_status
3232

3333

34-
def setup_logging():
34+
def setup_logging(debug):
3535
# code we run can also set up logging, so we need to set the level directly on our
3636
# own pacakge
3737
sh = logging.StreamHandler(stream=sys.stderr)
3838

3939
pkg_logger = logging.getLogger("cg_trace")
4040
pkg_logger.addHandler(sh)
41-
pkg_logger.setLevel(logging.INFO)
41+
pkg_logger.setLevel(logging.CRITICAL if debug else logging.INFO)
4242

4343

4444
def main(args=None) -> int:
45-
setup_logging()
4645

4746
# from . import bytecode_reconstructor
4847
# logging.getLogger(bytecode_reconstructor.__name__).setLevel(logging.INFO)
@@ -53,6 +52,9 @@ def main(args=None) -> int:
5352

5453
opts = cmdline.parse(args)
5554

55+
settings.DEBUG = opts.debug
56+
setup_logging(opts.debug)
57+
5658
# These details of setting up the program to be run is very much inspired by `trace`
5759
# from the standard library
5860
if opts.module:

‎python/tools/recorded-call-graph-metrics/src/cg_trace/settings.py‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
# Whether to run the call graph tracer with debugging enabled. Turning off
2+
# `if DEBUG: LOGGER.debug()` code completely yielded massive performance improvements.
3+
DEBUG = False
4+
5+
6+
FAIL_ON_UNKNOWN_BYTECODE = False

‎python/tools/recorded-call-graph-metrics/src/cg_trace/tracer.py‎

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
from typing import Any, Optional, Tuple
77

88
from cg_trace.bytecode_reconstructor import BytecodeExpr, expr_from_frame
9+
from cg_trace.settings import DEBUG
910
from cg_trace.utils import better_compare_for_dataclass
1011

1112
LOGGER = logging.getLogger(__name__)
@@ -233,7 +234,8 @@ def profilefunc(self, frame: FrameType, event: str, arg):
233234
if event not in ["call", "c_call"]:
234235
return
235236

236-
LOGGER.debug(f"profilefunc event={event}")
237+
if DEBUG:
238+
LOGGER.debug(f"profilefunc event={event}")
237239
if event == "call":
238240
# in call, the `frame` argument is new the frame for entering the callee
239241
assert frame.f_back is not None
@@ -242,10 +244,12 @@ def profilefunc(self, frame: FrameType, event: str, arg):
242244

243245
key = (Call.hash_key(frame.f_back), callee)
244246
if key in self.python_calls:
245-
LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}")
247+
if DEBUG:
248+
LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}")
246249
return
247250

248-
LOGGER.debug(f"callee={callee}")
251+
if DEBUG:
252+
LOGGER.debug(f"callee={callee}")
249253
call = Call.from_frame(frame.f_back)
250254

251255
self.python_calls[key] = (call, callee)
@@ -258,12 +262,15 @@ def profilefunc(self, frame: FrameType, event: str, arg):
258262

259263
key = (Call.hash_key(frame), callee)
260264
if key in self.external_calls:
261-
LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}")
265+
if DEBUG:
266+
LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}")
262267
return
263268

264-
LOGGER.debug(f"callee={callee}")
269+
if DEBUG:
270+
LOGGER.debug(f"callee={callee}")
265271
call = Call.from_frame(frame)
266272

267273
self.external_calls[key] = (call, callee)
268274

269-
LOGGER.debug(f"{call} --> {callee}")
275+
if DEBUG:
276+
LOGGER.debug(f"{call} --> {callee}")

0 commit comments

Comments
 (0)
Back | FazBrowse Home | New Git URL