Codex/update function entry/return interfaces

Doc/howto/instrumentation.rst

@@ -274,14 +274,14 @@ should instead read:
 Available static markers
 ------------------------
 
-.. object:: function__entry(str filename, str funcname, int lineno)
+.. object:: function__entry(str filename, str funcname, int lineno, str modulename)
 
    This marker indicates that execution of a Python function has begun.
    It is only triggered for pure-Python (bytecode) functions.
 
-   The filename, function name, and line number are provided back to the
-   tracing script as positional arguments, which must be accessed using
-   ``$arg1``, ``$arg2``, ``$arg3``:
+   The filename, function name, line number, and module name are provided back
+   to the tracing script as positional arguments, which must be accessed using
+   ``$arg1``, ``$arg2``, ``$arg3``, ``$arg4``:
 
        * ``$arg1`` : ``(const char *)`` filename, accessible using ``user_string($arg1)``
 
@@ -290,21 +290,38 @@ Available static markers
 
        * ``$arg3`` : ``int`` line number
 
-.. object:: function__return(str filename, str funcname, int lineno)
+       * ``$arg4`` : ``(const char *)`` module name
+
+.. object:: function__return(str filename, str funcname, int lineno, str modulename)
 
    This marker is the converse of :c:func:`function__entry`, and indicates that
    execution of a Python function has ended (either via ``return``, or via an
    exception).  It is only triggered for pure-Python (bytecode) functions.
 
    The arguments are the same as for :c:func:`function__entry`
 
+.. object:: cfunction__entry(str filename, str funcname, int lineno, str modulename)
+
+   This marker indicates that execution of a built-in or extension function has
+   begun. The filename and line number refer to the Python call site, while the
+   module name and function name identify the C callable. The module name may
+   be empty when the function is not associated with a particular module.
+
+.. object:: cfunction__return(str filename, str funcname, int lineno, str modulename)
+
+   This marker is the converse of :c:func:`cfunction__entry`, and indicates that
+   execution of a built-in or extension function has ended. The arguments are
+   the same as for :c:func:`cfunction__entry`.
+
 .. object:: line(str filename, str funcname, int lineno)
 
    This marker indicates a Python line is about to be executed.  It is
    the equivalent of line-by-line tracing with a Python profiler.  It is
    not triggered within C functions.
 
-   The arguments are the same as for :c:func:`function__entry`.
+   The arguments are the filename, function name, and line number for the
+   executing frame (the same as the first three arguments to
+   :c:func:`function__entry`).
 
 .. object:: gc__start(int generation)
 

Include/pydtrace.d

