[RFC 4/5] xen/tracing: Add a function tracer

[Ryo Takakura <takakura@xxxxxxxxxxxxx>]

Add a function tracer which records calls to the selected function.

Each record includes the timestamp, CPU ID, and domain associated with
the call.

~$ xenhypfs cat /tracing/trace
# tracer: function
#
# entries-in-buffer/entries-written: 5/5   #P:1
#
#                      _-----=> irqs-off
#                     / _----=> need-resched
#                    | / _---=> in-irq
#                    || / _--=> preempt-depth
#                    ||| /
# DOMAIN/VCPU  PCPU  ||||         TIMESTAMP        FUNCTION
#      |        |    ||||             |               |
         d0/v0 [000] nnn  0           442.074071: xen_extra_version 
<-do_xen_version
         d0/v0 [000] nnn  0           443.160035: xen_extra_version 
<-do_xen_version
         d0/v0 [000] nnn  0           469.897195: xen_extra_version 
<-do_xen_version
         d0/v0 [000] nnn  0           471.295576: xen_extra_version 
<-do_xen_version
         d0/v0 [000] nnn  0           472.052187: xen_extra_version 
<-do_xen_version

The tracer is inspired by Linux ftrace's function tracer.

Signed-off-by: Ryo Takakura <takakura@xxxxxxxxxxxxx>
---
 xen/common/Makefile         |   2 +
 xen/common/function_trace.c | 274 ++++++++++++++++++++++++++++++++++++
 2 files changed, 276 insertions(+)
 create mode 100644 xen/common/function_trace.c

diff --git a/xen/common/Makefile b/xen/common/Makefile
index 303016f250..435423f694 100644
--- a/xen/common/Makefile
+++ b/xen/common/Makefile
@@ -80,8 +80,10 @@ obj-$(CONFIG_NEEDS_LIBELF) += libelf/
 obj-$(CONFIG_LIBFDT) += libfdt/
 
 obj-$(CONFIG_LIVEPATCH_TRACER) += hypfs_trace.o
+obj-$(CONFIG_LIVEPATCH_TRACER) += function_trace.o
 # Do not generate patchable entries for the tracer functions.
 $(obj)/hypfs_trace.o: CFLAGS-y += -fpatchable-function-entry=0,0
+$(obj)/function_trace.o: CFLAGS-y += -fpatchable-function-entry=0,0
 
 CONF_FILE := $(if $(patsubst 
/%,,$(KCONFIG_CONFIG)),$(objtree)/)$(KCONFIG_CONFIG)
 $(obj)/config.gz: $(CONF_FILE)
