Add and test instrumentation when using threading.Thread

Author: Flamefire

scorep/_instrumenters/scorep_cProfile.py

@@ -6,3 +6,13 @@ class ScorepCProfile(scorep_bindings.CInstrumenter, ScorepInstrumenter):
     def __init__(self, enable_instrumenter):
         scorep_bindings.CInstrumenter.__init__(self, tracingOrProfiling=False)
         ScorepInstrumenter.__init__(self, enable_instrumenter)
+
+    def _enable_instrumenter(self):
+        if self._threading:
+            self._threading.setprofile(self)
+        super()._enable_instrumenter()
+
+    def _disable_instrumenter(self):
+        super()._disable_instrumenter()
+        if self._threading:
+            self._threading.setprofile(None)

scorep/_instrumenters/scorep_cTrace.py

@@ -6,3 +6,13 @@ class ScorepCTrace(scorep_bindings.CInstrumenter, ScorepInstrumenter):
     def __init__(self, enable_instrumenter):
         scorep_bindings.CInstrumenter.__init__(self, tracingOrProfiling=True)
         ScorepInstrumenter.__init__(self, enable_instrumenter)
+
+    def _enable_instrumenter(self):
+        if self._threading:
+            self._threading.settrace(self)
+        super()._enable_instrumenter()
+
+    def _disable_instrumenter(self):
+        super()._disable_instrumenter()
+        if self._threading:
+            self._threading.settrace(None)

scorep/_instrumenters/scorep_instrumenter.py