@@ -1,8 +1,10 @@
 /* Python DTrace provider */
 
 provider python {
-    probe function__entry(const char *, const char *, int);
-    probe function__return(const char *, const char *, int);
+    probe function__entry(const char *, const char *, int, const char *);
+    probe function__return(const char *, const char *, int, const char *);
+    probe cfunction__entry(const char *, const char *, int, const char *);
+    probe cfunction__return(const char *, const char *, int, const char *);
     probe instance__new__start(const char *, const char *);
     probe instance__new__done(const char *, const char *);
     probe instance__delete__start(const char *, const char *);

Include/pydtrace.h

@@ -18,29 +18,33 @@ extern "C" {
    check to minimize performance impact when probing is off. For example:
 
        if (PyDTrace_FUNCTION_ENTRY_ENABLED())
-           PyDTrace_FUNCTION_ENTRY(f);
+           PyDTrace_FUNCTION_ENTRY(filename, funcname, lineno, modulename);
 */
 
 #else
 
 /* Without DTrace, compile to nothing. */
 
 static inline void PyDTrace_LINE(const char *arg0, const char *arg1, int arg2) {}
-static inline void PyDTrace_FUNCTION_ENTRY(const char *arg0, const char *arg1, int arg2)  {}
-static inline void PyDTrace_FUNCTION_RETURN(const char *arg0, const char *arg1, int arg2) {}
+static inline void PyDTrace_FUNCTION_ENTRY(const char *arg0, const char *arg1, int arg2, const char *arg3)  {}
+static inline void PyDTrace_FUNCTION_RETURN(const char *arg0, const char *arg1, int arg2, const char *arg3) {}
+static inline void PyDTrace_CFUNCTION_ENTRY(const char *arg0, const char *arg1, int arg2, const char *arg3) {}
+static inline void PyDTrace_CFUNCTION_RETURN(const char *arg0, const char *arg1, int arg2, const char *arg3) {}
 static inline void PyDTrace_GC_START(int arg0) {}
 static inline void PyDTrace_GC_DONE(Py_ssize_t arg0) {}
-static inline void PyDTrace_INSTANCE_NEW_START(int arg0) {}
-static inline void PyDTrace_INSTANCE_NEW_DONE(int arg0) {}
-static inline void PyDTrace_INSTANCE_DELETE_START(int arg0) {}
-static inline void PyDTrace_INSTANCE_DELETE_DONE(int arg0) {}
+static inline void PyDTrace_INSTANCE_NEW_START(const char *arg0, const char *arg1) {}
+static inline void PyDTrace_INSTANCE_NEW_DONE(const char *arg0, const char *arg1) {}
+static inline void PyDTrace_INSTANCE_DELETE_START(const char *arg0, const char *arg1) {}
+static inline void PyDTrace_INSTANCE_DELETE_DONE(const char *arg0, const char *arg1) {}
 static inline void PyDTrace_IMPORT_FIND_LOAD_START(const char *arg0) {}
 static inline void PyDTrace_IMPORT_FIND_LOAD_DONE(const char *arg0, int arg1) {}
 static inline void PyDTrace_AUDIT(const char *arg0, void *arg1) {}
 
 static inline int PyDTrace_LINE_ENABLED(void) { return 0; }
 static inline int PyDTrace_FUNCTION_ENTRY_ENABLED(void) { return 0; }
 static inline int PyDTrace_FUNCTION_RETURN_ENABLED(void) { return 0; }
+static inline int PyDTrace_CFUNCTION_ENTRY_ENABLED(void) { return 0; }
+static inline int PyDTrace_CFUNCTION_RETURN_ENABLED(void) { return 0; }
 static inline int PyDTrace_GC_START_ENABLED(void) { return 0; }
 static inline int PyDTrace_GC_DONE_ENABLED(void) { return 0; }
 static inline int PyDTrace_INSTANCE_NEW_START_ENABLED(void) { return 0; }

Lib/test/dtracedata/assert_usable.bt

@@ -0,0 +1 @@
+BEGIN { printf("probe: success\n"); exit(); }

Lib/test/dtracedata/call_stack.bt

@@ -0,0 +1,29 @@
+@seq = 0;
+
+usdt:@TARGET@:python:function__entry /str(args->arg1) == "start"/ {
+    @trace[tid] = 1;
+    @indent[tid] = 0;
+}
+
+usdt:@TARGET@:python:function__entry /@trace[tid]/ {
+    @seq += 1;
+    printf("%d\t%15s:", (int)@seq, "function-entry");
+    printf("%*s", @indent[tid], "");
+    printf("%s:%s:%d:%s\n", str(args->arg0), str(args->arg1), args->arg2,
+           str(args->arg3));
+    @indent[tid] = @indent[tid] + 1;
+}
+
+usdt:@TARGET@:python:function__return /@trace[tid]/ {
+    @indent[tid] = @indent[tid] - 1;
+    @seq += 1;
+    printf("%d\t%15s:", (int)@seq, "function-return");
+    printf("%*s", @indent[tid], "");
+    printf("%s:%s:%d:%s\n", str(args->arg0), str(args->arg1), args->arg2,
+           str(args->arg3));
+}
+
+usdt:@TARGET@:python:function__return /str(args->arg1) == "start"/ {
+    @trace[tid] = 0;
+    @indent[tid] = 0;
+}

Lib/test/dtracedata/call_stack.bt.expected

@@ -0,0 +1,18 @@
+ function-entry:call_stack.py:start:23
+ function-entry: call_stack.py:function_1:1:__main__
+ function-entry:  call_stack.py:function_3:9:__main__
+function-return:  call_stack.py:function_3:10:__main__
+function-return: call_stack.py:function_1:2:__main__
+ function-entry: call_stack.py:function_2:5:__main__
+ function-entry:  call_stack.py:function_1:1:__main__
+ function-entry:   call_stack.py:function_3:9:__main__
+function-return:   call_stack.py:function_3:10:__main__
+function-return:  call_stack.py:function_1:2:__main__
+function-return: call_stack.py:function_2:6:__main__
+ function-entry: call_stack.py:function_3:9:__main__
+function-return: call_stack.py:function_3:10:__main__
+ function-entry: call_stack.py:function_4:13:__main__
+function-return: call_stack.py:function_4:14:__main__
+ function-entry: call_stack.py:function_5:18:__main__
+function-return: call_stack.py:function_5:21:__main__
+function-return:call_stack.py:start:28:__main__

Lib/test/dtracedata/call_stack.d

@@ -11,7 +11,8 @@ python$target:::function-entry
 {
     printf("%d\t%*s:", timestamp, 15, probename);
     printf("%*s", self->indent, "");
-    printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
+    printf("%s:%s:%d:%s\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2,
+           copyinstr(arg3));
     self->indent++;
 }
 
@@ -21,7 +22,8 @@ python$target:::function-return
     self->indent--;
     printf("%d\t%*s:", timestamp, 15, probename);
     printf("%*s", self->indent, "");
-    printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
+    printf("%s:%s:%d:%s\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2,
+           copyinstr(arg3));
 }
 
 python$target:::function-return

Lib/test/dtracedata/call_stack.d.expected

@@ -1,18 +1,18 @@
- function-entry:call_stack.py:start:23
- function-entry: call_stack.py:function_1:1
- function-entry:  call_stack.py:function_3:9
-function-return:  call_stack.py:function_3:10
-function-return: call_stack.py:function_1:2
- function-entry: call_stack.py:function_2:5
- function-entry:  call_stack.py:function_1:1
- function-entry:   call_stack.py:function_3:9
-function-return:   call_stack.py:function_3:10
-function-return:  call_stack.py:function_1:2
-function-return: call_stack.py:function_2:6
- function-entry: call_stack.py:function_3:9
-function-return: call_stack.py:function_3:10
- function-entry: call_stack.py:function_4:13
-function-return: call_stack.py:function_4:14
- function-entry: call_stack.py:function_5:18
-function-return: call_stack.py:function_5:21
-function-return:call_stack.py:start:28
+ function-entry:call_stack.py:start:23:__main__
+ function-entry: call_stack.py:function_1:1:__main__
+ function-entry:  call_stack.py:function_3:9:__main__
+function-return:  call_stack.py:function_3:10:__main__
+function-return: call_stack.py:function_1:2:__main__
+ function-entry: call_stack.py:function_2:5:__main__
+ function-entry:  call_stack.py:function_1:1:__main__
+ function-entry:   call_stack.py:function_3:9:__main__
+function-return:   call_stack.py:function_3:10:__main__
+function-return:  call_stack.py:function_1:2:__main__
+function-return: call_stack.py:function_2:6:__main__
+ function-entry: call_stack.py:function_3:9:__main__
+function-return: call_stack.py:function_3:10:__main__
+ function-entry: call_stack.py:function_4:13:__main__
+function-return: call_stack.py:function_4:14:__main__
+ function-entry: call_stack.py:function_5:18:__main__
+function-return: call_stack.py:function_5:21:__main__
+function-return:call_stack.py:start:28:__main__

Lib/test/dtracedata/call_stack.stp

@@ -24,10 +24,11 @@ probe process.mark("function__entry"), process.mark("function__return")
     filename = user_string($arg1);
     funcname = user_string($arg2);
     lineno = $arg3;
+    modulename = user_string($arg4);
 
     if (tracing) {
-        printf("%d\t%s:%s:%s:%d\n", gettimeofday_us(), $$name,
-               basename(filename), funcname, lineno);
+        printf("%d\t%s:%s:%s:%d:%s\n", gettimeofday_us(), $$name,
+               basename(filename), funcname, lineno, modulename);
     }
 }
 

