diff --git a/per4m/giltracer.py b/per4m/giltracer.py index 976f36b..505428f 100644 --- a/per4m/giltracer.py +++ b/per4m/giltracer.py @@ -35,7 +35,7 @@ class PerfRecordSched(PerfRecord): class PerfRecordGIL(PerfRecord): def __init__(self, output='perf-gil.data', trace_output='giltracer.json', viztracer_input="viztracer.json", verbose=1): # TODO: check output of perf probe --list="python:*gil*" to see if probes are set - super().__init__(output=output, verbose=verbose, args=["-e 'python:*gil*'"], stacktrace=False) + super().__init__(output=output, verbose=verbose, args=["-e 'python:*gil*'", "-e pytrace:function_entry", "-e pytrace:function_return"], stacktrace=False) # this is used to filter the giltracer data self.viztracer_input = viztracer_input self.trace_output = trace_output diff --git a/per4m/perf2trace.py b/per4m/perf2trace.py index acdfcf1..ff06636 100644 --- a/per4m/perf2trace.py +++ b/per4m/perf2trace.py @@ -128,6 +128,10 @@ def gil2trace(input, verbose=1, take_probe="python:take_gil$", take_probe_return wants_take_gil = {} wants_drop_gil = {} has_gil = {} + has_gil_stack = {} + + pystack = defaultdict(list) + wait_for_stack = defaultdict(list) # pid -> call parent_pid = None # to avoid printing out the same msg over and over @@ -163,10 +167,36 @@ def gil2trace(input, verbose=1, take_probe="python:take_gil$", take_probe_return if time_first is None: time_first = time - if re.match(take_probe, event): + function_entry_probe = 'pytrace:function_entry' + function_return_probe = 'pytrace:function_return' + if re.match(function_entry_probe, event): + values = parse_values(other, l=int, what=int) + call = (values['filename'], values['funcname'], + values['l'], values['what']) + pystack[pid].append(call) + depth = len(pystack[pid]) + if verbose >= 3: + print(pid, " " * depth, "→", call) + elif re.match(function_return_probe, event): + try: + call = pystack[pid].pop() + depth = len(pystack[pid]) + if verbose >= 3: + print(pid, " " * depth, "←", call) + except: + pass # we may have missed some calls + elif re.match(take_probe, event): wants_take_gil[pid] = time scope = "t" # thread scope yield header, {"pid": parent_pid, "tid": pid, "ts": time, "name": 'take', "ph": "i", "cat": "GIL state", 's': scope, 'cname': 'bad'} + if has_gil: + for blocking_pid in has_gil: + if pystack[blocking_pid]: + call = pystack[blocking_pid][-1] + wait_for_stack[pid].append((blocking_pid, call, None)) + else: + call = ('cpython', 'cpython', -1) + wait_for_stack[pid].append((blocking_pid, call, None)) elif re.match(take_probe_return, event): if has_gil: for other_pid in has_gil: @@ -185,7 +215,9 @@ def gil2trace(input, verbose=1, take_probe="python:take_gil$", take_probe_return # yield header, {"pid": parent_pid, "tid": other_pid, "ts": wants_drop_gil[other_pid], "dur": overlap_relaxed, "name": 'GIL overlap2', "ph": "X", "cat": "process state"} # yield header, {"pid": parent_pid, "tid": pid, "ts": wants_drop_gil[other_pid], "dur": overlap_relaxed, "name": 'GIL overlap2', "ph": "X", "cat": "process state"} has_gil[pid] = time - time_wait_gil[pid] += time - max(t_min[pid], wants_take_gil[pid]) + has_gil_stack[pid] = pystack[pid].copy() + time_wait = time - max(t_min[pid], wants_take_gil[pid]) + time_wait_gil[pid] += time_wait elif re.match(drop_probe, event): wants_drop_gil[pid] = time scope = "t" # thread scope diff --git a/per4m/probes.cpp b/per4m/probes.cpp new file mode 100644 index 0000000..566b820 --- /dev/null +++ b/per4m/probes.cpp @@ -0,0 +1,9 @@ +#include + +extern "C" void pytrace_function_entry(const char *filename, const char *funcname, int lineno, int what) { + // do nothing, so we can attach a probe here +} + +extern "C" void pytrace_function_return(const char *filename, const char *funcname, int lineno, int what) { + // do nothing +} \ No newline at end of file diff --git a/per4m/pytrace.cpp b/per4m/pytrace.cpp new file mode 100644 index 0000000..dd4d6a0 --- /dev/null +++ b/per4m/pytrace.cpp @@ -0,0 +1,76 @@ +#include +#include + +extern "C" void pytrace_function_entry(const char *filename, + const char *funcname, int lineno, + int what); +extern "C" void pytrace_function_return(const char *filename, + const char *funcname, int lineno, + int what); + +int pytrace_trace(PyObject *obj, PyFrameObject *frame, int what, + PyObject *arg) { + if ((what == PyTrace_CALL) || (what == PyTrace_C_CALL)) { + // simular to https://github.com/python/cpython/blob/master/Python/ceval.c + // dtrace_function_entry + const char *filename; + const char *funcname; + int lineno; + + PyCodeObject *code = frame->f_code; + filename = PyUnicode_AsUTF8(code->co_filename); + funcname = PyUnicode_AsUTF8(code->co_name); + lineno = PyCode_Addr2Line(code, frame->f_lasti); + + pytrace_function_entry(filename, funcname, lineno, what); + } + if ((what == PyTrace_RETURN) || (what == PyTrace_C_RETURN)) { + const char *filename; + const char *funcname; + int lineno; + + PyCodeObject *code = frame->f_code; + filename = PyUnicode_AsUTF8(code->co_filename); + funcname = PyUnicode_AsUTF8(code->co_name); + lineno = PyCode_Addr2Line(code, frame->f_lasti); + + pytrace_function_return(filename, funcname, lineno, what); + } + return 0; +} + +static PyObject *pytrace_start(PyObject *obj, PyObject *args) { + PyEval_SetProfile(pytrace_trace, NULL); + // PyObject *threading_module = PyImport_ImportModule("threading"); + // PyObject *threading_setprofile = + // PyObject_GetAttrString(threading_module, "setprofile"); + // Py_INCREF(Py_None); + // PyObject *pytrace_cfunction = PyCFunction_New(pytrace_trace, Py_None); + // PyObject *args = Py_BuildValue("(N)", pytrace_cfunction); + // PyObject_CallObject(setprofile, args); + // Py_DECREF(args); + Py_RETURN_NONE; +} + +static PyObject *pytrace_stop(PyObject *obj, PyObject *args) { + PyEval_SetProfile(NULL, NULL); + Py_RETURN_NONE; +} + +static PyMethodDef pytrace_methods[] = { + {"start", (PyCFunction)pytrace_start, METH_VARARGS, "start tracing"}, + {"stop", (PyCFunction)pytrace_stop, METH_VARARGS, "stop tracing"}, + {NULL, NULL, 0, NULL}}; + +static struct PyModuleDef pytrace_module = { + PyModuleDef_HEAD_INIT, "per4m.pytrace", NULL, -1, pytrace_methods}; + +PyMODINIT_FUNC PyInit_pytrace(void) { + PyObject *m = PyModule_Create(&pytrace_module); + + if (!m) { + return NULL; + } + + return m; +} \ No newline at end of file diff --git a/setup.py b/setup.py index cb77cf8..409ccab 100644 --- a/setup.py +++ b/setup.py @@ -1,20 +1,25 @@ -from setuptools import setup, find_packages +from setuptools import setup, find_packages, Extension author = "Maarten A. Breddels" author_email = "maartenbreddels@gmail.com" license = 'MIT' url = 'https://www.github.com/maartenbreddels/per4m' +# add debug, and use O1 to avoid inlining +extra_compile_args = ["-g", "-O1"] + setup( author=author, author_email=author_email, name='per4m', - description = "Profiling and tracing information for Python using viztracer and perf, the GIL exposed.", + description="Profiling and tracing information for Python using viztracer and perf, the GIL exposed.", # version='0.1', url=url, packages=['per4m'], license=license, use_scm_version=True, setup_requires=['setuptools_scm'], + ext_modules=[Extension("per4m.pytrace", ["per4m/pytrace.cpp", "per4m/probes.cpp"], + extra_compile_args=extra_compile_args)], entry_points={ 'console_scripts': [ 'per4m = per4m.__main__:main',