implement experimental support for line tracing

CHANGES.rst

@@ -8,6 +8,9 @@ Cython Changelog
 Features added
 --------------
 
+* EXPERIMENTAL support for simple Cython code level line tracing.  Enabled by
+  the "linetrace" compiler directive.
+
 * Cython implemented functions make their argument and return type annotations
   available through the ``__annotations__`` attribute (PEP 3107).
 

Cython/Compiler/Code.py

@@ -467,6 +467,7 @@ class FunctionState(object):
     # label_counter    integer         counter for naming labels
     # in_try_finally   boolean         inside try of try...finally
     # exc_vars         (string * 3)    exception variables for reraise, or None
+    # can_trace        boolean         line tracing is supported in the current context
 
     # Not used for now, perhaps later
     def __init__(self, owner, names_taken=set()):
@@ -483,6 +484,7 @@ class FunctionState(object):
 
         self.in_try_finally = 0
         self.exc_vars = None
+        self.can_trace = False
 
         self.temps_allocated = [] # of (name, type, manage_ref, static)
         self.temps_free = {} # (type, manage_ref) -> list of free vars with same type/managed status
@@ -1494,13 +1496,16 @@ class CCodeWriter(object):
                 self.put_safe(code)
             else:
                 self.put(code)
-        self.write("\n");
+        self.write("\n")
         self.bol = 1
 
     def emit_marker(self):
-        self.write("\n");
+        self.write("\n")
         self.indent()
         self.write("/* %s */\n" % self.marker[1])
+        if self.funcstate.can_trace and self.globalstate.directives['linetrace']:
+            self.indent()
+            self.write('__Pyx_TraceLine(%d)\n' % self.marker[0])
         self.last_marker_line = self.marker[0]
         self.marker = None
 
@@ -1966,10 +1971,10 @@ class CCodeWriter(object):
         self.putln('__Pyx_AddTraceback("%s", %s, %s, %s);' % format_tuple)
 
     def put_trace_declarations(self):
-        self.putln('__Pyx_TraceDeclarations');
+        self.putln('__Pyx_TraceDeclarations')
 
     def put_trace_call(self, name, pos):
-        self.putln('__Pyx_TraceCall("%s", %s[%s], %s);' % (name, Naming.filetable_cname, self.lookup_filename(pos[0]), pos[1]));
+        self.putln('__Pyx_TraceCall("%s", %s[%s], %s);' % (name, Naming.filetable_cname, self.lookup_filename(pos[0]), pos[1]))
 
     def put_trace_exception(self):
         self.putln("__Pyx_TraceException();")

Cython/Compiler/Nodes.py

@@ -1537,10 +1537,11 @@ class FuncDefNode(StatNode, BlockNode):
         preprocessor_guard = self.get_preprocessor_guard()
 
         profile = code.globalstate.directives['profile']
-        if profile and lenv.nogil:
+        linetrace = code.globalstate.directives['linetrace']
+        if (linetrace or profile) and lenv.nogil:
             warning(self.pos, "Cannot profile nogil function.", 1)
-            profile = False
-        if profile:
+            profile = linetrace = False
+        if profile or linetrace:
             code.globalstate.use_utility_code(
                 UtilityCode.load_cached("Profile", "Profile.c"))
 
@@ -1601,7 +1602,7 @@ class FuncDefNode(StatNode, BlockNode):
         tempvardecl_code = code.insertion_point()
         self.generate_keyword_list(code)
 
-        if profile:
+        if profile or linetrace:
             code.put_trace_declarations()
 
         # ----- Extern library function declarations
@@ -1616,7 +1617,7 @@ class FuncDefNode(StatNode, BlockNode):
         # Profiling or closures are not currently possible for cdef nogil
         # functions, but check them anyway
         have_object_args = (self.needs_closure or self.needs_outer_scope or
-                            profile)
+                            profile or linetrace)
         for arg in lenv.arg_entries:
             if arg.type.is_pyobject:
                 have_object_args = True
@@ -1690,10 +1691,11 @@ class FuncDefNode(StatNode, BlockNode):
                 code.put_incref(outer_scope_cname, cenv.scope_class.type)
                 code.put_giveref(outer_scope_cname)
         # ----- Trace function call
-        if profile:
+        if profile or linetrace:
             # this looks a bit late, but if we don't get here due to a
             # fatal error before hand, it's not really worth tracing
             code.put_trace_call(self.entry.name, self.pos)