Lib/test/dtracedata/call_stack.stp.expected

@@ -1,14 +1,14 @@
-function__entry:call_stack.py:start:23
-function__entry:call_stack.py:function_1:1
-function__return:call_stack.py:function_1:2
-function__entry:call_stack.py:function_2:5
-function__entry:call_stack.py:function_1:1
-function__return:call_stack.py:function_1:2
-function__return:call_stack.py:function_2:6
-function__entry:call_stack.py:function_3:9
-function__return:call_stack.py:function_3:10
-function__entry:call_stack.py:function_4:13
-function__return:call_stack.py:function_4:14
-function__entry:call_stack.py:function_5:18
-function__return:call_stack.py:function_5:21
-function__return:call_stack.py:start:28
+function__entry:call_stack.py:start:23:__main__
+function__entry:call_stack.py:function_1:1:__main__
+function__return:call_stack.py:function_1:2:__main__
+function__entry:call_stack.py:function_2:5:__main__
+function__entry:call_stack.py:function_1:1:__main__
+function__return:call_stack.py:function_1:2:__main__
+function__return:call_stack.py:function_2:6:__main__
+function__entry:call_stack.py:function_3:9:__main__
+function__return:call_stack.py:function_3:10:__main__
+function__entry:call_stack.py:function_4:13:__main__
+function__return:call_stack.py:function_4:14:__main__
+function__entry:call_stack.py:function_5:18:__main__
+function__return:call_stack.py:function_5:21:__main__
+function__return:call_stack.py:start:28:__main__

Lib/test/dtracedata/cfunction.bt

