DTrace support: function calls, GC activity, line execution

Tested on macOS 10.11 dtrace, Ubuntu 16.04 SystemTap, and libbcc.

Largely based by an initial patch by Jesús Cea Avión, with some
influence from Dave Malcolm's SystemTap patch and Nikhil Benesch's
unification patch.

Things deliberately left out for simplicity:
- ustack helpers, I have no way of testing them at this point since
they are Solaris-specific
- PyFrameObject * in function__entry/function__return, this is
SystemTap-specific
- SPARC support
- dynamic tracing
- sys module dtrace facility introspection

All of those might be added later.

17 files changed, 463 insertions, 0 deletions

diff --git a/Lib/test/dtracedata/assert_usable.d b/Lib/test/dtracedata/assert_usable.d
new file mode 100644
index 0000000..0b2d4da
--- /dev/null
+++ b/Lib/test/dtracedata/assert_usable.d
@@ -0,0 +1,5 @@
+BEGIN
+{
+    printf("probe: success\n");
+    exit(0);
+}
diff --git a/Lib/test/dtracedata/assert_usable.stp b/Lib/test/dtracedata/assert_usable.stp
new file mode 100644
index 0000000..88e7e68
--- /dev/null
+++ b/Lib/test/dtracedata/assert_usable.stp
@@ -0,0 +1,5 @@
+probe begin
+{
+  println("probe: success")
+  exit ()
+}
diff --git a/Lib/test/dtracedata/call_stack.d b/Lib/test/dtracedata/call_stack.d
new file mode 100644
index 0000000..450e939
--- /dev/null
+++ b/Lib/test/dtracedata/call_stack.d
@@ -0,0 +1,31 @@
+self int indent;
+
+python$target:::function-entry
+/copyinstr(arg1) == "start"/
+{
+    self->trace = 1;
+}
+
+python$target:::function-entry
+/self->trace/
+{
+    printf("%d\t%*s:", timestamp, 15, probename);
+    printf("%*s", self->indent, ""); 
+    printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
+    self->indent++;
+}
+
+python$target:::function-return
+/self->trace/
+{
+    self->indent--;
+    printf("%d\t%*s:", timestamp, 15, probename);
+    printf("%*s", self->indent, ""); 
+    printf("%s:%s:%d\n", basename(copyinstr(arg0)), copyinstr(arg1), arg2);
+}
+
+python$target:::function-return
+/copyinstr(arg1) == "start"/
+{
+    self->trace = 0;
+}
diff --git a/Lib/test/dtracedata/call_stack.d.expected b/Lib/test/dtracedata/call_stack.d.expected
new file mode 100644
index 0000000..27849d1
--- /dev/null
+++ b/Lib/test/dtracedata/call_stack.d.expected
@@ -0,0 +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
diff --git a/Lib/test/dtracedata/call_stack.py b/Lib/test/dtracedata/call_stack.py
new file mode 100644
index 0000000..ee9f3ae
--- /dev/null
+++ b/Lib/test/dtracedata/call_stack.py
@@ -0,0 +1,30 @@
+def function_1():
+    function_3(1, 2)
+
+# Check stacktrace
+def function_2():
+    function_1()
+
+# CALL_FUNCTION_VAR
+def function_3(dummy, dummy2):
+    pass
+
+# CALL_FUNCTION_KW
+def function_4(**dummy):
+    return 1
+    return 2  # unreachable
+
+# CALL_FUNCTION_VAR_KW
+def function_5(dummy, dummy2, **dummy3):
+    if False:
+        return 7
+    return 8
+
+def start():
+    function_1()
+    function_2()
+    function_3(1, 2)
+    function_4(test=42)
+    function_5(*(1, 2), **{"test": 42})
+
+start()
diff --git a/Lib/test/dtracedata/call_stack.stp b/Lib/test/dtracedata/call_stack.stp
new file mode 100644
index 0000000..54082c2
--- /dev/null
+++ b/Lib/test/dtracedata/call_stack.stp
@@ -0,0 +1,41 @@
+global tracing
+
+function basename:string(path:string)
+{
+    last_token = token = tokenize(path, "/");
+    while (token != "") {
+        last_token = token;
+        token = tokenize("", "/");
+    }
+    return last_token;
+}
+
+probe process.mark("function__entry")
+{
+    funcname = user_string($arg2);
+
+    if (funcname == "start") {
+        tracing = 1;
+    }
+}
+
+probe process.mark("function__entry"), process.mark("function__return")
+{
+    filename = user_string($arg1);
+    funcname = user_string($arg2);
+    lineno = $arg3;
+
+    if (tracing) {
+        printf("%d\t%s:%s:%s:%d\n", gettimeofday_us(), $$name,
+               basename(filename), funcname, lineno);
+    }
+}
+
+probe process.mark("function__return")
+{
+    funcname = user_string($arg2);
+
+    if (funcname == "start") {
+        tracing = 0;
+    }
+}
diff --git a/Lib/test/dtracedata/call_stack.stp.expected b/Lib/test/dtracedata/call_stack.stp.expected
new file mode 100644
index 0000000..32cf396
--- /dev/null
+++ b/Lib/test/dtracedata/call_stack.stp.expected
@@ -0,0 +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
diff --git a/Lib/test/dtracedata/gc.d b/Lib/test/dtracedata/gc.d
new file mode 100644
index 0000000..4d91487
--- /dev/null
+++ b/Lib/test/dtracedata/gc.d
@@ -0,0 +1,18 @@
+python$target:::function-entry
+/copyinstr(arg1) == "start"/
+{
+    self->trace = 1;
+}
+
+python$target:::gc-start,
+python$target:::gc-done
+/self->trace/
+{
+    printf("%d\t%s:%ld\n", timestamp, probename, arg0);
+}
+
+python$target:::function-return
+/copyinstr(arg1) == "start"/
+{
+    self->trace = 0;
+}
diff --git a/Lib/test/dtracedata/gc.d.expected b/Lib/test/dtracedata/gc.d.expected
new file mode 100644
index 0000000..8e5ac2a
--- /dev/null
+++ b/Lib/test/dtracedata/gc.d.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
diff --git a/Lib/test/dtracedata/gc.py b/Lib/test/dtracedata/gc.py
new file mode 100644
index 0000000..144a783
--- /dev/null
+++ b/Lib/test/dtracedata/gc.py
@@ -0,0 +1,13 @@
+import gc
+
+def start():
+    gc.collect(0)
+    gc.collect(1)
+    gc.collect(2)
+    l = []
+    l.append(l)
+    del l
+    gc.collect(2)
+
+gc.collect()
+start()
diff --git a/Lib/test/dtracedata/gc.stp b/Lib/test/dtracedata/gc.stp
new file mode 100644
index 0000000..162c6d3
--- /dev/null
+++ b/Lib/test/dtracedata/gc.stp
@@ -0,0 +1,26 @@
+global tracing
+
+probe process.mark("function__entry")
+{
+    funcname = user_string($arg2);
+
+    if (funcname == "start") {
+        tracing = 1;
+    }
+}
+
+probe process.mark("gc__start"), process.mark("gc__done")
+{
+    if (tracing) {
+        printf("%d\t%s:%ld\n", gettimeofday_us(), $$name, $arg1);
+    }
+}
+
+probe process.mark("function__return")
+{
+    funcname = user_string($arg2);
+
+    if (funcname == "start") {
+        tracing = 0;
+    }
+}
diff --git a/Lib/test/dtracedata/gc.stp.expected b/Lib/test/dtracedata/gc.stp.expected
new file mode 100644
index 0000000..7e6e622
--- /dev/null
+++ b/Lib/test/dtracedata/gc.stp.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
diff --git a/Lib/test/dtracedata/instance.py b/Lib/test/dtracedata/instance.py
new file mode 100644
index 0000000..f142137
--- /dev/null
+++ b/Lib/test/dtracedata/instance.py
@@ -0,0 +1,24 @@
+import gc
+
+class old_style_class():
+    pass
+class new_style_class(object):
+    pass
+
+a = old_style_class()
+del a
+gc.collect()
+b = new_style_class()
+del b
+gc.collect()
+
+a = old_style_class()
+del old_style_class
+gc.collect()
+b = new_style_class()
+del new_style_class
+gc.collect()
+del a
+gc.collect()
+del b
+gc.collect()
diff --git a/Lib/test/dtracedata/line.d b/Lib/test/dtracedata/line.d
new file mode 100644
index 0000000..03f22db
--- /dev/null
+++ b/Lib/test/dtracedata/line.d
@@ -0,0 +1,7 @@
+python$target:::line
+/(copyinstr(arg1)=="test_line")/
+{
+    printf("%d\t%s:%s:%s:%d\n", timestamp,
+        probename, basename(copyinstr(arg0)),
+        copyinstr(arg1), arg2);
+}
diff --git a/Lib/test/dtracedata/line.d.expected b/Lib/test/dtracedata/line.d.expected
new file mode 100644
index 0000000..9b16ce7
--- /dev/null
+++ b/Lib/test/dtracedata/line.d.expected
@@ -0,0 +1,20 @@
+line:line.py:test_line:2
+line:line.py:test_line:3
+line:line.py:test_line:4
+line:line.py:test_line:5
+line:line.py:test_line:6
+line:line.py:test_line:7
+line:line.py:test_line:8
+line:line.py:test_line:9
+line:line.py:test_line:10
+line:line.py:test_line:11
+line:line.py:test_line:4
+line:line.py:test_line:5
+line:line.py:test_line:6
+line:line.py:test_line:7
+line:line.py:test_line:8
+line:line.py:test_line:10
+line:line.py:test_line:11
+line:line.py:test_line:4
+line:line.py:test_line:12
+line:line.py:test_line:13
diff --git a/Lib/test/dtracedata/line.py b/Lib/test/dtracedata/line.py
new file mode 100644
index 0000000..0930ff3
--- /dev/null
+++ b/Lib/test/dtracedata/line.py
@@ -0,0 +1,17 @@
+def test_line():
+    a = 1
+    print('# Preamble', a)
+    for i in range(2):
+        a = i
+        b = i+2
+        c = i+3
+        if c < 4:
+            a = c
+        d = a + b +c
+        print('#', a, b, c, d)
+    a = 1
+    print('# Epilogue', a)
+
+
+if __name__ == '__main__':
+    test_line()
diff --git a/Lib/test/test_dtrace.py b/Lib/test/test_dtrace.py
new file mode 100644
index 0000000..ca239b3
--- /dev/null
+++ b/Lib/test/test_dtrace.py
@@ -0,0 +1,178 @@
+import dis
+import os.path
+import re
+import subprocess
+import sys
+import types
+import unittest
+
+from test.support import findfile, run_unittest
+
+
+def abspath(filename):
+    return os.path.abspath(findfile(filename, subdir="dtracedata"))
+
+
+def normalize_trace_output(output):
+    """Normalize DTrace output for comparison.
+
+    DTrace keeps a per-CPU buffer, and when showing the fired probes, buffers
+    are concatenated. So if the operating system moves our thread around, the
+    straight result can be "non-causal". So we add timestamps to the probe
+    firing, sort by that field, then strip it from the output"""
+
+    # When compiling with '--with-pydebug', strip '[# refs]' debug output.
+    output = re.sub(r"\[[0-9]+ refs\]", "", output)
+    try:
+        result = [
+            row.split("\t")
+            for row in output.splitlines()
+            if row and not row.startswith('#')
+        ]
+        result.sort(key=lambda row: int(row[0]))
+        result = [row[1] for row in result]
+        return "\n".join(result)
+    except (IndexError, ValueError):
+        raise AssertionError(
+            "tracer produced unparseable output:\n{}".format(output)
+        )
+
+
+class TraceBackend:
+    EXTENSION = None
+    COMMAND = None
+    COMMAND_ARGS = []
+
+    def run_case(self, name, optimize_python=None):
+        actual_output = normalize_trace_output(self.trace_python(
+            script_file=abspath(name + self.EXTENSION),
+            python_file=abspath(name + ".py"),
+            optimize_python=optimize_python))
+
+        with open(abspath(name + self.EXTENSION + ".expected")) as f:
+            expected_output = f.read().rstrip()
+
+        return (expected_output, actual_output)
+
+    def generate_trace_command(self, script_file, subcommand=None):
+        command = self.COMMAND + [script_file]
+        if subcommand:
+            command += ["-c", subcommand]
+        return command
+
+    def trace(self, script_file, subcommand=None):
+        command = self.generate_trace_command(script_file, subcommand)
+        stdout, _ = subprocess.Popen(command,
+                                     stdout=subprocess.PIPE,
+                                     stderr=subprocess.STDOUT,
+                                     universal_newlines=True).communicate()
+        return stdout
+
+    def trace_python(self, script_file, python_file, optimize_python=None):
+        python_flags = []
+        if optimize_python:
+            python_flags.extend(["-O"] * optimize_python)
+        subcommand = " ".join([sys.executable] + python_flags + [python_file])
+        return self.trace(script_file, subcommand)
+
+    def assert_usable(self):
+        try:
+            output = self.trace(abspath("assert_usable" + self.EXTENSION))
+            output = output.strip()
+        except FileNotFoundError as fnfe:
+            output = str(fnfe)
+        if output != "probe: success":
+            raise unittest.SkipTest(
+                "{}(1) failed: {}".format(self.COMMAND[0], output)
+            )
+
+
+class DTraceBackend(TraceBackend):
+    EXTENSION = ".d"
+    COMMAND = ["dtrace", "-q", "-s"]
+
+
+class SystemTapBackend(TraceBackend):
+    EXTENSION = ".stp"
+    COMMAND = ["stap", "-g"]
+
+
+class TraceTests(unittest.TestCase):
+    # unittest.TestCase options
+    maxDiff = None
+
+    # TraceTests options
+    backend = None
+    optimize_python = 0
+
+    @classmethod
+    def setUpClass(self):
+        self.backend.assert_usable()
+
+    def run_case(self, name):
+        actual_output, expected_output = self.backend.run_case(
+            name, optimize_python=self.optimize_python)
+        self.assertEqual(actual_output, expected_output)
+
+    def test_function_entry_return(self):
+        self.run_case("call_stack")
+
+    def test_verify_call_opcodes(self):
+        """Ensure our call stack test hits all function call opcodes"""
+
+        opcodes = set(["CALL_FUNCTION", "CALL_FUNCTION_EX", "CALL_FUNCTION_KW"])
+
+        with open(abspath("call_stack.py")) as f:
+            code_string = f.read()
+
+        def get_function_instructions(funcname):
+            # Recompile with appropriate optimization setting
+            code = compile(source=code_string,
+                           filename="<string>",
+                           mode="exec",
+                           optimize=self.optimize_python)
+
+            for c in code.co_consts:
+                if isinstance(c, types.CodeType) and c.co_name == funcname:
+                    return dis.get_instructions(c)
+            return []
+
+        for instruction in get_function_instructions('start'):
+            opcodes.discard(instruction.opname)
+
+        self.assertEqual(set(), opcodes)
+
+    def test_gc(self):
+        self.run_case("gc")
+
+    def test_line(self):
+        self.run_case("line")
+
+
+class DTraceNormalTests(TraceTests):
+    backend = DTraceBackend()
+    optimize_python = 0
+
+
+class DTraceOptimizedTests(TraceTests):
+    backend = DTraceBackend()
+    optimize_python = 2
+
+
+class SystemTapNormalTests(TraceTests):
+    backend = SystemTapBackend()
+    optimize_python = 0
+
+
+class SystemTapOptimizedTests(TraceTests):
+    backend = SystemTapBackend()
+    optimize_python = 2
+
+
+def test_main():
+    run_unittest(DTraceNormalTests, DTraceOptimizedTests, SystemTapNormalTests,
+                 SystemTapOptimizedTests)
+
+
+if __name__ == '__main__':
+    test_main()