diff --git a/xen/common/function_trace.c b/xen/common/function_trace.c
new file mode 100644
index 0000000000..5dd4ccdec0
--- /dev/null
+++ b/xen/common/function_trace.c
@@ -0,0 +1,274 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+#include <xen/init.h>
+#include <xen/lib.h>
+#include <xen/percpu.h>
+#include <xen/preempt.h>
+#include <xen/time.h>
+#include <xen/hypfs_trace.h>
+#include <xen/symbols.h>
+#include <xen/sched.h>
+#include <xen/irq.h>
+#include <xen/smp.h>
+#include <xen/softirq.h>
+#include <xen/cpumask.h>
+#include <xen/xmalloc.h>
+
+#include <asm/system.h>
+
+#define FUNCTION_TRACE_CTX_NORMAL  0
+#define FUNCTION_TRACE_CTX_IRQ     (1U << 0)
+#define FUNCTION_TRACE_CTX_IDLE    (1U << 1)
+#define FUNCTION_TRACE_CTX_IRQS_OFF (1U << 2)
+#define FUNCTION_TRACE_CTX_RESCHED  (1U << 3)
+#define FUNCTION_TRACE_RECORD_TEXT_SIZE (2 * KSYM_NAME_LEN + 128)
+#define FUNCTION_TRACE_BUFSIZE 256
+
+static const char function_trace_header[] =
+    "#\n"
+    "#                      _-----=> irqs-off\n"
+    "#                     / _----=> need-resched\n"
+    "#                    | / _---=> in-irq\n"
+    "#                    || / _--=> preempt-depth\n"
+    "#                    ||| /\n"
+    "# DOMAIN/VCPU  PCPU  ||||         TIMESTAMP        FUNCTION\n"
+    "#      |        |    ||||             |               |\n";
+
+struct function_trace_record {
+    uint64_t timestamp; /* Timestamp of when the event occurred */
+    unsigned long ip; /* The address of the traced function */
+    unsigned long parent_ip; /* The address where the traced function was 
called */
+    unsigned int pcpu; /* pCPU */
+    domid_t domid; /* Domain ID */
+    unsigned int vcpuid; /* vCPU */
+    unsigned int context_flags; /* Execution context */
+    unsigned int preempt_depth; /* Preempt count */
+};
+
+struct function_trace_cpu_buffer {
+    struct function_trace_record records[FUNCTION_TRACE_BUFSIZE];
+    unsigned int head;
+    uint64_t written;
+};
+
+struct buffer_iterator {
+    const struct function_trace_cpu_buffer *buffer;
+    unsigned int start;
+    unsigned int count;
+    unsigned int next;
+};
+
+static DEFINE_PER_CPU(struct function_trace_cpu_buffer, function_trace_buffer);
+static DEFINE_PER_CPU(bool, function_trace_recursing);
+
+static void cf_check function_trace_callback(unsigned long ip, unsigned long 
parent_ip)
+{
+    struct function_trace_cpu_buffer *buf;
+    struct function_trace_record *rec;
+    unsigned int ctx = FUNCTION_TRACE_CTX_NORMAL;
+    unsigned long pending;
+
+    if ( this_cpu(function_trace_recursing) )
+        return;
+
+    this_cpu(function_trace_recursing) = true;
+
+    buf = &this_cpu(function_trace_buffer);
+    rec = &buf->records[buf->head];
+
+    rec->preempt_depth = preempt_count();
+
+    if ( !local_irq_is_enabled() )
+        ctx |= FUNCTION_TRACE_CTX_IRQS_OFF;
+
+    pending = softirq_pending(smp_processor_id());
+    if ( pending & ((1UL << SCHEDULE_SOFTIRQ) |
+                    (1UL << SCHED_SLAVE_SOFTIRQ)) )
+        ctx |= FUNCTION_TRACE_CTX_RESCHED;
+
+    rec->timestamp = NOW();
+    rec->ip = ip;
+    rec->parent_ip = parent_ip;
+    rec->pcpu = smp_processor_id();
+
+    if ( in_irq() )
+        ctx |= FUNCTION_TRACE_CTX_IRQ;
+
+    if ( is_idle_vcpu(current) )
+        ctx |= FUNCTION_TRACE_CTX_IDLE;
+
+    rec->context_flags = ctx;
+    rec->domid = current->domain->domain_id;
+    rec->vcpuid = current->vcpu_id;
+
+    buf->head = (buf->head + 1) % FUNCTION_TRACE_BUFSIZE;
+    buf->written++;
+
+    this_cpu(function_trace_recursing) = false;
+}
+
+static int cf_check function_tracer_clear(struct trace_context *tr)
+{
+    struct function_trace_cpu_buffer *buf;
+    unsigned int cpu;
+
+    for_each_online_cpu ( cpu )
+    {
+        buf = &per_cpu(function_trace_buffer, cpu);
+        buf->head = 0;
+        buf->written = 0;
+    }
+
+    return 0;
+}
+
+static int cf_check function_tracer_init(struct trace_context *tr)
+{
+    int rc;
+
+    rc = function_tracer_clear(tr);
+    if ( rc )
+        return rc;
+
+    return trace_register_callback(function_trace_callback);
+}
+
+static int cf_check function_tracer_reset(struct trace_context *tr)
+{
+    return trace_unregister_callback();
+}
+
+static void format_ip(char *buf, size_t size, unsigned long ip)
+{
+    const char *name;
+    unsigned long sym_size, offset;
+    char namebuf[KSYM_NAME_LEN + 1];
+
+    name = symbols_lookup(ip, &sym_size, &offset, namebuf);
+    if ( name )
+        snprintf(buf, size, "%s", name);
+    else
+        snprintf(buf, size, "0x%lx", ip);
+}
+
+static unsigned int cf_check function_tracer_get_trace_size(struct 
trace_context *tr)
+{
+    unsigned int size = sizeof(function_trace_header) + 128;
+    unsigned int cpu, count;
+    struct function_trace_cpu_buffer *buf;
+
+    for_each_online_cpu ( cpu )
+    {
+        buf = &per_cpu(function_trace_buffer, cpu);
+        count = min(buf->written, (uint64_t)FUNCTION_TRACE_BUFSIZE);
+        size += count * FUNCTION_TRACE_RECORD_TEXT_SIZE;
+    }
+
+    return size;
+}
+
+static size_t cf_check function_tracer_print_trace(struct trace_context *tr, 
char *buf, size_t size)
+{
+    struct buffer_iterator *iters;
+    unsigned int cpu, nr_iters = 0;
+    uint64_t entries = 0, written = 0;
+    size_t pos = 0;
+
+    iters = xzalloc_array(struct buffer_iterator, nr_cpu_ids);
+    if ( !iters )
+        return scnprintf(buf, size, "# unable to allocate trace iterators\n");
+
+    pos += scnprintf(buf + pos, size - pos, "# tracer: function\n#\n");
+
+    for_each_online_cpu ( cpu )
+    {
+        const struct function_trace_cpu_buffer *cbuf = 
&per_cpu(function_trace_buffer, cpu);
+        struct buffer_iterator *iter = &iters[nr_iters++];
+
+        iter->buffer = cbuf;
+        iter->count = min(cbuf->written, (uint64_t)FUNCTION_TRACE_BUFSIZE);
+        iter->start = cbuf->written >= FUNCTION_TRACE_BUFSIZE ? cbuf->head : 0;
+
+        entries += iter->count;
+        written += cbuf->written;
+    }
+
+    pos += scnprintf(buf + pos, size - pos,
+                     "# entries-in-buffer/entries-written: "
+                     "%"PRIu64"/%"PRIu64"   #P:%u\n",
+                     entries, written, num_online_cpus());
+    pos += scnprintf(buf + pos, size - pos, "%s", function_trace_header);
+
+    while ( pos < size - 1 )
+    {
+        const struct function_trace_record *rec = NULL;
+        unsigned int i, selected = 0;
+        char func_str[KSYM_NAME_LEN];
+        char parent_str[KSYM_NAME_LEN];
+        char vcpu_str[32];
+        uint64_t seconds;
+        unsigned int useconds;
+
+        for ( i = 0; i < nr_iters; i++ )
+        {
+            const struct buffer_iterator *iter = &iters[i];
+            const struct function_trace_record *next_rec;
+            unsigned int idx;
+
+            if ( iter->next == iter->count )
+                continue;
+
+            idx = (iter->start + iter->next) % FUNCTION_TRACE_BUFSIZE;
+            next_rec = &iter->buffer->records[idx];
+
+            if ( !rec || next_rec->timestamp < rec->timestamp )
+            {
+                rec = next_rec;
+                selected = i;
+            }
+        }
+
+        if ( !rec )
+            break;
+
+        iters[selected].next++;
+
+        format_ip(func_str, sizeof(func_str), rec->ip);
+        format_ip(parent_str, sizeof(parent_str), rec->parent_ip);
+
+        seconds = rec->timestamp / 1000000000ULL;
+        useconds = (rec->timestamp % 1000000000ULL) / 1000;
+
+        if ( rec->context_flags & FUNCTION_TRACE_CTX_IDLE )
+            snprintf(vcpu_str, sizeof(vcpu_str), "idle");
+        else
+            snprintf(vcpu_str, sizeof(vcpu_str), "d%u/v%u",
+                     rec->domid, rec->vcpuid);
+
+        pos += scnprintf(buf + pos, size - pos,
+                         "%14s [%03u] %c%c%c%3u %13"PRIu64".%06u: %s <-%s\n",
+                         vcpu_str, rec->pcpu,
+                         rec->context_flags & FUNCTION_TRACE_CTX_IRQS_OFF ? 
'y' : 'n',
+                         rec->context_flags & FUNCTION_TRACE_CTX_RESCHED ? 'y' 
: 'n',
+                         rec->context_flags & FUNCTION_TRACE_CTX_IRQ ? 'y' : 
'n',
+                         rec->preempt_depth, seconds, useconds, func_str, 
parent_str);
+    }
+
+    xfree(iters);
+
+    return pos;
+}
+
+static struct tracer function_tracer = {
+    .name = "function",
+    .init = function_tracer_init,
+    .reset = function_tracer_reset,
+    .clear_trace = function_tracer_clear,
+    .get_trace_size = function_tracer_get_trace_size,
+    .print_trace = function_tracer_print_trace,
+};
+
+static int __init cf_check function_trace_init(void)
+{
+    return trace_register_tracer(&function_tracer);
+}
+__initcall(function_trace_init);
-- 
2.34.1