dbus tools: print averages

This adds collecting and printing of average timings for
the dbus tools. Unfortunately, it is in a copy & paste style
as I didn't find a way to share BPF maps code between the tools.
I've even tried static implementation in an included header. Doesn't work.
Apparently bcc needs it in one file, analysed by bcc, before
it is passed to libllvm's preprocessor.

Change-Id: Id1c259b47ee7cfb0b05ac36d4800ea041af11e9c

diff --git a/tools/dbus-glib-client-sending.c b/tools/dbus-glib-client-sending.c
index 340788d765b3c75471905ffb0a51f9ce0b9c3c8c..a98c754f45c9858d55ae6892a7e40ad3b3fb9313 100644 (file)
--- a/tools/dbus-glib-client-sending.c
+++ b/tools/dbus-glib-client-sending.c
@@ -3,6 +3,20 @@
 #include <hostcompat/dbus/gio.h>
 #include "dbus-glib-tools.h"
 
+BPF_ARRAY(count_averages, u64, 2);
+#define INDEX_OF_AVERAGE_VALUE 0
+#define INDEX_OF_NUMBER_OF_SAMPLES 1
+
+static void average_add(u64 val) {
+       int avg = INDEX_OF_AVERAGE_VALUE;
+       u64 *current_avg;
+
+       count_averages.increment(INDEX_OF_NUMBER_OF_SAMPLES);
+       current_avg = count_averages.lookup(&avg);
+       if (current_avg)
+               lock_xadd(current_avg, val);
+}
+
 /* 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);
@@ -44,6 +58,7 @@ int handle_worker_send_message(struct pt_regs      *ctx,
        msg_sending.delete(&key);
 
        timings.increment(bpf_log2l(ns_to_us(timestamp)));
+       average_add(timestamp);
 
        return 0;
 }

diff --git a/tools/dbus-glib-client-sending.py b/tools/dbus-glib-client-sending.py
index ce2ee2f31d1c0e6179bbea8c6ae5b2cc0265edb9..92dd512de3a0b3b8179dae469ce485d42b8207e7 100755 (executable)
--- a/tools/dbus-glib-client-sending.py
+++ b/tools/dbus-glib-client-sending.py
@@ -44,6 +44,9 @@ while (1):
                print(" containers stats:")
                print('     msg_sending:', msgs)
 
+       if b["count_averages"][1].value > 0:
+               print('Average:', (b["count_averages"][0].value // b["count_averages"][1].value) // 1000)
+
        if count == loop:
                print('Finished')
                break

diff --git a/tools/dbus-glib-receiving.c b/tools/dbus-glib-receiving.c
index 5da43936bfa6ec57608ae8c325642d98e5762232..b07ed2fef980723bc50aaa592fa06e474194b274 100644 (file)
--- a/tools/dbus-glib-receiving.c
+++ b/tools/dbus-glib-receiving.c
@@ -43,6 +43,20 @@ int handle_message_delete(struct pt_regs *ctx, struct GDBusMessage *msg) {
        return 0;
 }
 
+BPF_ARRAY(count_averages, u64, 2);
+#define INDEX_OF_AVERAGE_VALUE 0
+#define INDEX_OF_NUMBER_OF_SAMPLES 1
+
+static void average_add(u64 val) {
+       int avg = INDEX_OF_AVERAGE_VALUE;
+       u64 *current_avg;
+
+       count_averages.increment(INDEX_OF_NUMBER_OF_SAMPLES);
+       current_avg = count_averages.lookup(&avg);
+       if (current_avg)
+               lock_xadd(current_avg, val);
+}
+
 /********** method calls *************/
 struct value_msg_ptr_t {
        struct GDBusMessage *msg_ptr;
@@ -106,6 +120,7 @@ int handle_call_in_idle_cb(struct pt_regs *ctx, void *user_data) {
        msg_on_worker_received.delete(&wrk_key);
 
        timings.increment(bpf_log2l(ns_to_us(timestamp)));
+       average_add(timestamp);
 
        return 0;
 }
@@ -171,6 +186,7 @@ int handle_task_return_now(struct pt_regs *ctx, void *task) {
        msg_on_worker_received.delete(&wrk_key);
 
        timings.increment(bpf_log2l(ns_to_us(timestamp)));
+       average_add(timestamp);
 
        return 0;
 }
@@ -217,6 +233,7 @@ int handle_emit_signal(struct pt_regs *ctx, void *user_data) {
        msg_on_worker_received.delete(&key);
 
        timings.increment(bpf_log2l(ns_to_us(timestamp)));
+       average_add(timestamp);
 
        return 0;
 }

diff --git a/tools/dbus-glib-receiving.py b/tools/dbus-glib-receiving.py
index 9587899ddb4ff1c952c63a680fcbf9b252016835..f19c58591cea215bced8ad9437e8977acc5229ea 100755 (executable)
--- a/tools/dbus-glib-receiving.py
+++ b/tools/dbus-glib-receiving.py
@@ -92,6 +92,9 @@ while (1):
                if invocations > 0: print('     invocation_to_message :', invocations)
                if tasks > 0:       print('     task_to_message       :', tasks)
 
+       if b["count_averages"][1].value > 0:
+               print('Average:', (b["count_averages"][0].value // b["count_averages"][1].value) // 1000)
+
        if count == loop:
                print('Finished')
                break

diff --git a/tools/dbus-glib-sending.c b/tools/dbus-glib-sending.c
index 07008f8b1774093598e5e51ee8f4c185698fc6f4..dcfbfb02e731182eb92b854a11b53b7373f839df 100644 (file)
--- a/tools/dbus-glib-sending.c
+++ b/tools/dbus-glib-sending.c
@@ -3,6 +3,20 @@
 #include <hostcompat/dbus/gio.h>
 #include "dbus-glib-tools.h"
 
+BPF_ARRAY(count_averages, u64, 2);
+#define INDEX_OF_AVERAGE_VALUE 0
+#define INDEX_OF_NUMBER_OF_SAMPLES 1
+
+static void average_add(u64 val) {
+       int avg = INDEX_OF_AVERAGE_VALUE;
+       u64 *current_avg;
+
+       count_averages.increment(INDEX_OF_NUMBER_OF_SAMPLES);
+       current_avg = count_averages.lookup(&avg);
+       if (current_avg)
+               lock_xadd(current_avg, val);
+}
+
 /* 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);
@@ -43,6 +57,7 @@ int handle_about_to_be_sent(struct pt_regs      *ctx,
        msg_sending.delete(&key);
 
        timings.increment(bpf_log2l(ns_to_us(timestamp)));
+       average_add(timestamp);
 
        return 0;
 }

diff --git a/tools/dbus-glib-sending.py b/tools/dbus-glib-sending.py
index 737e33f57c5132dbbfc5e2b2d69cf2ec57d546d5..a87eb7e2ec497603d3dfd081f49cc495529dca3d 100755 (executable)
--- a/tools/dbus-glib-sending.py
+++ b/tools/dbus-glib-sending.py
@@ -44,6 +44,9 @@ while (1):
                print(" containers stats:")
                print('     msg_sending:', msgs)
 
+       if b["count_averages"][1].value > 0:
+               print('Average:', (b["count_averages"][0].value // b["count_averages"][1].value) // 1000)
+
        if count == loop:
                print('Finished')
                break

diff --git a/tools/dbus-latency.c b/tools/dbus-latency.c
index f196aa772525e1b553c9030fca36c6702c159ead..9f8e541eba2e1e816f7f90de970679851d4444c8 100644 (file)
--- a/tools/dbus-latency.c
+++ b/tools/dbus-latency.c
@@ -27,7 +27,6 @@ struct stats_t {
 
 BPF_HASH(msg_sent_addr, u32 , struct data_t);
 BPF_HASH(msg_latency, struct data_t , struct stats_t);
-BPF_HASH(g_serial_addr, struct data_t, struct GDBusMessage *);
 BPF_HISTOGRAM(latency_histo);
 
 static void get_process_data(struct data_t *data) {
@@ -156,6 +155,7 @@ static int get_delay(int serial, struct data_t *receiver_data) {
                        return 0;
                }
                latency_histo.increment(bpf_log2l(delta));
+
                receiver_data->pid = s_data.pid;
                receiver_data->ts  = 0;
                bpf_probe_read(&receiver_data->comm, sizeof(receiver_data->comm), s_data.comm);

diff --git a/tools/dbus-latency.py b/tools/dbus-latency.py
index 2e997a617fd4636f43ba5b21eba1294f62f9599e..1a302f40274200b3f82564ebf38e2047a35ac555 100755 (executable)
--- a/tools/dbus-latency.py
+++ b/tools/dbus-latency.py
@@ -48,11 +48,18 @@ while (1):
        sleep(interval)
        loop = loop + 1
        print("\n%d:" % loop)
+       latency = b["msg_latency"]
        if mode =="histogram":
                b["latency_histo"].print_log2_hist("us")
+               avgcnt = 0
+               avgval = 0
+               for v, p in latency.items():
+                       avgcnt += long(p.count)
+                       avgval += long(p.count) * long(p.avg)
+               if avgcnt > 0:
+                       print 'Average:', avgval // avgcnt
        else:
                print ("%10s %20s %10s %10s %10s" % ("PID", "COMM", "MIN", "AVG", "MAX"))
-               latency = b["msg_latency"]
                for v, p in sorted(latency.items(), key=lambda latency: latency[1].avg, reverse=True):
                        print("%10d %20s %10d %10d %10d" % (v.pid, v.comm.encode('string-escape'), int(p.min), int(p.avg), int(p.max)))