From: Adrian Szyndela Date: Tue, 18 Jan 2022 14:43:29 +0000 (+0100) Subject: dbus-tools: new tools for message path in glib X-Git-Tag: submit/tizen/20220713.022109~3 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=c3adde83a7ff5736f06bde951a038f68d69b7896;p=platform%2Fupstream%2Fbcc.git dbus-tools: new tools for message path in glib Add new tools for measurements: dbus-glib-client-sending - for gio API usage dbus-glib-sending - for threads gap while sending dbus-glib-receiving - for threads gap while receiving Change-Id: I3d26346df5a3f7273794d4e240acdc350fda2d67 --- diff --git a/src/cc/hostcompat/dbus/gio.h b/src/cc/hostcompat/dbus/gio.h index eadf65d2..080a99a3 100644 --- a/src/cc/hostcompat/dbus/gio.h +++ b/src/cc/hostcompat/dbus/gio.h @@ -85,4 +85,22 @@ struct GDBusMessage { // #endif G_OS_UNIX }; +struct _GDBusMethodInvocation +{ + /*< private >*/ + struct GObject parent_instance; + + /* construct-only properties */ + ptr_t sender; // const gchar * + ptr_t object_path; // const gchar *; + ptr_t interface_name ;// const gchar *; + ptr_t method_name; // const gchar *; + ptr_t method_info; // GDBusMethodInfo * + ptr_t property_info; // GDBusPropertyInfo * + ptr_t connection; // GDBusConnection * + ptr_t message; // GDBusMessage * + ptr_t parameters; // GVariant * + ptr_t user_data; // gpointer +}; + #endif // HOSTCOMPAT_GIO_H diff --git a/tools/dbus-glib-client-sending.c b/tools/dbus-glib-client-sending.c new file mode 100644 index 00000000..340788d7 --- /dev/null +++ b/tools/dbus-glib-client-sending.c @@ -0,0 +1,56 @@ +#include +#include +#include +#include "dbus-glib-tools.h" + +/* This histogram is meant to keep time intervals used for preparing a message to send + * by the sending API, just before such message is passed to 'gdbus' thread. */ +BPF_HISTOGRAM(timings); + +/* This hashmap contains mapping from a message pointer to a timestamp. + * It is meant to keep timestamps of using the sending API. */ +BPF_HASH(msg_sending, key_pointer_t, timestamp_value_t); + +int handle_send_message(struct pt_regs *ctx, + void *connection, /* GDBusConnection */ + struct GDBusMessage *message + /* we don't care about the rest of arguments */ + ) { + key_pointer_t key; + timestamp_value_t value; + + key_pointer_set_pointer(&key, message); + timestamp_value_set_timestamp(&value); + + msg_sending.update(&key, &value); + return 0; +} + +int handle_worker_send_message(struct pt_regs *ctx, + void *worker, + struct GDBusMessage *message, + char *blob, + size_t blob_len) { + key_pointer_t key; + timestamp_value_t *value; + u64 timestamp = get_current_timestamp(); + + key_pointer_set_pointer(&key, message); + value = msg_sending.lookup(&key); + if (value == 0) + return 0; + + timestamp -= timestamp_value_get_timestamp(value); + msg_sending.delete(&key); + + timings.increment(bpf_log2l(ns_to_us(timestamp))); + + return 0; +} + +int handle_message_delete(struct pt_regs *ctx, struct GDBusMessage *msg) { + key_pointer_t key; + key_pointer_set_pointer(&key, msg); + msg_sending.delete(&key); + return 0; +} diff --git a/tools/dbus-glib-client-sending.py b/tools/dbus-glib-client-sending.py new file mode 100755 index 00000000..ce2ee2f3 --- /dev/null +++ b/tools/dbus-glib-client-sending.py @@ -0,0 +1,49 @@ +#!/usr/bin/python3 + +from bcc import BPF +from time import sleep +import argparse + +parser = argparse.ArgumentParser( + description="Measure time interval between using the sending API for a message and handling it in a gdbus thread in glib", + formatter_class=argparse.RawDescriptionHelpFormatter) +parser.add_argument("interval", nargs="?", default=2, + help="output interval, in seconds") +parser.add_argument("count", nargs="?", default=-1, + help="number of outputs") + +args = parser.parse_args() +interval = int(args.interval) +loop = 0 +count = int(args.count) + +b = BPF(src_file="dbus-glib-client-sending.c") + +# Setup uprobes + +# ****** General +b.attach_uprobe(name="gio-2.0", sym="g_dbus_connection_send_message_unlocked", fn_name="handle_send_message") +b.attach_uprobe(name="gio-2.0", sym="_g_dbus_worker_send_message", fn_name="handle_worker_send_message") +# this uprobe function detects destroying of a message and removes any existing references +b.attach_uprobe(name="gio-2.0", sym="g_dbus_message_finalize", fn_name="handle_message_delete") + +# GO! +print("Hit Ctrl-C to end.") + +while (1): + sleep(interval) + loop = loop + 1 + print("\n%d:" % loop) + b["timings"].print_log2_hist("us") + + # Kinda debug part, but important - it shows any leftovers in hashmaps. + # This way, if it shows up, we can tell how bad it is. + msgs = len(b["msg_sending"].items()) + + if msgs > 0: + print(" containers stats:") + print(' msg_sending:', msgs) + + if count == loop: + print('Finished') + break diff --git a/tools/dbus-glib-receiving.c b/tools/dbus-glib-receiving.c new file mode 100644 index 00000000..5da43936 --- /dev/null +++ b/tools/dbus-glib-receiving.c @@ -0,0 +1,222 @@ +#include +#include +#include +#include "dbus-glib-tools.h" +/* + * This file contains functions aimed to measure the time interval between receiving a message and + * making it available in a target thread. + * They are meant to be compiled to eBPF byte code, and attached to appropriate uprobes. + * + * The general idea is: + * 1. Detect receiving of a message in on_worker_message_received + * Record timestamp: map message (serial, pointer?) -> timestamp + * key: (pid, pointer) + * value: timestamp + * 2. Detect first (possible) occurrence in a client thread, where the message data is available. + * The exact functions and data tracing flow depend on the message type. + * 3. Measure the time between 1 and 2. + */ + +/* This hashmap contains mapping from a message pointer to a timestamp. + * It is meant to keep timestamps of detection of message receiving. */ +BPF_HASH(msg_on_worker_received, key_pointer_t, timestamp_value_t); + +/* This histogram is meant to keep time intervals between detection of a message receiving + * and making its data available in a target thread. */ +BPF_HISTOGRAM(timings); + +int handle_on_worker_received(struct pt_regs *ctx, struct GDBusMessage *msg, void *user_data) { + key_pointer_t key; + timestamp_value_t value; + + key_pointer_set_pointer(&key, msg); + timestamp_value_set_timestamp(&value); + + msg_on_worker_received.update(&key, &value); + return 0; +} + +int handle_message_delete(struct pt_regs *ctx, struct GDBusMessage *msg) { + key_pointer_t key; + key_pointer_set_pointer(&key, msg); + msg_on_worker_received.delete(&key); + return 0; +} + +/********** method calls *************/ +struct value_msg_ptr_t { + struct GDBusMessage *msg_ptr; +}; +typedef struct value_msg_ptr_t value_msg_ptr_t; + +static void value_msg_ptr_set_msg_ptr(value_msg_ptr_t *value, void *msg_ptr) { + value->msg_ptr = (struct GDBusMessage *)msg_ptr; +} +static struct GDBusMessage *value_msg_ptr_get_msg_ptr(value_msg_ptr_t *value) { + return value->msg_ptr; +} + +/* There is an intermediate step for method calls - we track creation of + * GDBusMethodInvocation for a given message, and then we track when + * it is about to be used */ +/* This hashmap tracks invocation->message relationships */ +BPF_HASH(invocation_to_message, key_pointer_t, value_msg_ptr_t); + +int handle_ret_method_invocation_new(struct pt_regs *ctx) { + struct _GDBusMethodInvocation *invocation_ptr = + (struct _GDBusMethodInvocation *)PT_REGS_RC(ctx); + key_pointer_t key; + value_msg_ptr_t value; + + key_pointer_set_pointer(&key, invocation_ptr); + value_msg_ptr_set_msg_ptr(&value, (void *)invocation_ptr->message); + + invocation_to_message.update(&key, &value); + return 0; +} + +int handle_call_in_idle_cb(struct pt_regs *ctx, void *user_data) { +/* user_data is GDBusMethodInvocation */ + key_pointer_t itm_key; + value_msg_ptr_t *itm_value; + struct GDBusMessage *message; + + key_pointer_t wrk_key; + timestamp_value_t *wrk_value; + u64 timestamp = get_current_timestamp(); + + key_pointer_set_pointer(&itm_key, user_data); + + itm_value = invocation_to_message.lookup(&itm_key); + if (itm_value == 0) + return 0; + + message = value_msg_ptr_get_msg_ptr(itm_value); + invocation_to_message.delete(&itm_key); + + key_pointer_set_pointer(&wrk_key, message); + wrk_value = msg_on_worker_received.lookup(&wrk_key); + if (wrk_value == 0) { + bpf_trace_printk("no message %p connected to invocation\n", message); + bpf_trace_printk(" for pid %u\n", wrk_key.pid); + return 0; + } + + timestamp -= timestamp_value_get_timestamp(wrk_value); + msg_on_worker_received.delete(&wrk_key); + + timings.increment(bpf_log2l(ns_to_us(timestamp))); + + return 0; +} + +int handle_finalize_invocation(struct pt_regs *ctx, struct _GDBusMethodInvocation *invocation) { + key_pointer_t itm_key; + key_pointer_set_pointer(&itm_key, invocation); + invocation_to_message.delete(&itm_key); + return 0; +} + +/************** method returns, errors *******************/ +/* There is an intermediate step for method returns and errors - we track association of + * a GTask with a given message, and then we track when + * it is about to be used */ +/* This hashmap tracks task->message relationships */ +BPF_HASH(task_to_message, key_pointer_t, value_msg_ptr_t); + +int handle_task_return_pointer(struct pt_regs *ctx, void *task, struct GDBusMessage *message) { + key_pointer_t key; + value_msg_ptr_t value; + + /* first, check if we track such message pointer */ + key_pointer_t wrk_key; + key_pointer_set_pointer(&wrk_key, message); + if (msg_on_worker_received.lookup(&wrk_key) == 0) + return 0; + + /* ok, we track it, let's track the task */ + key_pointer_set_pointer(&key, task); + value_msg_ptr_set_msg_ptr(&value, message); + + task_to_message.update(&key, &value); + return 0; +} + +int handle_task_return_now(struct pt_regs *ctx, void *task) { + key_pointer_t ttm_key; + value_msg_ptr_t *ttm_value; + struct GDBusMessage *message; + + key_pointer_t wrk_key; + timestamp_value_t *wrk_value; + u64 timestamp = get_current_timestamp(); + + key_pointer_set_pointer(&ttm_key, task); + ttm_value = task_to_message.lookup(&ttm_key); + if (ttm_value == 0) + return 0; + + message = value_msg_ptr_get_msg_ptr(ttm_value); + task_to_message.delete(&ttm_key); + + key_pointer_set_pointer(&wrk_key, message); + wrk_value = msg_on_worker_received.lookup(&wrk_key); + if (wrk_value == 0) { + bpf_trace_printk("no message %p connected to task\n", message); + bpf_trace_printk(" for pid %u\n", wrk_key.pid); + return 0; + } + + timestamp -= timestamp_value_get_timestamp(wrk_value); + msg_on_worker_received.delete(&wrk_key); + + timings.increment(bpf_log2l(ns_to_us(timestamp))); + + return 0; +} + +int handle_finalize_task(struct pt_regs *ctx, void *invocation) { + key_pointer_t ttm_key; + + key_pointer_set_pointer(&ttm_key, invocation); + task_to_message.delete(&ttm_key); + return 0; +} + +/************** signals *******************/ +/* The SignalInstance is taken from gio source code. It's only here, not in gio.h, + * as it is a very specialized struct, used only for passing signals + * between gdbus and client threads. It is very, very unlikely to be + * needed anywhere else. + */ +typedef struct { + ptr_t subscriber; // SignalSubscriber *subscriber; /* (owned) */ + ptr_t message; // GDBusMessage *message; + ptr_t connection; // GDBusConnection *connection; + ptr_t sender; // const gchar *sender; /* (nullable) for peer-to-peer connections */ + ptr_t path; // const gchar *path; + ptr_t interface; // const gchar *interface; + ptr_t member; // const gchar *member; +} SignalInstance; + +/* We measure only the first subscriber, if any. + * If a signal is received, but there are no subscribers, then no measurements are recorded. + */ +int handle_emit_signal(struct pt_regs *ctx, void *user_data) { + SignalInstance *signal_instance = user_data; + key_pointer_t key; + timestamp_value_t *value; + u64 timestamp = get_current_timestamp(); + + key_pointer_set_pointer(&key, (void *)signal_instance->message); + value = msg_on_worker_received.lookup(&key); + if (value == 0) + return 0; + + timestamp -= timestamp_value_get_timestamp(value); + msg_on_worker_received.delete(&key); + + timings.increment(bpf_log2l(ns_to_us(timestamp))); + + return 0; +} diff --git a/tools/dbus-glib-receiving.py b/tools/dbus-glib-receiving.py new file mode 100755 index 00000000..9587899d --- /dev/null +++ b/tools/dbus-glib-receiving.py @@ -0,0 +1,97 @@ +#!/usr/bin/python3 + +from bcc import BPF +from time import sleep +import argparse + +parser = argparse.ArgumentParser( + description="Measure time interval between receiving a message and handling it in a client thread in glib", + formatter_class=argparse.RawDescriptionHelpFormatter) +parser.add_argument("--no-method-calls", action="store_true", + help="disable detecting D-Bus method calls") +parser.add_argument("--no-method-returns-and-errors", action="store_true", + help="disable detecting D-Bus method returns and errors") +parser.add_argument("--no-signals", action="store_true", + help="disable detecting D-Bus signals") +parser.add_argument("interval", nargs="?", default=2, + help="output interval, in seconds") +parser.add_argument("count", nargs="?", default=-1, + help="number of outputs") + +args = parser.parse_args() +interval = int(args.interval) +loop = 0 +count = int(args.count) + +b = BPF(src_file="dbus-glib-receiving.c") + +# Setup uprobes + +# ****** General + +# this uprobe function detects an incoming, constructed message and stores a reference to it +# it also stores time of detection of the message +b.attach_uprobe(name="gio-2.0", sym="on_worker_message_received", fn_name="handle_on_worker_received") + +# this uprobe function detects destroying of a message and removes any existing references +b.attach_uprobe(name="gio-2.0", sym="g_dbus_message_finalize", fn_name="handle_message_delete") + +# ****** Receiving method calls +if not args.no_method_calls: + # this uprobe function detects when a GDBusMethodInvocation is created, and stores a reference to it + b.attach_uretprobe(name="gio-2.0", sym="_g_dbus_method_invocation_new", fn_name="handle_ret_method_invocation_new") + + # this uprobe function detects when a GDBusMethodInvocation is handled in a client thread + # it removes any existing references to the invocation and the message associated with the invocation + # it also records time interval between detection of the message and this point + b.attach_uprobe(name="gio-2.0", sym="call_in_idle_cb", fn_name="handle_call_in_idle_cb") + + # this uprobe function detects non-handled method invocations for removing references + b.attach_uprobe(name="gio-2.0", sym="g_dbus_method_invocation_finalize", fn_name="handle_finalize_invocation") + +# ***** Receiving method returns and errors + +if not args.no_method_returns_and_errors: + # this uprobe function detects when a task is associated with a message, and stores a reference to it + b.attach_uprobe(name="gio-2.0", sym="g_task_return_pointer", fn_name="handle_task_return_pointer") + + # this uprobe function detects when a task is handled in a client thread + # it removes any existing references to the task and the message associated with the task + # it also records time interval between detection of the message and this point + b.attach_uprobe(name="gio-2.0", sym="g_task_return_now", fn_name="handle_task_return_now") + + # this uprobe function detects non-handled tasks for removing references + b.attach_uprobe(name="gio-2.0", sym="g_task_finalize", fn_name="handle_finalize_task") + +# ***** Receiving signals +if not args.no_method_returns_and_errors: + # this uprobe function detects when a signal is about to be delivered in a client thread + # it removes any existing references to the message + # it also records time interval between detection of the message and this point + # thus, it records only timings for the very first subscriber that receives the signal + b.attach_uprobe(name="gio-2.0", sym="emit_signal_instance_in_idle_cb", fn_name="handle_emit_signal") + +# GO! +print("Hit Ctrl-C to end.") + +while (1): + sleep(interval) + loop = loop + 1 + print("\n%d:" % loop) + b["timings"].print_log2_hist("us") + + # Kinda debug part, but important - it shows any leftovers in hashmaps. + # This way, if it shows up, we can tell how bad it is. + msgs = len(b["msg_on_worker_received"].items()) + invocations = len(b["invocation_to_message"].items()) + tasks = len(b["task_to_message"].items()) + + if msgs + invocations + tasks > 0: + print(" containers stats:") + if msgs > 0: print(' msg_on_worker_received:', msgs) + if invocations > 0: print(' invocation_to_message :', invocations) + if tasks > 0: print(' task_to_message :', tasks) + + if count == loop: + print('Finished') + break diff --git a/tools/dbus-glib-sending.c b/tools/dbus-glib-sending.c new file mode 100644 index 00000000..07008f8b --- /dev/null +++ b/tools/dbus-glib-sending.c @@ -0,0 +1,55 @@ +#include +#include +#include +#include "dbus-glib-tools.h" + +/* This histogram is meant to keep time intervals between detection of sending of a message + * and making its data available in a gdbus thread. */ +BPF_HISTOGRAM(timings); + +/* This hashmap contains mapping from a message pointer to a timestamp. + * It is meant to keep timestamps of detection of passing a message for sending + * to a gdbus thread from a client thread. */ +BPF_HASH(msg_sending, key_pointer_t, timestamp_value_t); + +int handle_worker_send_message(struct pt_regs *ctx, + void *worker, + struct GDBusMessage *message, + char *blob, + size_t blob_len) { + key_pointer_t key; + timestamp_value_t value; + + key_pointer_set_pointer(&key, message); + timestamp_value_set_timestamp(&value); + + msg_sending.update(&key, &value); + return 0; +} + +int handle_about_to_be_sent(struct pt_regs *ctx, + struct GDBusMessage *message, + void *user_data) { + key_pointer_t key; + timestamp_value_t *value; + u64 timestamp = get_current_timestamp(); + + key_pointer_set_pointer(&key, message); + value = msg_sending.lookup(&key); + if (value == 0) + return 0; + + timestamp -= timestamp_value_get_timestamp(value); + msg_sending.delete(&key); + + timings.increment(bpf_log2l(ns_to_us(timestamp))); + + return 0; +} + +int handle_message_delete(struct pt_regs *ctx, struct GDBusMessage *msg) { + key_pointer_t key; + key_pointer_set_pointer(&key, msg); + msg_sending.delete(&key); + return 0; +} diff --git a/tools/dbus-glib-sending.py b/tools/dbus-glib-sending.py new file mode 100755 index 00000000..737e33f5 --- /dev/null +++ b/tools/dbus-glib-sending.py @@ -0,0 +1,49 @@ +#!/usr/bin/python3 + +from bcc import BPF +from time import sleep +import argparse + +parser = argparse.ArgumentParser( + description="Measure time interval between using the sending API for a message and handling it in a gdbus thread in glib", + formatter_class=argparse.RawDescriptionHelpFormatter) +parser.add_argument("interval", nargs="?", default=2, + help="output interval, in seconds") +parser.add_argument("count", nargs="?", default=-1, + help="number of outputs") + +args = parser.parse_args() +interval = int(args.interval) +loop = 0 +count = int(args.count) + +b = BPF(src_file="dbus-glib-sending.c") + +# Setup uprobes + +# ****** General +b.attach_uprobe(name="gio-2.0", sym="_g_dbus_worker_send_message", fn_name="handle_worker_send_message") +b.attach_uprobe(name="gio-2.0", sym="on_worker_message_about_to_be_sent", fn_name="handle_about_to_be_sent") +# this uprobe function detects destroying of a message and removes any existing references +b.attach_uprobe(name="gio-2.0", sym="g_dbus_message_finalize", fn_name="handle_message_delete") + +# GO! +print("Hit Ctrl-C to end.") + +while (1): + sleep(interval) + loop = loop + 1 + print("\n%d:" % loop) + b["timings"].print_log2_hist("us") + + # Kinda debug part, but important - it shows any leftovers in hashmaps. + # This way, if it shows up, we can tell how bad it is. + msgs = len(b["msg_sending"].items()) + + if msgs > 0: + print(" containers stats:") + print(' msg_sending:', msgs) + + if count == loop: + print('Finished') + break diff --git a/tools/dbus-glib-tools.h b/tools/dbus-glib-tools.h new file mode 100644 index 00000000..b5b7ee2f --- /dev/null +++ b/tools/dbus-glib-tools.h @@ -0,0 +1,37 @@ +#pragma once + +#include + +typedef struct { + ptr_t pointer; + u32 pid; + u32 padding; +} key_pointer_t; + +static key_pointer_t *key_pointer_set_pointer(key_pointer_t *key, void *ptr) { + key->pointer = (ptr_t)ptr; + key->pid = bpf_get_current_pid_tgid() >> 32; + key->padding = 0; + return key; +} + +typedef struct { + u64 timestamp; +} timestamp_value_t; + +static u64 get_current_timestamp(void) { + return bpf_ktime_get_ns(); +} + +static timestamp_value_t *timestamp_value_set_timestamp(timestamp_value_t *value) { + value->timestamp = get_current_timestamp(); + return value; +} + +static u64 timestamp_value_get_timestamp(timestamp_value_t *value) { + return value->timestamp; +} + +static u64 ns_to_us(u64 ts) { + return ts / 1000; +}