@@ -0,0 +1,19 @@
+@seq = 0;
+
+usdt:@TARGET@:python:function__entry /str(args->arg1) == "start"/ { @trace[tid] = 1; }
+
+usdt:@TARGET@:python:cfunction__entry /@trace[tid]/ {
+    @seq += 1;
+    const char *module = args->arg3 ? str(args->arg3) : "";
+    printf("%d\tcfunction-entry:%s:%s:%d:%s\n", (int)@seq,
+           str(args->arg0), str(args->arg1), args->arg2, module);
+}
+
+usdt:@TARGET@:python:cfunction__return /@trace[tid]/ {
+    @seq += 1;
+    const char *module = args->arg3 ? str(args->arg3) : "";
+    printf("%d\tcfunction-return:%s:%s:%d:%s\n", (int)@seq,
+           str(args->arg0), str(args->arg1), args->arg2, module);
+}
+
+usdt:@TARGET@:python:function__return /str(args->arg1) == "start"/ { @trace[tid] = 0; }

Lib/test/dtracedata/cfunction.bt.expected

@@ -0,0 +1,6 @@
+cfunction-entry:cfunction.py:5:builtins:len
+cfunction-return:cfunction.py:5:builtins:len
+cfunction-entry:cfunction.py:6:math:sqrt
+cfunction-return:cfunction.py:6:math:sqrt
+cfunction-entry:cfunction.py:7:builtins:sum
+cfunction-return:cfunction.py:7:builtins:sum

Lib/test/dtracedata/cfunction.d

@@ -0,0 +1,22 @@
+self int tracing;
+
+python$target:::function-entry
+/copyinstr(arg1) == "start"/
+{
+    self->tracing = 1;
+}
+
+python$target:::cfunction-entry,
+python$target:::cfunction-return
+/self->tracing/
+{
+    this->module = arg3 ? copyinstr(arg3) : "";
+    printf("%d\t%s:%s:%d:%s:%s\n", timestamp, probename,
+           copyinstr(arg0), arg2, this->module, copyinstr(arg1));
+}
+
+python$target:::function-return
+/copyinstr(arg1) == "start"/
+{
+    self->tracing = 0;
+}

Lib/test/dtracedata/cfunction.d.expected

@@ -0,0 +1,6 @@
+cfunction-entry:cfunction.py:5:builtins:len
+cfunction-return:cfunction.py:5:builtins:len
+cfunction-entry:cfunction.py:6:math:sqrt
+cfunction-return:cfunction.py:6:math:sqrt
+cfunction-entry:cfunction.py:7:builtins:sum
+cfunction-return:cfunction.py:7:builtins:sum

Lib/test/dtracedata/cfunction.py

@@ -0,0 +1,15 @@
+import math
+
+
+def start():
+    len([1, 2, 3])
+    math.sqrt(16.0)
+    sum([1, 2, 3])
+
+
+def main():
+    start()
+
+
+if __name__ == "__main__":
+    main()

Lib/test/dtracedata/cfunction.stp

@@ -0,0 +1,24 @@
+global tracing
+
+probe process.mark("function__entry")
+{
+    if (user_string($arg2) == "start") {
+        tracing = 1;
+    }
+}
+
+probe process.mark("cfunction__entry"), process.mark("cfunction__return")
+{
+    if (tracing) {
+        modulename = $arg4 ? user_string($arg4) : "";
+        printf("%d\t%s:%s:%d:%s:%s\n", gettimeofday_us(), $$name,
+               user_string($arg1), $arg3, modulename, user_string($arg2));
+    }
+}
+
+probe process.mark("function__return")
+{
+    if (user_string($arg2) == "start") {
+        tracing = 0;
+    }
+}

Lib/test/dtracedata/cfunction.stp.expected

@@ -0,0 +1,6 @@
+cfunction__entry:cfunction.py:5:builtins:len
+cfunction__return:cfunction.py:5:builtins:len
+cfunction__entry:cfunction.py:6:math:sqrt
+cfunction__return:cfunction.py:6:math:sqrt
+cfunction__entry:cfunction.py:7:builtins:sum
+cfunction__return:cfunction.py:7:builtins:sum

Lib/test/dtracedata/gc.bt

@@ -0,0 +1,15 @@
+@seq = 0;
+
+usdt:@TARGET@:python:function__entry /str(args->arg1) == "start"/ { @trace[tid] = 1; }
+
+usdt:@TARGET@:python:gc__start /@trace[tid]/ {
+    @seq += 1;
+    printf("%d\tgc-start:%ld\n", (int)@seq, args->arg0);
+}
+
+usdt:@TARGET@:python:gc__done /@trace[tid]/ {
+    @seq += 1;
+    printf("%d\tgc-done:%ld\n", (int)@seq, args->arg0);
+}
+
+usdt:@TARGET@:python:function__return /str(args->arg1) == "start"/ { @trace[tid] = 0; }

Lib/test/dtracedata/gc.bt.expected

@@ -0,0 +1,8 @@
+gc-start:0
+gc-done:0
+gc-start:1
+gc-done:0
+gc-start:2
+gc-done:0
+gc-start:2
+gc-done:1