@@ -15,6 +15,12 @@ def __init__(self, enable_instrumenter=True):
         """
         self._tracer_registered = False
         self._enabled = enable_instrumenter
+        # TODO: Support other threading libs, e.g. greenlet?
+        try:
+            import threading
+            self._threading = threading
+        except ImportError:
+            self._threading = None
 
     @abc.abstractmethod
     def _enable_instrumenter(self):

src/classes.cpp

@@ -55,6 +55,21 @@ extern "C"
         self->disable_instrumenter();
         Py_RETURN_NONE;
     }
+
+    static PyObject* CInstrumenter_call(scorepy::CInstrumenter* self, PyObject* args,
+                                        PyObject* kwds)
+    {
+        static const char* kwlist[] = { "frame", "event", "arg", nullptr };
+
+        PyFrameObject* frame;
+        const char* event;
+        PyObject* arg;
+
+        if (!PyArg_ParseTupleAndKeywords(args, kwds, "O!sO", const_cast<char**>(kwlist),
+                                         &PyFrame_Type, &frame, &event, &arg))
+            return nullptr;
+        return (*self)(*frame, event, arg);
+    }
 }
 
 namespace scorepy
@@ -84,6 +99,7 @@ PyTypeObject& getCInstrumenterType()
     type.tp_new = call_object_new;
     type.tp_init = scorepy::castToPyFunc(CInstrumenter_init);
     type.tp_methods = methods;
+    type.tp_call = scorepy::castToPyFunc(CInstrumenter_call);
     type.tp_getset = getseters;
     type.tp_flags = Py_TPFLAGS_DEFAULT | Py_TPFLAGS_BASETYPE;
     type.tp_doc = "Class for the C instrumenter interface of Score-P";

src/scorepy/cInstrumenter.cpp

@@ -1,6 +1,8 @@
 #include "cInstrumenter.hpp"
 #include "events.hpp"
 #include "pythonHelpers.hpp"
+#include <algorithm>
+#include <array>
 #include <string>
 
 namespace scorepy
@@ -16,10 +18,6 @@ static const std::string& make_region_name(const char* moduleName, const char* n
 
 void CInstrumenter::enable_instrumenter()
 {
-    // TODO: Known issue:  `sys.getprofile()` returns the user object (2nd arg)
-    // So `sys.setprofile(sys.getprofile())` will not round-trip as it will try to call the
-    // 2nd arg. If it is nullptr (here) it means it will be disabled completely
-    // See https://nedbatchelder.com/text/trace-function.html for details
     const auto callback = [](PyObject* obj, PyFrameObject* frame, int what, PyObject* arg) -> int {
         return fromPyObject(obj)->onEvent(*frame, what, arg) ? 0 : -1;
     };
@@ -41,6 +39,34 @@ void CInstrumenter::disable_instrumenter()
         PyEval_SetProfile(nullptr, nullptr);
 }
 
+/// Mapping of PyTrace_* to it's string representations
+/// List taken from CPythons sysmodule.c
+static const std::array<std::string, 8> whatStrings = { "call",     "exception", "line",
+                                                        "return",   "c_call",    "c_exception",
+                                                        "c_return", "opcode" };
+
+// Required because:  `sys.getprofile()` returns the user object (2nd arg to PyEval_SetTrace)
+// So `sys.setprofile(sys.getprofile())` will not round-trip as it will try to call the
+// 2nd arg through pythons dispatch function. Hence make the object callable.
+// See https://nedbatchelder.com/text/trace-function.html for details
+PyObject* CInstrumenter::operator()(PyFrameObject& frame, const char* what, PyObject* arg)
+{
+    const auto itWhat = std::find(whatStrings.begin(), whatStrings.end(), what);
+    const int iWhat = itWhat == whatStrings.end() ? -1 : std::distance(whatStrings.begin(), itWhat);
+    // To speed up further event processing install this class directly as the handler
+    // But we might be inside a `sys.settrace` call where the user wanted to set another function
+    // which would then be overwritten here. Hence use the CALL event which avoids the problem
+    if (iWhat == PyTrace_CALL)
+        enable_instrumenter();
+    if (onEvent(frame, iWhat, arg))
+    {
+        Py_INCREF(toPyObject());
+        return toPyObject();
+    }
+    else
+        return nullptr;
+}
+
 bool CInstrumenter::onEvent(PyFrameObject& frame, int what, PyObject*)
 {
     switch (what)

src/scorepy/cInstrumenter.hpp

@@ -17,6 +17,9 @@ struct CInstrumenter
     void enable_instrumenter();
     void disable_instrumenter();
 
+    /// Callback for when this object is called directly
+    PyObject* operator()(PyFrameObject& frame, const char* what, PyObject* arg);
+
     /// These casts are valid as long as `PyObject_HEAD` is the first entry in this struct
     PyObject* toPyObject()
     {

test/cases/use_threads.py

@@ -0,0 +1,22 @@
+import random
+import threading
+import time
+import instrumentation2
+
+
+def worker(id, func):
+    print("Thread %s started" % id)
+    # Use a random delay to add non-determinism to the output
+    time.sleep(random.uniform(0.01, 0.9))
+    func()
+
+
+def foo():
+    print("hello world")
+    t1 = threading.Thread(target=worker, args=(0, instrumentation2.bar))
+    t2 = threading.Thread(target=worker, args=(1, instrumentation2.baz))
+    t1.start()
+    t2.start()
+
+
+foo()

test/test_scorep.py

@@ -294,3 +294,27 @@ def test_instrumentation_ctracing(scorep_env, instrumenter):
     for func in ('__main__:foo', 'instrumentation2:bar', 'instrumentation2:baz'):
         for event in ('ENTER', 'LEAVE'):
             assert re.search('%s[ ]*[0-9 ]*[0-9 ]*Region: "%s"' % (event, func), std_out)
+
+
+@pytest.mark.parametrize('instrumenter', ['profile', 'trace', 'cProfile', 'cTrace'])
+def test_threads(scorep_env, instrumenter):
+    if instrumenter[0] == 'c' and sys.version_info.major < 3:
+        pytest.skip("C extension class only implemented for Python3")
+
+    trace_path = scorep_env["SCOREP_EXPERIMENT_DIRECTORY"] + "/traces.otf2"
+
+    std_out, std_err = call_with_scorep("cases/use_threads.py",
+                                        ["--nocompiler",  "--instrumenter-type=" + instrumenter],
+                                        env=scorep_env)
+
+    # assert std_err == "" TODO: Readd when issue #87 is resolved
+    assert re.search(("hello world\n" +
+                      "(Thread 0 started\nThread 1 started\n|Thread 1 started\nThread 0 started\n)" +
+                      "(baz\nbar\n|bar\nbaz\n)"), std_out)
+
+    std_out, std_err = call(["otf2-print", trace_path])
+
+    assert std_err == ""
+    for func in ('__main__:foo', 'instrumentation2:bar', 'instrumentation2:baz'):
+        for event in ('ENTER', 'LEAVE'):
+            assert re.search('%s[ ]*[0-9 ]*[0-9 ]*Region: "%s"' % (event, func), std_out)