[PATCH 0/2] SysCall tracing

[PATCH 0/2] SysCall tracing

[Yordan Karadzhov (VMware)]

Now, when we have the necessary APIs for working with 'eprobes' and
'synthetic' events, we can combine the two and trace system calls.

Yordan Karadzhov (VMware) (2):
  trace-cruncher: Add (un)register methods for dynamic events
  trace-cruncher: Add example of tracing systemcalls

 examples/syscall_trace.py                     | 66 ++++++++++++++
 src/ftracepy-utils.c                          | 90 ++++++++++++++-----
 src/ftracepy-utils.h                          |  4 +
 src/ftracepy.c                                | 15 +++-
 tracecruncher/ft_utils.py                     |  2 +
 .../tests/1_unit/test_01_ftracepy_unit.py     |  7 +-
 6 files changed, 159 insertions(+), 25 deletions(-)
 create mode 100755 examples/syscall_trace.py

-- 
2.33.1

[PATCH 1/2] trace-cruncher: Add (un)register methods for dynamic events

[Yordan Karadzhov (VMware)]

Currently the allocation of the Python object and the registration of
the new dynamic event are both done in the corresponding constructor for
kprobe, kretprobe or eprobe. Originally, this was done with the idea to
simplify the usage, however it turns that this can be an issue in the
case when these events are used in conjuction with synthetic events. In
such a case, the order in which the events are registered cannot be
arbitrary, because of the intrinsic dependencies between those events.
And the order used to create the events must be reverced when destroying
them. However, this requirement collides with way the Python automatic
garbage collection works, where the objects are destroyed in the same
order of there creation. The problem gets solved by decoupling the
allocation of the Python objects from the registration of the
corresponding events on the system. With this, we can create the objects
in one order and register in another.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 src/ftracepy-utils.c                          | 90 ++++++++++++++-----
 src/ftracepy-utils.h                          |  4 +
 src/ftracepy.c                                | 15 +++-
 tracecruncher/ft_utils.py                     |  2 +
 .../tests/1_unit/test_01_ftracepy_unit.py     |  7 +-
 5 files changed, 93 insertions(+), 25 deletions(-)

diff --git a/src/ftracepy-utils.c b/src/ftracepy-utils.c
index 19e237b..888e29b 100644
--- a/src/ftracepy-utils.c
+++ b/src/ftracepy-utils.c
@@ -2234,11 +2234,54 @@ PyObject *PyDynevent_probe(PyDynevent *self)
 	return dynevent_info2py(buff, type);
 }
 