+            code.funcstate.can_trace = True
         # ----- Fetch arguments
         self.generate_argument_parsing_code(env, code)
         # If an argument is assigned to in the body, we must
@@ -1891,7 +1893,8 @@ class FuncDefNode(StatNode, BlockNode):
             code.putln("if (unlikely(%s == -1) && !PyErr_Occurred()) %s = -2;" % (
                     Naming.retval_cname, Naming.retval_cname))
 
-        if profile:
+        if profile or linetrace:
+            code.funcstate.can_trace = False
             if self.return_type.is_pyobject:
                 code.put_trace_return(Naming.retval_cname)
             else:
@@ -6542,15 +6545,21 @@ class GILStatNode(NogilTryFinallyStatNode):
         else:
             variable = None
 
+        old_trace_config = code.funcstate.can_trace
         if self.state == 'gil':
             code.put_ensure_gil(variable=variable)
+            # FIXME: not that easy, tracing may not be possible at all here
+            #code.funcstate.can_trace = True
         else:
             code.put_release_gil(variable=variable)
+            code.funcstate.can_trace = False
 
         TryFinallyStatNode.generate_execution_code(self, code)
 
         if self.state_temp:
             self.state_temp.release(code)
+
+        code.funcstate.can_trace = old_trace_config
         code.end_block()
 
 

Cython/Compiler/Options.py

