From 3ead2e3dc714ec0dfa0e7e9042a451d56df43175 Mon Sep 17 00:00:00 2001 From: Rasmus Wriedt Larsen Date: Thu, 23 Jul 2020 20:14:49 +0200 Subject: [PATCH] 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 --- .../src/cg_trace/bytecode_reconstructor.py | 40 ++++++++++--------- .../src/cg_trace/cmdline.py | 4 ++ .../src/cg_trace/main.py | 10 +++-- .../src/cg_trace/settings.py | 6 +++ .../src/cg_trace/tracer.py | 19 ++++++--- 5 files changed, 51 insertions(+), 28 deletions(-) create mode 100644 python/tools/recorded-call-graph-metrics/src/cg_trace/settings.py diff --git a/python/tools/recorded-call-graph-metrics/src/cg_trace/bytecode_reconstructor.py b/python/tools/recorded-call-graph-metrics/src/cg_trace/bytecode_reconstructor.py index 018d13f8d2b..4e22696b04c 100644 --- a/python/tools/recorded-call-graph-metrics/src/cg_trace/bytecode_reconstructor.py +++ b/python/tools/recorded-call-graph-metrics/src/cg_trace/bytecode_reconstructor.py @@ -5,6 +5,7 @@ from dis import Instruction from types import FrameType from typing import Any, List +from cg_trace.settings import DEBUG, FAIL_ON_UNKNOWN_BYTECODE from cg_trace.utils import better_compare_for_dataclass LOGGER = logging.getLogger(__name__) @@ -155,9 +156,10 @@ def expr_that_added_elem_to_stack( immediately. (since correctly process the bytecode when faced with jumps is not as straight forward). """ - LOGGER.debug( - f"find_inst_that_added_elem_to_stack start_index={start_index} stack_pos={stack_pos}" - ) + if DEBUG: + LOGGER.debug( + f"find_inst_that_added_elem_to_stack start_index={start_index} stack_pos={stack_pos}" + ) assert stack_pos >= 0 for inst in reversed(instructions[: start_index + 1]): # Return immediately if faced with a jump @@ -165,13 +167,15 @@ def expr_that_added_elem_to_stack( return SomethingInvolvingScaryBytecodeJump(inst.opname) if stack_pos == 0: - LOGGER.debug(f"Found it: {inst}") + if DEBUG: + LOGGER.debug(f"Found it: {inst}") found_index = instructions.index(inst) break old = stack_pos stack_pos -= dis.stack_effect(inst.opcode, inst.arg) new = stack_pos - LOGGER.debug(f"Skipping ({old} -> {new}) {inst}") + if DEBUG: + LOGGER.debug(f"Skipping ({old} -> {new}) {inst}") else: raise Exception("inst_index_for_stack_diff failed") @@ -181,7 +185,8 @@ def expr_that_added_elem_to_stack( def expr_from_instruction(instructions: List[Instruction], index: int) -> BytecodeExpr: inst = instructions[index] - LOGGER.debug(f"expr_from_instruction: {inst} index={index}") + if DEBUG: + LOGGER.debug(f"expr_from_instruction: {inst} index={index}") if inst.opname in ["LOAD_GLOBAL", "LOAD_FAST", "LOAD_NAME", "LOAD_DEREF"]: return BytecodeVariableName(inst.argval) @@ -247,24 +252,23 @@ def expr_from_instruction(instructions: List[Instruction], index: int) -> Byteco # - LOAD_BUILD_CLASS: Called when constructing a class. # - IMPORT_NAME: Observed to result in a call to filename='', linenum=389, funcname='parent' - if inst.opname not in ["LOAD_BUILD_CLASS", "IMPORT_NAME"] + WITH_OPNAMES: - LOGGER.warning( - f"Don't know how to handle this type of instruction: {inst.opname}" - ) - # Uncomment to stop execution when encountering non-ignored unknown instruction - # class MyBytecodeException(BaseException): - # pass - # - # raise MyBytecodeException() + if FAIL_ON_UNKNOWN_BYTECODE: + if inst.opname not in ["LOAD_BUILD_CLASS", "IMPORT_NAME"] + WITH_OPNAMES: + LOGGER.warning( + f"Don't know how to handle this type of instruction: {inst.opname}" + ) + raise BaseException() + return BytecodeUnknown(inst.opname) def expr_from_frame(frame: FrameType) -> BytecodeExpr: bytecode = dis.Bytecode(frame.f_code, current_offset=frame.f_lasti) - LOGGER.debug( - f"{frame.f_code.co_filename}:{frame.f_lineno}: bytecode: \n{bytecode.dis()}" - ) + if DEBUG: + LOGGER.debug( + f"{frame.f_code.co_filename}:{frame.f_lineno}: bytecode: \n{bytecode.dis()}" + ) instructions = list(iter(bytecode)) last_instruction_index = [inst.offset for inst in instructions].index(frame.f_lasti) diff --git a/python/tools/recorded-call-graph-metrics/src/cg_trace/cmdline.py b/python/tools/recorded-call-graph-metrics/src/cg_trace/cmdline.py index d17328638dc..8e909367c32 100644 --- a/python/tools/recorded-call-graph-metrics/src/cg_trace/cmdline.py +++ b/python/tools/recorded-call-graph-metrics/src/cg_trace/cmdline.py @@ -4,6 +4,10 @@ import argparse def parse(args): parser = argparse.ArgumentParser() + parser.add_argument( + "--debug", action="store_true", default=False, help="Enable debug logging" + ) + parser.add_argument("--xml") parser.add_argument( diff --git a/python/tools/recorded-call-graph-metrics/src/cg_trace/main.py b/python/tools/recorded-call-graph-metrics/src/cg_trace/main.py index 5f5a7881500..51ba2cf8a0a 100644 --- a/python/tools/recorded-call-graph-metrics/src/cg_trace/main.py +++ b/python/tools/recorded-call-graph-metrics/src/cg_trace/main.py @@ -6,7 +6,7 @@ import time from datetime import datetime from io import StringIO -from cg_trace import __version__, cmdline, tracer +from cg_trace import __version__, cmdline, settings, tracer from cg_trace.exporter import XMLExporter @@ -31,18 +31,17 @@ def record_calls(code, globals): return all_calls_sorted, captured_stdout, captured_stderr, exit_status -def setup_logging(): +def setup_logging(debug): # code we run can also set up logging, so we need to set the level directly on our # own pacakge sh = logging.StreamHandler(stream=sys.stderr) pkg_logger = logging.getLogger("cg_trace") pkg_logger.addHandler(sh) - pkg_logger.setLevel(logging.INFO) + pkg_logger.setLevel(logging.CRITICAL if debug else logging.INFO) def main(args=None) -> int: - setup_logging() # from . import bytecode_reconstructor # logging.getLogger(bytecode_reconstructor.__name__).setLevel(logging.INFO) @@ -53,6 +52,9 @@ def main(args=None) -> int: opts = cmdline.parse(args) + settings.DEBUG = opts.debug + setup_logging(opts.debug) + # These details of setting up the program to be run is very much inspired by `trace` # from the standard library if opts.module: diff --git a/python/tools/recorded-call-graph-metrics/src/cg_trace/settings.py b/python/tools/recorded-call-graph-metrics/src/cg_trace/settings.py new file mode 100644 index 00000000000..d69476b1c41 --- /dev/null +++ b/python/tools/recorded-call-graph-metrics/src/cg_trace/settings.py @@ -0,0 +1,6 @@ +# Whether to run the call graph tracer with debugging enabled. Turning off +# `if DEBUG: LOGGER.debug()` code completely yielded massive performance improvements. +DEBUG = False + + +FAIL_ON_UNKNOWN_BYTECODE = False diff --git a/python/tools/recorded-call-graph-metrics/src/cg_trace/tracer.py b/python/tools/recorded-call-graph-metrics/src/cg_trace/tracer.py index c6b4f16d3a4..6f960e835be 100644 --- a/python/tools/recorded-call-graph-metrics/src/cg_trace/tracer.py +++ b/python/tools/recorded-call-graph-metrics/src/cg_trace/tracer.py @@ -6,6 +6,7 @@ from types import FrameType from typing import Any, Optional, Tuple from cg_trace.bytecode_reconstructor import BytecodeExpr, expr_from_frame +from cg_trace.settings import DEBUG from cg_trace.utils import better_compare_for_dataclass LOGGER = logging.getLogger(__name__) @@ -233,7 +234,8 @@ class CallGraphTracer: if event not in ["call", "c_call"]: return - LOGGER.debug(f"profilefunc event={event}") + if DEBUG: + LOGGER.debug(f"profilefunc event={event}") if event == "call": # in call, the `frame` argument is new the frame for entering the callee assert frame.f_back is not None @@ -242,10 +244,12 @@ class CallGraphTracer: key = (Call.hash_key(frame.f_back), callee) if key in self.python_calls: - LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}") + if DEBUG: + LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}") return - LOGGER.debug(f"callee={callee}") + if DEBUG: + LOGGER.debug(f"callee={callee}") call = Call.from_frame(frame.f_back) self.python_calls[key] = (call, callee) @@ -258,12 +262,15 @@ class CallGraphTracer: key = (Call.hash_key(frame), callee) if key in self.external_calls: - LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}") + if DEBUG: + LOGGER.debug(f"ignoring already seen call {key[0]} --> {callee}") return - LOGGER.debug(f"callee={callee}") + if DEBUG: + LOGGER.debug(f"callee={callee}") call = Call.from_frame(frame) self.external_calls[key] = (call, callee) - LOGGER.debug(f"{call} --> {callee}") + if DEBUG: + LOGGER.debug(f"{call} --> {callee}")