+PyObject *PyDynevent_register(PyDynevent *self)
+{
+	if (tracefs_dynevent_create(self->ptrObj) < 0) {
+		char *evt;
+		int type;
+
+		type = tracefs_dynevent_info(self->ptrObj, NULL, &evt, NULL, NULL, NULL);
+		TfsError_fmt(NULL, "Failed to register dynamic event '%s'.",
+		type != TRACEFS_DYNEVENT_UNKNOWN ? evt : "UNKNOWN");
+		free(evt);
+		return NULL;
+	}
+
+	/*
+	 * Here the dynamic event gets added to the system.
+	 * Hence we need to 'destroy' this event at exit.
+	 */
+	set_destroy_flag((PyObject *)self, true);
+	Py_RETURN_NONE;
+}
+
+PyObject *PyDynevent_unregister(PyDynevent *self)
+{
+	if (tracefs_dynevent_destroy(self->ptrObj, true) < 0) {
+		char *evt;
+		int type;
+
+		type = tracefs_dynevent_info(self->ptrObj, NULL, &evt, NULL, NULL, NULL);
+		TfsError_fmt(NULL, "Failed to unregister dynamic event '%s'.",
+		type != TRACEFS_DYNEVENT_UNKNOWN ? evt : "UNKNOWN");
+		free(evt);
+		return NULL;
+	}
+
+	/*
+	 * Here the synthetic event gets removed from the system.
+	 * Hence we no loger need to 'destroy' this event at exit.
+	 */
+	set_destroy_flag((PyObject *)self, false);
+	Py_RETURN_NONE;
+}
+
 PyObject *PyFtrace_kprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 {
 	static char *kwlist[] = {"event", "function", "probe", NULL};
 	const char *event, *function, *probe;
 	struct tracefs_dynevent *kprobe;
+	PyObject *py_dyn;
 
 	if (!PyArg_ParseTupleAndKeywords(args,
 					 kwargs,
@@ -2256,13 +2299,14 @@ PyObject *PyFtrace_kprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 		return NULL;
 	}
 
-	if (tracefs_dynevent_create(kprobe) < 0) {
-		TfsError_fmt(NULL, "Failed to create kprobe '%s'", event);
-		tracefs_dynevent_free(kprobe);
-		return NULL;
-	}
-
-	return PyDynevent_New(kprobe);
+	py_dyn = PyDynevent_New(kprobe);
+	/*
+	 * Here we only allocated and initializes a dynamic event object.
+	 * However, no dynamic event is added to the system yet. Hence,
+	 * there is no need to 'destroy' this event at exit.
+	 */
+	set_destroy_flag(py_dyn, false);
+	return py_dyn;
 }
 
 PyObject *PyFtrace_kretprobe(PyObject *self, PyObject *args, PyObject *kwargs)
@@ -2270,6 +2314,7 @@ PyObject *PyFtrace_kretprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 	static char *kwlist[] = {"event", "function", "probe", NULL};
 	const char *event, *function, *probe = "$retval";
 	struct tracefs_dynevent *kprobe;
+	PyObject *py_dyn;
 
 	if (!PyArg_ParseTupleAndKeywords(args,
 					 kwargs,
@@ -2287,13 +2332,14 @@ PyObject *PyFtrace_kretprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 		return NULL;
 	}
 
-	if (tracefs_dynevent_create(kprobe) < 0) {
-		TfsError_fmt(NULL, "Failed to create kretprobe '%s'", event);
-		tracefs_dynevent_free(kprobe);
-		return NULL;
-	}
-
-	return PyDynevent_New(kprobe);
+	py_dyn = PyDynevent_New(kprobe);
+	/*
+	 * Here we only allocated and initializes a dynamic event object.
+	 * However, no dynamic event is added to the system yet. Hence,
+	 * there is no need to 'destroy' this event at exit.
+	 */
+	set_destroy_flag(py_dyn, false);
+	return py_dyn;
 }
 
 struct tep_event *dynevent_get_event(PyDynevent *event,
@@ -2323,6 +2369,7 @@ PyObject *PyFtrace_eprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 	static char *kwlist[] = {"event", "target_system", "target_event", "fetchargs", NULL};
 	const char *event, *target_system, *target_event, *fetchargs;
 	struct tracefs_dynevent *eprobe;
+	PyObject *py_dyn;
 
 	if (!PyArg_ParseTupleAndKeywords(args,
 					 kwargs,
@@ -2341,13 +2388,14 @@ PyObject *PyFtrace_eprobe(PyObject *self, PyObject *args, PyObject *kwargs)
 		return NULL;
 	}
 
-	if (tracefs_dynevent_create(eprobe) < 0) {
-		TfsError_fmt(NULL, "Failed to create eprobe '%s'", event);
-		tracefs_dynevent_free(eprobe);
-		return NULL;
-	}
-
-	return PyDynevent_New(eprobe);
+	py_dyn = PyDynevent_New(eprobe);
+	/*
+	 * Here we only allocated and initializes a dynamic event object.
+	 * However, no dynamic event is added to the system yet. Hence,
+	 * there is no need to 'destroy' this event at exit.
+	 */
+	set_destroy_flag(py_dyn, false);
+	return py_dyn;;
 }
 
 static PyObject *set_filter(PyObject *args, PyObject *kwargs,
diff --git a/src/ftracepy-utils.h b/src/ftracepy-utils.h
index 13b4c91..9491b18 100644
--- a/src/ftracepy-utils.h
+++ b/src/ftracepy-utils.h
@@ -76,6 +76,10 @@ PyObject *PyDynevent_address(PyDynevent *self);
 
 PyObject *PyDynevent_probe(PyDynevent *self);
 
+PyObject *PyDynevent_register(PyDynevent *self);
+
+PyObject *PyDynevent_unregister(PyDynevent *self);
+
 PyObject *PyDynevent_set_filter(PyDynevent *self, PyObject *args,
 					      PyObject *kwargs);
 
diff --git a/src/ftracepy.c b/src/ftracepy.c
index 354c6d1..574bf38 100644
--- a/src/ftracepy.c
+++ b/src/ftracepy.c
@@ -127,6 +127,16 @@ static PyMethodDef PyDynevent_methods[] = {
 	 METH_NOARGS,
 	 "Get the event definition."
 	},
+	{"register",
+	 (PyCFunction) PyDynevent_register,
+	 METH_NOARGS,
+	 "Register dynamic event."
+	},
+	{"unregister",
+	 (PyCFunction) PyDynevent_unregister,
+	 METH_NOARGS,
+	 "Unregister dynamic event."
+	},
 	{"set_filter",
 	 (PyCFunction) PyDynevent_set_filter,
 	 METH_VARARGS | METH_KEYWORDS,
@@ -164,6 +174,7 @@ static int dynevent_destroy(struct tracefs_dynevent *devt)
 {
 	return tracefs_dynevent_destroy(devt, true);
 }
+
 C_OBJECT_WRAPPER(tracefs_dynevent, PyDynevent,
 		 dynevent_destroy,
 		 tracefs_dynevent_free)
@@ -255,12 +266,12 @@ static PyMethodDef PySynthEvent_methods[] = {
 	{"register",
 	 (PyCFunction) PySynthEvent_register,
 	 METH_NOARGS,
-	 "Register synth. event to a trace instance."
+	 "Register synth. event."
 	},
 	{"unregister",
 	 (PyCFunction) PySynthEvent_unregister,
 	 METH_NOARGS,
-	 "Unregister synth. event from a trace instance."
+	 "Unregister synth. event."
 	},
 	{"enable",
 	 (PyCFunction) PySynthEvent_enable,
diff --git a/tracecruncher/ft_utils.py b/tracecruncher/ft_utils.py
index b7e2e73..26c06ec 100644
--- a/tracecruncher/ft_utils.py
+++ b/tracecruncher/ft_utils.py
@@ -157,6 +157,7 @@ class kprobe(kprobe_base):
         probe = ' '.join('{!s}={!s}'.format(key,val) for (key, val) in self.fields.items())
 
         self.kp = ft.kprobe(event=self.name, function=self.func, probe=probe);
+        self.kp.register();
         self.evt_id = find_event_id(system=ft.tc_event_system(), event=self.name)
 
 
@@ -187,6 +188,7 @@ class kretval_probe(kprobe_base):
         """ Register this probe to Ftrace.
         """
         self.kp = ft.kprobe(event=self.name, function=self.func);
+        self.kp.register();
         self.evt_id = find_event_id(system=ft.tc_event_system(), event=self.name)
 
 
diff --git a/tracecruncher/tests/1_unit/test_01_ftracepy_unit.py b/tracecruncher/tests/1_unit/test_01_ftracepy_unit.py
index 1ef8951..f51bcc1 100644
--- a/tracecruncher/tests/1_unit/test_01_ftracepy_unit.py
+++ b/tracecruncher/tests/1_unit/test_01_ftracepy_unit.py
@@ -414,11 +414,13 @@ class KprobeTestCase(unittest.TestCase):
         evt2_prove = 'file=+u0($arg2):ustring'
 
         kp1 = ft.kprobe(event=evt1, function=evt1_func, probe=evt1_prove)
+        kp1.register()
         self.assertEqual(evt1, kp1.event())
         self.assertEqual(evt1_func, kp1.address())
         self.assertEqual(evt1_prove, kp1.probe())
 
         kp2 = ft.kprobe(event=evt2, function=evt2_func, probe=evt2_prove)
+        kp2.register()
         self.assertEqual(evt2, kp2.event())
         self.assertEqual(evt2_func, kp2.address())
         self.assertEqual(evt2_prove, kp2.probe())
@@ -430,6 +432,7 @@ class KprobeTestCase(unittest.TestCase):
         flt = 'path~\'/sys/fs/cgroup/*\''
 
         kp1 = ft.kprobe(event=evt1, function=evt1_func, probe=evt1_prove)
+        kp1.register()
         inst = ft.create_instance(instance_name)
 
         kp1.set_filter(instance=inst, filter=flt)
@@ -445,6 +448,7 @@ class KprobeTestCase(unittest.TestCase):
         evt1_prove = 'path=+u0($arg2):ustring'
 
         kp1 = ft.kprobe(event=evt1, function=evt1_func, probe=evt1_prove)
+        kp1.register()
         inst = ft.create_instance(instance_name)
         kp1.enable(instance=inst)
         ret = kp1.is_enabled(instance=inst)
@@ -458,8 +462,6 @@ class EprobeTestCase(unittest.TestCase):
     def test_eprobe(self):
         """ Event probes are introduced in Linux kernel 5.15
         """
-        if kernel_version < (5, 15):
-            return
 
         evt1 = 'sopen_in'
         evt1_tsys = 'syscalls'
@@ -495,6 +497,7 @@ class EprobeTestCase(unittest.TestCase):
 
         ep1 = ft.eprobe(event=evt1, target_system=evt1_tsys, target_event=evt1_tevent,
                         fetchargs=evt1_args)
+        ep1.register()
         inst = ft.create_instance(instance_name)
         ep1.enable(instance=inst)
         ret = ep1.is_enabled(instance=inst)
-- 
2.33.1

[PATCH 2/2] trace-cruncher: Add example of tracing systemcalls

[Yordan Karadzhov (VMware)]

This is a very basic example, demonstrating how the low-level APIs can
be used to trace system calls.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 examples/syscall_trace.py | 66 +++++++++++++++++++++++++++++++++++++++
 1 file changed, 66 insertions(+)
 create mode 100755 examples/syscall_trace.py

diff --git a/examples/syscall_trace.py b/examples/syscall_trace.py
new file mode 100755
index 0000000..7d6f399
--- /dev/null
+++ b/examples/syscall_trace.py
@@ -0,0 +1,66 @@
+#!/usr/bin/env python3
+
+"""
+SPDX-License-Identifier: CC-BY-4.0
+
+Copyright 2022 VMware Inc, Yordan Karadzhov (VMware) <y.karadz@gmail.com>
+"""
+
+import sys
+
+import tracecruncher.ftracepy as ft
+import tracecruncher.ft_utils as tc
+
+eprobe_evt = 'eprobe_open'
+synth_evt = 'synth_open'
+syscall = 'openat'
+args = 'file=+0($file):ustring delta_T=$delta_T:s64'
+
+# In order to trace a system call, we will create a synthetic event that
+# combines the 'sys_enter_XXX' and 'sys_exit_XXX' static events. A dynamic
+# 'eprobe' will be attached to this synthetic event in order to decode the
+# pointer argument of the system and to calculate the time spend between
+# 'sys_enter_XXX' and 'sys_exit_XXX' (syscall duration).
+
+eprobe = ft.eprobe(event=eprobe_evt,
+                   target_system='synthetic', target_event=synth_evt,
+                   fetchargs=args)
+
+synth = ft.synth(name=synth_evt,
+                 start_sys='syscalls', start_evt='sys_enter_' + syscall,
+                 end_sys='syscalls',   end_evt='sys_exit_' + syscall,
+                 start_match='common_pid', end_match='common_pid')
+
+# Add to the synth. event one field from the 'start' event. In the synth. event,
+# the field 'filename' will be renamed to 'file'.
+synth.add_start_fields(fields=['filename'], names=['file'])
+
+# Add to the synth. event a field that measures the time-difference between
+# the 'start' and 'end' events. Use 'hd' time resolution (nanoseconds).
+synth.add_delta_T(hd=True)
+
+# The synthetic event must be registered first (and destroyed last), because the
+# eprobe depends on it. Note that the order in which the events are allocated
+# will be the order in which Python will destroy them at exit.
+synth.register()
+eprobe.register()
+
+tep = tc.local_tep()
+eprobe_id = tep.get_event(system=ft.tc_event_system(), name=eprobe_evt).id()
+
+def callback(event, record):
+    if event.id() == eprobe_id:
+        # Print only the dynamic eprobe.
+        print(tep.info(event, record))
+
+if __name__ == "__main__":
+    if len(sys.argv) < 2:
+        print('Usage: ', sys.argv[0], ' [PROCESS]')
+        sys.exit(1)
+
+    inst = ft.create_instance(tracing_on=False)
+
+    # Enable the two events and trace the user process.
+    synth.enable(instance=inst)
+    eprobe.enable(instance=inst)
+    ft.trace_process(instance=inst, argv=sys.argv[1:])
-- 
2.33.1