@@ -90,6 +90,7 @@ directive_defaults = {
     'final' : False,
     'internal' : False,
     'profile': False,
+    'linetrace': False,
     'infer_types': None,
     'infer_types.verbose': False,
     'autotestdict': True,

Cython/Utility/Profile.c

@@ -8,11 +8,19 @@
   #define CYTHON_PROFILE 1
 #endif
 
+#ifndef CYTHON_TRACE
+  #define CYTHON_TRACE 0
+#endif
+
+#if CYTHON_TRACE
+  #undef CYTHON_PROFILE_REUSE_FRAME
+#endif
+
 #ifndef CYTHON_PROFILE_REUSE_FRAME
   #define CYTHON_PROFILE_REUSE_FRAME 0
 #endif
 
-#if CYTHON_PROFILE
+#if CYTHON_PROFILE || CYTHON_TRACE
 
   #include "compile.h"
   #include "frameobject.h"
@@ -23,7 +31,7 @@
     #define CYTHON_FRAME_DEL
   #else
     #define CYTHON_FRAME_MODIFIER
-    #define CYTHON_FRAME_DEL Py_DECREF($frame_cname)
+    #define CYTHON_FRAME_DEL Py_CLEAR($frame_cname)
   #endif
 
   #define __Pyx_TraceDeclarations                                     \
@@ -32,25 +40,40 @@
   int __Pyx_use_tracing = 0;
 
   #define __Pyx_TraceCall(funcname, srcfile, firstlineno)                            \
-  if (unlikely(PyThreadState_GET()->use_tracing && PyThreadState_GET()->c_profilefunc)) {      \
+  if (unlikely(PyThreadState_GET()->use_tracing &&                                   \
+          (PyThreadState_GET()->c_profilefunc || (CYTHON_TRACE && PyThreadState_GET()->c_tracefunc)))) {      \
       __Pyx_use_tracing = __Pyx_TraceSetupAndCall(&$frame_code_cname, &$frame_cname, funcname, srcfile, firstlineno);  \
   }
 
   #define __Pyx_TraceException()                                                           \
-  if (unlikely(__Pyx_use_tracing( && PyThreadState_GET()->use_tracing && PyThreadState_GET()->c_profilefunc) {  \
+  if (unlikely(__Pyx_use_tracing) && PyThreadState_GET()->use_tracing &&                   \
+          (PyThreadState_GET()->c_profilefunc || (CYTHON_TRACE && PyThreadState_GET()->c_tracefunc))) {  \
+      PyThreadState* tstate = PyThreadState_GET();                                         \
+      tstate->use_tracing = 0;                                                             \
       PyObject *exc_info = __Pyx_GetExceptionTuple();                                      \
       if (exc_info) {                                                                      \
-          PyThreadState_GET()->c_profilefunc(                                              \
-              PyThreadState_GET()->c_profileobj, $frame_cname, PyTrace_EXCEPTION, exc_info);  \
+          if (CYTHON_TRACE && tstate->c_tracefunc)                                         \
+              tstate->c_tracefunc(                                                         \
+                  tstate->c_traceobj, $frame_cname, PyTrace_EXCEPTION, exc_info);          \
+          tstate->c_profilefunc(                                                           \
+              tstate->c_profileobj, $frame_cname, PyTrace_EXCEPTION, exc_info);            \
           Py_DECREF(exc_info);                                                             \
       }                                                                                    \
+      tstate->use_tracing = 1;                                                             \
   }
 
   #define __Pyx_TraceReturn(result)                                                  \
-  if (unlikely(__Pyx_use_tracing) && PyThreadState_GET()->use_tracing && PyThreadState_GET()->c_profilefunc) {  \
-      PyThreadState_GET()->c_profilefunc(                                            \
-          PyThreadState_GET()->c_profileobj, $frame_cname, PyTrace_RETURN, (PyObject*)result);     \
+  if (unlikely(__Pyx_use_tracing) && PyThreadState_GET()->use_tracing) {             \
+      PyThreadState* tstate = PyThreadState_GET();                                   \
+      tstate->use_tracing = 0;                                                        \
+      if (CYTHON_TRACE && tstate->c_tracefunc)                                       \
+          tstate->c_tracefunc(                                                       \
+              tstate->c_traceobj, $frame_cname, PyTrace_RETURN, (PyObject*)result);  \
+      if (tstate->c_profilefunc)                                                     \
+          tstate->c_profilefunc(                                                     \
+              tstate->c_profileobj, $frame_cname, PyTrace_RETURN, (PyObject*)result);  \
       CYTHON_FRAME_DEL;                                                              \
+      tstate->use_tracing = 1;                                                       \
   }
 
   static PyCodeObject *__Pyx_createFrameCodeObject(const char *funcname, const char *srcfile, int firstlineno); /*proto*/
@@ -65,6 +88,19 @@
 
 #endif /* CYTHON_PROFILE */
 
+#if CYTHON_TRACE
+  #define __Pyx_TraceLine(lineno)                                                          \
+  if (unlikely(__Pyx_use_tracing) && unlikely(PyThreadState_GET()->use_tracing && PyThreadState_GET()->c_tracefunc)) {    \
+      PyThreadState* tstate = PyThreadState_GET();                                         \
+      $frame_cname->f_lineno = lineno;                                                     \
+      tstate->use_tracing = 0;                                                             \
+      tstate->c_tracefunc(tstate->c_traceobj, $frame_cname, PyTrace_LINE, NULL);           \
+      tstate->use_tracing = 1;                                                             \
+  }
+#else
+  #define __Pyx_TraceLine(lineno)
+#endif
+
 /////////////// Profile ///////////////
 //@substitute: naming
 
@@ -75,23 +111,41 @@ static int __Pyx_TraceSetupAndCall(PyCodeObject** code,
                                    const char *funcname,
                                    const char *srcfile,
                                    int firstlineno) {
+    int retval;
+    PyThreadState* tstate = PyThreadState_GET();
     if (*frame == NULL || !CYTHON_PROFILE_REUSE_FRAME) {
         if (*code == NULL) {
             *code = __Pyx_createFrameCodeObject(funcname, srcfile, firstlineno);
             if (*code == NULL) return 0;
         }
         *frame = PyFrame_New(
-            PyThreadState_GET(),             /*PyThreadState *tstate*/
+            tstate,                          /*PyThreadState *tstate*/
             *code,                           /*PyCodeObject *code*/
             $moddict_cname,                  /*PyObject *globals*/
             0                                /*PyObject *locals*/
         );
         if (*frame == NULL) return 0;
+        if (CYTHON_TRACE && (*frame)->f_trace == NULL) {
+            // this enables "f_lineno" lookup, at least in CPython ...
+            Py_INCREF(Py_None);
+            (*frame)->f_trace = Py_None;
         }
-    else {
-        (*frame)->f_tstate = PyThreadState_GET();
+    } else {
+        (*frame)->f_tstate = tstate;
     }
-    return PyThreadState_GET()->c_profilefunc(PyThreadState_GET()->c_profileobj, *frame, PyTrace_CALL, NULL) == 0;
+    (*frame)->f_lineno = firstlineno;
+    tstate->use_tracing = 0;
+    #if CYTHON_TRACE
+    if (tstate->c_tracefunc)
+        tstate->c_tracefunc(tstate->c_traceobj, *frame, PyTrace_CALL, NULL);
+    if (!tstate->c_profilefunc)
+        retval = 1;
+    else
+    #endif
+        retval = tstate->c_profilefunc(tstate->c_profileobj, *frame, PyTrace_CALL, NULL) == 0;
+    tstate->use_tracing = (tstate->c_profilefunc ||
+                           (CYTHON_TRACE && tstate->c_tracefunc));
+    return tstate->use_tracing && retval;
 }
 
 static PyCodeObject *__Pyx_createFrameCodeObject(const char *funcname, const char *srcfile, int firstlineno) {

docs/src/reference/compilation.rst

@@ -194,6 +194,13 @@ Cython code.  Here is the list of currently supported directives:
     Add hooks for Python profilers into the compiled C code.  Default
     is False.
 
+``linetrace`` (True / False)
+    Add line tracing hooks for Python profilers into the compiled C code.
+    This also enables profiling.  Default is False.  Note that the
+    generated module will not actually use line tracing, unless you
+    additionally pass the C macro definition ``CYTHON_TRACE=1`` to the
+    C compiler (e.g. using the distutils option ``define_macros``).
+
 ``infer_types`` (True / False)
     Infer types of untyped variables in function bodies. Default is
     None, indicating that on safe (semantically-unchanging) inferences

runtests.py

@@ -104,6 +104,10 @@ def unpatch_inspect_isfunction():
     else:
         inspect.isfunction = orig_isfunction
 
+def update_linetrace_extension(ext):
+    ext.define_macros.append(('CYTHON_TRACE', 1))
+    return ext
+
 def update_numpy_extension(ext):
     import numpy
     ext.include_dirs.append(numpy.get_include())
@@ -186,6 +190,7 @@ EXCLUDE_EXT = object()
 EXT_EXTRAS = {
     'tag:numpy' : update_numpy_extension,
     'tag:openmp': update_openmp_extension,
+    'tag:trace':  update_linetrace_extension,
 }
 
 # TODO: use tags

tests/run/line_trace.pyx

+# cython: linetrace=True
+# mode: run
+# tag: trace
+
+from cpython.ref cimport PyObject
+
+from cpython.pystate cimport (
+    Py_tracefunc, PyFrameObject,
+    PyTrace_CALL, PyTrace_EXCEPTION, PyTrace_LINE, PyTrace_RETURN,
+    PyTrace_C_CALL, PyTrace_C_EXCEPTION, PyTrace_C_RETURN)
+
+cdef extern from *:
+    void PyEval_SetProfile(Py_tracefunc cfunc, object obj)
+    void PyEval_SetTrace(Py_tracefunc cfunc, object obj)
+
+
+map_trace_types = {
+    PyTrace_CALL:        'call',
+    PyTrace_EXCEPTION:   'exc',
+    PyTrace_LINE:        'line',
+    PyTrace_RETURN:      'return',
+    PyTrace_C_CALL:      'ccall',
+    PyTrace_C_EXCEPTION: 'cexc',
+    PyTrace_C_RETURN:    'cret',
+}.get
+
+
+cdef int _trace_func(PyObject* _traceobj, PyFrameObject* _frame, int what, PyObject* arg) except -1:
+    frame, traceobj = <object>_frame, <object>_traceobj
+    traceobj.append((map_trace_types(what), frame.f_lineno - frame.f_code.co_firstlineno))
+    return 0
+
+
+def cy_add(a,b):
+    x = a + b
+    return x
+
+
+def cy_add_nogil(a,b):
+    cdef int z, x=a, y=b
+    with nogil:    # no traces in this block !
+        z = 0
+        z += x + y
+    return z
+
+
+def run_trace(func, *args):
+    """
+    >>> def py_add(a,b):
+    ...     x = a+b
+    ...     return x
+    >>> run_trace(py_add, 1, 2)
+    [('call', 0), ('line', 1), ('line', 2), ('return', 2)]
+    >>> run_trace(cy_add, 1, 2)
+    [('call', 0), ('line', 1), ('line', 2), ('return', 2)]
+    >>> run_trace(cy_add_nogil, 1, 2)
+    [('call', 0), ('line', 1), ('line', 2), ('line', 5), ('return', 5)]
+    """
+    trace = []
+    PyEval_SetTrace(<Py_tracefunc>_trace_func, trace)
+    try:
+        func(*args)
+    finally:
+        PyEval_SetTrace(NULL, None)
+    return trace