Re: [PATCH v5 4/9] contrib/plugins/uftrace: implement tracing

[Manos Pitsidianakis <manos.pitsidianakis@linaro.org>]

On Fri, 08 Aug 2025 05:06, Pierrick Bouvier <pierrick.bouvier@linaro.org> wrote:
>We implement tracing, following uftrace format.
>Trace is flushed every 32 MB, so file operations don't impact
>performance at runtime.
>
>A different trace is generated per cpu, and we ensure they have a unique
>name, based on vcpu_index, while keeping room for privilege level coming
>in next commit.

Suggestion (not a request): put some kind of documentation about the 
format this patch implements, maybe a commit sha & URL to a header file 
from upstream uftrace.

>
>Signed-off-by: Pierrick Bouvier <pierrick.bouvier@linaro.org>
>---
> contrib/plugins/uftrace.c | 149 +++++++++++++++++++++++++++++++++++++-
> 1 file changed, 148 insertions(+), 1 deletion(-)
>
>diff --git a/contrib/plugins/uftrace.c b/contrib/plugins/uftrace.c
>index d51faceb344..402a242433e 100644
>--- a/contrib/plugins/uftrace.c
>+++ b/contrib/plugins/uftrace.c
>@@ -12,6 +12,13 @@
> #include <qemu-plugin.h>
> #include <glib.h>
> #include <stdio.h>
>+#include <sys/stat.h>
>+#include <sys/time.h>
>+#include <time.h>
>+#include <unistd.h>
>+
>+#define MiB     (INT64_C(1) << 20)
>+#define NANOSECONDS_PER_SECOND 1000000000LL
> 
> QEMU_PLUGIN_EXPORT int qemu_plugin_version = QEMU_PLUGIN_VERSION;
> 
>@@ -24,6 +31,13 @@ typedef struct {
>     uint64_t frame_pointer;
> } CallstackEntry;
> 
>+typedef struct {
>+    GArray *t;
>+    GString *path;
>+    GString *name;
>+    uint32_t id;
>+} Trace;
>+
> typedef struct Cpu Cpu;
> 
> typedef struct {
>@@ -34,6 +48,7 @@ typedef struct {
> } CpuOps;
> 
> typedef struct Cpu {
>+    Trace *trace;
>     Callstack *cs;
>     GByteArray *buf;
>     CpuOps ops;
>@@ -44,9 +59,41 @@ typedef struct {
>     struct qemu_plugin_register *reg_fp;
> } Aarch64Cpu;
> 
>+typedef struct {
>+    uint64_t timestamp;
>+    uint64_t data;
>+} UftraceEntry;
>+
>+typedef enum {
>+    UFTRACE_ENTRY,
>+    UFTRACE_EXIT,
>+    UFTRACE_LOST,
>+    UFTRACE_EVENT
>+} UftraceRecordType;
>+
> static struct qemu_plugin_scoreboard *score;
> static CpuOps arch_ops;
> 
>+static uint64_t gettime_ns(void)
>+{
>+#ifdef _WIN32
>+    /*
>+     * On Windows, timespec_get is available only with UCRT, but not with
>+     * MinGW64 environment. Simplify by using only gettimeofday on this
>+     * platform. This may result in a precision loss.
>+     */
>+    struct timeval tv;
>+    gettimeofday(&tv, NULL);
>+    uint64_t now_ns = tv.tv_sec * NANOSECONDS_PER_SECOND + tv.tv_usec * 1000;
>+#else
>+    /* We need nanosecond precision for short lived functions. */
>+    struct timespec ts;
>+    timespec_get(&ts, TIME_UTC);
>+    uint64_t now_ns = ts.tv_sec * NANOSECONDS_PER_SECOND + ts.tv_nsec;
>+#endif
>+    return now_ns;
>+}
>+
> static Callstack *callstack_new(void)
> {
>     Callstack *cs = g_new0(Callstack, 1);
>@@ -112,6 +159,85 @@ static CallstackEntry callstack_pop(Callstack *cs)
>     return e;
> }
> 
>+static Trace *trace_new(uint32_t id, GString *name)
>+{
>+    Trace *t = g_new0(Trace, 1);
>+    t->t = g_array_new(false, false, sizeof(UftraceEntry));
>+    t->path = g_string_new(NULL);
>+    g_string_append_printf(t->path, "./uftrace.data/%"PRIu32".dat", id);
>+    t->name = g_string_new(name->str);
>+    t->id = id;
>+    return t;
>+}
>+
>+static void trace_free(Trace *t)
>+{
>+    g_assert(t->t->len == 0);
>+    g_array_free(t->t, true);
>+    t->t = NULL;
>+    g_string_free(t->path, true);
>+    t->path = NULL;
>+    g_string_free(t->name, true);
>+    t->name = NULL;
>+    g_free(t);
>+}
>+
>+static void trace_flush(Trace *t, bool append)
>+{
>+    int create_dir = g_mkdir_with_parents("./uftrace.data",
>+                                          S_IRWXU | S_IRWXG | S_IRWXO);
>+    g_assert(create_dir == 0);
>+    FILE *dat = fopen(t->path->str, append ? "a" : "w");
>+    g_assert(dat);
>+    GArray *data = t->t;
>+    if (data->len) {
>+        fwrite(data->data, data->len, sizeof(UftraceEntry), dat);

fwrite might not write all bytes, how about using the 
g_file_set_contents() wrapper?

>+    }
>+    fclose(dat);
>+    g_array_set_size(data, 0);
>+}
>+
>+static void trace_add_entry(Trace *t, uint64_t timestamp, uint64_t pc,
>+                            size_t depth, UftraceRecordType type)
>+{
>+    /* libmcount/record.c:record_event */
>+    const uint64_t record_magic = 0x5;
>+    uint64_t data = type | record_magic << 3;
>+    data += depth << 6;
>+    data += pc << 16;
>+    UftraceEntry e = {.timestamp = timestamp, .data = data};
>+    g_array_append_val(t->t, e);
>+    if (t->t->len * sizeof(UftraceEntry) > 32 * MiB) {
>+        trace_flush(t, true);
>+    }
>+}
>+
>+static void trace_enter_function(Trace *t, uint64_t timestamp,
>+                                 uint64_t pc, size_t depth)
>+{
>+    trace_add_entry(t, timestamp, pc, depth, UFTRACE_ENTRY);
>+}
>+
>+static void trace_exit_function(Trace *t, uint64_t timestamp,
>+                                uint64_t pc, size_t depth)
>+{
>+    trace_add_entry(t, timestamp, pc, depth, UFTRACE_EXIT);
>+}
>+
>+static void trace_enter_stack(Trace *t, Callstack *cs, uint64_t timestamp)
>+{
>+    for (size_t depth = 1; depth <= callstack_depth(cs); ++depth) {
>+        trace_enter_function(t, timestamp, callstack_at(cs, depth)->pc, depth);
>+    }
>+}
>+
>+static void trace_exit_stack(Trace *t, Callstack *cs, uint64_t timestamp)
>+{
>+    for (size_t depth = callstack_depth(cs); depth > 0; --depth) {
>+        trace_exit_function(t, timestamp, callstack_at(cs, depth)->pc, depth);
>+    }
>+}
>+
> static uint64_t cpu_read_register64(Cpu *cpu, struct qemu_plugin_register *reg)
> {
>     GByteArray *buf = cpu->buf;
>@@ -223,7 +349,9 @@ static void track_callstack(unsigned int cpu_index, void *udata)
> {
>     uint64_t pc = (uintptr_t) udata;
>     Cpu *cpu = qemu_plugin_scoreboard_find(score, cpu_index);
>+    uint64_t timestamp = gettime_ns();
>     Callstack *cs = cpu->cs;
>+    Trace *t = cpu->trace;
> 
>     uint64_t fp = cpu->ops.get_frame_pointer(cpu);
>     if (!fp && callstack_empty(cs)) {
>@@ -232,6 +360,7 @@ static void track_callstack(unsigned int cpu_index, void *udata)
>          * long as a proper call does not happen.
>          */
>         callstack_push(cs, (CallstackEntry){.frame_pointer = fp, .pc = pc});
>+        trace_enter_function(t, timestamp, pc, callstack_depth(cs));
>         return;
>     }
> 
>@@ -244,7 +373,8 @@ static void track_callstack(unsigned int cpu_index, void *udata)
>     CallstackEntry caller = callstack_caller(cs);
>     if (fp == caller.frame_pointer) {
>         /* return */
>-        callstack_pop(cs);
>+        CallstackEntry e = callstack_pop(cs);
>+        trace_exit_function(t, timestamp, e.pc, callstack_depth(cs));
>         return;
>     }
> 
>@@ -252,12 +382,16 @@ static void track_callstack(unsigned int cpu_index, void *udata)
>     if (caller_fp == top.frame_pointer) {
>         /* call */
>         callstack_push(cs, (CallstackEntry){.frame_pointer = fp, .pc = pc});
>+        trace_enter_function(t, timestamp, pc, callstack_depth(cs));
>         return;
>     }
> 
>     /* discontinuity, exit current stack and unwind new one */
>+    trace_exit_stack(t, cs, timestamp);
>     callstack_clear(cs);
>+
>     cpu_unwind_stack(cpu, fp, pc);
>+    trace_enter_stack(t, cs, timestamp);
> }
> 
> static void vcpu_tb_trans(qemu_plugin_id_t id, struct qemu_plugin_tb *tb)
>@@ -296,6 +430,16 @@ static void vcpu_init(qemu_plugin_id_t id, unsigned int vcpu_index)
>     cpu->ops.init(cpu);
>     cpu->buf = g_byte_array_new();
> 
>+    g_assert(vcpu_index < UINT32_MAX / 100);
>+    /* trace_id is: cpu_number * 100 */
>+    uint32_t trace_id = (vcpu_index + 1) * 100;
>+
>+    g_autoptr(GString) trace_name = g_string_new(NULL);
>+    g_string_append_printf(trace_name, "cpu%u", vcpu_index);
>+    cpu->trace = trace_new(trace_id, trace_name);
>+    /* create/truncate trace file */
>+    trace_flush(cpu->trace, false);
>+
>     cpu->cs = callstack_new();
> }
> 
>@@ -304,6 +448,7 @@ static void vcpu_end(unsigned int vcpu_index)
>     Cpu *cpu = qemu_plugin_scoreboard_find(score, vcpu_index);
>     g_byte_array_free(cpu->buf, true);
> 
>+    trace_free(cpu->trace);
>     callstack_free(cpu->cs);
>     memset(cpu, 0, sizeof(Cpu));
> }
>@@ -311,6 +456,8 @@ static void vcpu_end(unsigned int vcpu_index)
> static void at_exit(qemu_plugin_id_t id, void *data)
> {
>     for (size_t i = 0; i < qemu_plugin_num_vcpus(); ++i) {
>+        Cpu *cpu = qemu_plugin_scoreboard_find(score, i);
>+        trace_flush(cpu->trace, true);
>         vcpu_end(i);
>     }
> 
>-- 
>2.47.2
>

Looks good overall.