[mypyc] Implement optional tracing of ops
If mypyc.irbuild.ll_builder.TRACING is set to True, print information
about ops being executed to stdout while the compiled program is run.
This can be useful for debugging and performance analysis.
Only those ops generated in the main irbuild pass which have a line
number will be included in the trace. This seems sufficient to make
this feature useful, but it may make sense to include additional ops
in the future.
I've already used this to successfully fix a tricky code generation
bug.
Example trace from a simple program (it prints `hello` and appends
to a list):
```
[trace] t:9::Call(bar)
[trace] t:6:bar:CallC(CPyObject_GetAttr)
[trace] t:6:bar:CallC(_PyObject_Vectorcall)
hello
[trace] t:7:bar:Call(foo)
[trace] t:2:foo:CallC(PyList_New)
[trace] t:3:foo:CallC(PyList_Append)
[trace] t:3:foo:ComparisonOp
```
diff --git a/mypyc/irbuild/builder.py b/mypyc/irbuild/builder.py
index 57baa8d..b93179e 100644
--- a/mypyc/irbuild/builder.py
+++ b/mypyc/irbuild/builder.py
@@ -89,7 +89,7 @@
visitor: IRVisitor,
options: CompilerOptions,
singledispatch_impls: Dict[FuncDef, List[RegisterImplInfo]]) -> None:
- self.builder = LowLevelIRBuilder(current_module, mapper, options)
+ self.builder = LowLevelIRBuilder(current_module, '', mapper, options)
self.builders = [self.builder]
self.symtables: List[OrderedDict[SymbolNode, SymbolTarget]] = [OrderedDict()]
self.runtime_args: List[List[RuntimeArg]] = [[]]
@@ -981,7 +981,8 @@
def enter(self, fn_info: Union[FuncInfo, str] = '') -> None:
if isinstance(fn_info, str):
fn_info = FuncInfo(name=fn_info)
- self.builder = LowLevelIRBuilder(self.current_module, self.mapper, self.options)
+ self.builder = LowLevelIRBuilder(self.current_module, fn_info.name, self.mapper,
+ self.options)
self.builders.append(self.builder)
self.symtables.append(OrderedDict())
self.runtime_args.append([])
diff --git a/mypyc/irbuild/ll_builder.py b/mypyc/irbuild/ll_builder.py
index 98a69d9..779830f 100644
--- a/mypyc/irbuild/ll_builder.py
+++ b/mypyc/irbuild/ll_builder.py
@@ -22,7 +22,7 @@
from mypyc.ir.ops import (
BasicBlock, Op, Integer, Value, Register, Assign, Branch, Goto, Call, Box, Unbox, Cast,
GetAttr, LoadStatic, MethodCall, CallC, Truncate, LoadLiteral, AssignMulti,
- RaiseStandardError, Unreachable, LoadErrorValue,
+ RaiseStandardError, Unreachable, LoadErrorValue, SetAttr,
NAMESPACE_TYPE, NAMESPACE_MODULE, NAMESPACE_STATIC, IntOp, GetElementPtr,
LoadMem, ComparisonOp, LoadAddress, TupleGet, KeepAlive, ERR_NEVER, ERR_FALSE, SetMem
)
@@ -62,7 +62,7 @@
generic_len_op, generic_ssize_t_len_op
)
from mypyc.primitives.misc_ops import (
- none_object_op, fast_isinstance_op, bool_op
+ none_object_op, fast_isinstance_op, bool_op, trace_op
)
from mypyc.primitives.int_ops import int_comparison_op_mapping
from mypyc.primitives.exc_ops import err_occurred_op, keep_propagating_op
@@ -90,15 +90,20 @@
# From CPython
PY_VECTORCALL_ARGUMENTS_OFFSET: Final = 1 << (PLATFORM_SIZE * 8 - 1)
+# If True, print information about ops being executed to stdout
+TRACING: Final = False
+
class LowLevelIRBuilder:
def __init__(
self,
current_module: str,
+ current_function: str,
mapper: Mapper,
options: CompilerOptions,
) -> None:
self.current_module = current_module
+ self.current_function = current_function
self.mapper = mapper
self.options = options
self.args: List[Register] = []
@@ -111,6 +116,7 @@
def add(self, op: Op) -> Value:
"""Add an op."""
assert not self.blocks[-1].terminated, "Can't add to finished block"
+ self.trace(op)
self.blocks[-1].ops.append(op)
return op
@@ -796,6 +802,10 @@
else:
return Integer(value)
+ def load_int_object(self, value: int) -> Value:
+ """Load an int as a PyObject * (Python integer)."""
+ return self.add(LoadLiteral(value, object_rprimitive))
+
def load_float(self, value: float) -> Value:
"""Load a float literal value."""
return self.add(LoadLiteral(value, float_rprimitive))
@@ -1417,6 +1427,20 @@
"""
return self.call_c(new_tuple_with_length_op, [length], line)
+ # Debugging helpers
+
+ def trace(self, op: Op) -> None:
+ """Print debugging tracing information to stdout (disabled by default)."""
+ if TRACING and op.line >= 0:
+ func = self.current_function
+ if func == '<top level>':
+ func = ''
+ self.call_c(trace_op, [self.load_str(self.current_module),
+ self.load_str(func),
+ self.load_int_object(op.line),
+ self.load_str(trace_op_description(op))],
+ -1)
+
# Internal helpers
def decompose_union_helper(self,
@@ -1582,3 +1606,17 @@
if kind == ARG_POS:
num_pos += 1
return num_pos
+
+
+def trace_op_description(op: Op) -> str:
+ """Return a simple description of an Op usable for tracing execution."""
+ s = type(op).__name__
+ if isinstance(op, CallC):
+ return f"{s}({op.function_name})"
+ if isinstance(op, (GetAttr, SetAttr)):
+ return f"{s}({op.attr})"
+ if isinstance(op, Call):
+ return f"{s}({op.fn.name})"
+ if isinstance(op, MethodCall):
+ return f"{s}({op.method})"
+ return s
diff --git a/mypyc/lib-rt/CPy.h b/mypyc/lib-rt/CPy.h
index 4c0f91a..1a9e4c6 100644
--- a/mypyc/lib-rt/CPy.h
+++ b/mypyc/lib-rt/CPy.h
@@ -589,6 +589,8 @@
PyObject *CPySingledispatch_RegisterFunction(PyObject *singledispatch_func, PyObject *cls,
PyObject *func);
+
+void CPy_Trace(PyObject *module, PyObject *func, PyObject *line, PyObject *opname);
#ifdef __cplusplus
}
#endif
diff --git a/mypyc/lib-rt/misc_ops.c b/mypyc/lib-rt/misc_ops.c
index dcce89d..1ff29c2 100644
--- a/mypyc/lib-rt/misc_ops.c
+++ b/mypyc/lib-rt/misc_ops.c
@@ -783,3 +783,9 @@
return NULL;
}
+
+void CPy_Trace(PyObject *module, PyObject *func, PyObject *line, PyObject *opname) {
+ PyObject *output = PyUnicode_FromFormat("[trace] %S:%S:%S:%S", module, line, func, opname);
+ const char *cstr = PyUnicode_AsUTF8(output);
+ puts(cstr);
+}
diff --git a/mypyc/primitives/misc_ops.py b/mypyc/primitives/misc_ops.py
index cfdbb8a..cc3b2c4 100644
--- a/mypyc/primitives/misc_ops.py
+++ b/mypyc/primitives/misc_ops.py
@@ -4,7 +4,7 @@
from mypyc.ir.rtypes import (
bool_rprimitive, object_rprimitive, str_rprimitive, object_pointer_rprimitive,
int_rprimitive, dict_rprimitive, c_int_rprimitive, bit_rprimitive, c_pyssize_t_rprimitive,
- list_rprimitive,
+ list_rprimitive, void_rtype
)
from mypyc.primitives.registry import (
function_op, custom_op, load_address_op, ERR_NEG_INT
@@ -223,3 +223,11 @@
c_function_name='CPySingledispatch_RegisterFunction',
error_kind=ERR_MAGIC,
)
+
+# Used for tracing the op being executed
+trace_op = custom_op(
+ arg_types=[str_rprimitive, str_rprimitive, object_rprimitive, str_rprimitive],
+ return_type=void_rtype,
+ c_function_name='CPy_Trace',
+ error_kind=ERR_NEVER,
+)
