From 56615e6c2dd0c58b91f16d17a8f6024cd745ebfc Mon Sep 17 00:00:00 2001 From: Adam Michalski Date: Thu, 30 Dec 2021 12:22:29 +0100 Subject: [PATCH] Add raw data mode to store every possible latency measurement result. Facilitates the creation of histograms from a large number of samples. Latencies are saved in a simple CSV file. Change-Id: I5d98289787a6f352f4998d421e87164e2145c901 --- benchmark/gdbus.c | 21 ++++++++++++++- benchmark/libdbus-p2p-server.cpp | 46 ++++++++++++++++++++++++++++---- benchmark/libdbus.c | 23 +++++++++++++++- benchmark/p2p-gdbus.c | 20 +++++++++++++- benchmark/pipe.c | 21 +++++++++++++-- benchmark/sharedmem.c | 21 +++++++++++++-- benchmark/socket.c | 21 +++++++++++++-- 7 files changed, 159 insertions(+), 14 deletions(-) diff --git a/benchmark/gdbus.c b/benchmark/gdbus.c index f1abff9..c4df6ab 100644 --- a/benchmark/gdbus.c +++ b/benchmark/gdbus.c @@ -21,6 +21,9 @@ unsigned long long bw; bool lt_on, bw_on; +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + static void server_name_acquired_handler (GDBusConnection *conn, const gchar *name, gpointer user_data) { } @@ -86,6 +89,8 @@ static void handle_method_call (GDBusConnection *connection, #ifdef DEBUG_ON printf("latency: %0.4f\n", lt); #endif + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); if(lt > 0) { lt_cnt++; @@ -380,10 +385,21 @@ void Measure_latency(void) perror("fork"); return; default: + if (raw_data_on) { + raw_data_fd = fopen("gdbus-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } + Receive(msize, "org.gdbus.server", "/org/gdbus/server", true); printf("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); + if (raw_data_on) + fclose(raw_data_fd); return; } } @@ -401,7 +417,7 @@ main(int argc, char **argv) msize = 3; lt_on = bw_on = false; - while((opt = getopt(argc, argv, "m:p:blh")) != -1) { + while((opt = getopt(argc, argv, "m:p:blhr")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -423,6 +439,9 @@ main(int argc, char **argv) case 'l': lt_on = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); diff --git a/benchmark/libdbus-p2p-server.cpp b/benchmark/libdbus-p2p-server.cpp index 44cf307..05d2e29 100644 --- a/benchmark/libdbus-p2p-server.cpp +++ b/benchmark/libdbus-p2p-server.cpp @@ -31,6 +31,8 @@ #include #include #include +#include +#include #include #include #include @@ -84,6 +86,10 @@ struct run_opts { * * Good for %-based comparisons, but avoid for time measurements. */ bool busy_wait = false; + + /* When enabled, the server collects all method call times and + * writes them out to a CSV file. Useful for distribution charts. */ + bool raw_data_on = false; }; run_opts get_opt (int argc, char ** argv) @@ -91,7 +97,7 @@ run_opts get_opt (int argc, char ** argv) run_opts ret; int opt; - while ((opt = getopt(argc, argv, "wit:p:h")) != -1) + while ((opt = getopt(argc, argv, "wit:p:rh")) != -1) switch (opt) { case 't': @@ -106,6 +112,9 @@ run_opts get_opt (int argc, char ** argv) case 'p': ret.sock_path = optarg; break; + case 'r': + ret.raw_data_on = true; + break; case 'h': default: ret.show_help = true; @@ -132,18 +141,24 @@ struct conn_with_metadata { size_t warmup_tries; + bool raw_data_on; + + std::ofstream &raw_data_out_file; + std::unique_ptr conn; bool finished; static DBusObjectPathVTable vtable; - conn_with_metadata (const run_opts & ro, DBusConnection * c) + conn_with_metadata (const run_opts & ro, DBusConnection * c, std::ofstream & rdof) : total_time (0) , total_count (0) , min_time (std::numeric_limits :: max ()) , max_time (std::numeric_limits :: min ()) , warmup_tries (ro.warmup_tries) + , raw_data_on(ro.raw_data_on) + , raw_data_out_file(rdof) , conn (c) , finished (false) { @@ -163,6 +178,8 @@ struct conn_with_metadata { , min_time (std::move(x.min_time)) , max_time (std::move(x.max_time)) , warmup_tries (std::move(x.warmup_tries)) + , raw_data_on (std::move(x.raw_data_on)) + , raw_data_out_file (x.raw_data_out_file) , conn (std::move(x.conn)) , finished (std::move(x.finished)) { @@ -192,6 +209,8 @@ struct conn_with_metadata { min_time = std::move(x.min_time); max_time = std::move(x.max_time); warmup_tries = std::move(x.warmup_tries); + raw_data_on = std::move(x.raw_data_on); + raw_data_out_file = std::move(x.raw_data_out_file); conn = std::move(x.conn); finished = std::move(x.finished); @@ -250,6 +269,11 @@ DBusObjectPathVTable conn_with_metadata::vtable = THIS->min_time = std::min (THIS->min_time, diff); THIS->max_time = std::max (THIS->max_time, diff); + + if (THIS->raw_data_on) { + THIS->raw_data_out_file << std::setprecision(4); + THIS->raw_data_out_file << (double)diff << std::endl; + } } else { -- THIS->warmup_tries; } @@ -266,6 +290,7 @@ void show_help (const char * argv0) << " [-p sock_path] " << " [-i (infinite listening)] " << " [-w (busy wait)] " + << " [-r (raw data dump)] " << std::endl ; } @@ -303,6 +328,7 @@ void read_from_watch (DBusWatch * watch, bool wait_infinitely) int main (int argc, char ** argv) { run_opts opt = get_opt (argc, argv); + std::ofstream raw_data_out_file; if (opt.show_help) { show_help (argv[0]); @@ -315,17 +341,27 @@ int main (int argc, char ** argv) return EXIT_FAILURE; } + if (opt.raw_data_on) { + raw_data_out_file.open("libdbus-p2p-latency.csv"); + if (!raw_data_out_file.is_open()) { + std::cerr << "cannot create raw data output file" << std::endl; + return EXIT_FAILURE; + } + raw_data_out_file << "Latency" << std::endl; + raw_data_out_file << std::fixed; + } + // Set up cleanup functions for `server` std::atexit (exit_func); std::signal (SIGINT , sig_handler); std::signal (SIGTERM, sig_handler); std::vector conns; - auto ud = std::make_pair (std::ref(opt), std::ref (conns)); + auto ud = std::make_tuple (std::ref(opt), std::ref (conns), std::ref(raw_data_out_file)); dbus_server_set_new_connection_function (server , [] (DBusServer * s, DBusConnection * c, void * data) { - auto [opts, connz] = *(reinterpret_cast (data)); - connz.emplace_back (opts, c); + auto [opts, connz, rdof] = *(reinterpret_cast (data)); + connz.emplace_back (opts, c, rdof); } , & ud // userdata , nullptr // userdata free func diff --git a/benchmark/libdbus.c b/benchmark/libdbus.c index de4a445..de38164 100644 --- a/benchmark/libdbus.c +++ b/benchmark/libdbus.c @@ -21,6 +21,9 @@ unsigned long long bw; bool lt_on, bw_on; bool stop; +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + static void unregistered_func (DBusConnection *connection, void *user_data) { } @@ -48,6 +51,9 @@ static DBusHandlerResult message_func (DBusConnection *connection, double lt = (double)(end - start) / 1000; + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); + if(lt) { lt_cnt++; total += lt; @@ -344,9 +350,21 @@ void Measure_latency(void) perror("fork"); return; default: + if (raw_data_on) { + raw_data_fd = fopen("libdbus-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } + Receive(msize, "org.libdbus.server", "/org/libdbus/server", true); printf("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); + + if (raw_data_on) + fclose(raw_data_fd); return; } } @@ -364,7 +382,7 @@ main(int argc, char **argv) msize = 3; lt_on = bw_on = false; - while((opt = getopt(argc, argv, "m:p:blh")) != -1) { + while((opt = getopt(argc, argv, "m:p:blhr")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -386,6 +404,9 @@ main(int argc, char **argv) case 'l': lt_on = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); diff --git a/benchmark/p2p-gdbus.c b/benchmark/p2p-gdbus.c index 8a38e93..fb63e8c 100644 --- a/benchmark/p2p-gdbus.c +++ b/benchmark/p2p-gdbus.c @@ -20,6 +20,9 @@ bool cpu_pin_to_same_core; /* specifies, whether client & server proces bool lt_on, /* latency test */ bw_on; /* bandwidth test */ +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + static GDBusNodeInfo *introspection_data = NULL; typedef struct _state { @@ -78,6 +81,8 @@ static void handle_method_call(GDBusConnection *connection, double lt = (double)(end - start) / 1000; if (state->verbose) g_print("latency: %0.4f\n", lt); + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); if (lt > 0) { /* latency */ lt_cnt++; total += lt; @@ -425,9 +430,19 @@ void Measure_latency(bool verbose) Send(msize, "org.gtk.GDBus.TestPeerInterface", "/org/gtk/GDBus/TestObject", "0", true, verbose); exit(0); default: /* parent process */ + if (raw_data_on) { + raw_data_fd = fopen("p2pgdbus-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } Receive(msize, "org.gtk.GDBus.TestPeerInterface", "/org/gtk/GDBus/TestObject", "0", true, verbose); g_print("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); /* wait for the child */ + if (raw_data_on) + fclose(raw_data_fd); } } @@ -570,7 +585,7 @@ int main(int argc, char *argv[]) n_real_tries = REAL_TRY; cpu_pin_to_same_core = false; - while ((opt = getopt(argc, argv, "m:p:blht:cv")) != -1) { + while ((opt = getopt(argc, argv, "m:p:blhrt:cv")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -605,6 +620,9 @@ int main(int argc, char *argv[]) case 'v': verbose = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); diff --git a/benchmark/pipe.c b/benchmark/pipe.c index 5d31e6e..0b649cb 100644 --- a/benchmark/pipe.c +++ b/benchmark/pipe.c @@ -13,6 +13,9 @@ unsigned long long bw; bool lt_on, bw_on; +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + void Receive(int rfd1, int rfd2, register int size, bool is_lt) { static int bw_cnt = 0; @@ -44,7 +47,8 @@ void Receive(int rfd1, int rfd2, register int size, bool is_lt) #ifdef DEBUG_ON printf("latency: %0.4f\n", lt); #endif - + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); if(lt > 0) { lt_cnt++; total += lt; @@ -295,6 +299,14 @@ void Measure_latency(void) perror("fork"); return; default: + if (raw_data_on) { + raw_data_fd = fopen("pipe-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } close(p1[1]); close(p2[1]); Receive(p1[0], p2[0], msize, true); @@ -302,6 +314,8 @@ void Measure_latency(void) close(p2[0]); printf("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); + if (raw_data_on) + fclose(raw_data_fd); return; } } @@ -319,7 +333,7 @@ main(int argc, char **argv) msize = 3; lt_on = bw_on = false; - while((opt = getopt(argc, argv, "m:p:blh")) != -1) { + while((opt = getopt(argc, argv, "m:p:blhr")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -341,6 +355,9 @@ main(int argc, char **argv) case 'l': lt_on = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); diff --git a/benchmark/sharedmem.c b/benchmark/sharedmem.c index 66a6644..ccfe4cc 100644 --- a/benchmark/sharedmem.c +++ b/benchmark/sharedmem.c @@ -19,6 +19,9 @@ unsigned long long bw; bool lt_on, bw_on; +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + void Receive(void *r1, register char *r2, register int size, bool is_lt) { static int bw_cnt = 0; @@ -50,7 +53,8 @@ repeat: #ifdef DEBUG_ON printf("latency: %0.4f\n", lt); #endif - + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); if(lt > 0) { lt_cnt++; total += lt; @@ -367,9 +371,19 @@ void Measure_latency(void) perror("fork"); return; default: + if (raw_data_on) { + raw_data_fd = fopen("sharedmem-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } Receive(shm_ptr[SHM1], shm_ptr[SHM2], msize, true); printf("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); + if (raw_data_on) + fclose(raw_data_fd); ret = munmap(shm_ptr[SHM1], sizeof(unsigned long long)); if (ret != 0) { perror("munmap"); @@ -410,7 +424,7 @@ main(int argc, char **argv) msize = 3; lt_on = bw_on = false; - while((opt = getopt(argc, argv, "m:p:blh")) != -1) { + while((opt = getopt(argc, argv, "m:p:blrh")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -432,6 +446,9 @@ main(int argc, char **argv) case 'l': lt_on = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); diff --git a/benchmark/socket.c b/benchmark/socket.c index b9c7f3c..7541689 100644 --- a/benchmark/socket.c +++ b/benchmark/socket.c @@ -13,6 +13,9 @@ unsigned long long bw; bool lt_on, bw_on; +bool raw_data_on; /* dump raw data (every possible result) */ +FILE *raw_data_fd; + void Receive(int rfd1, int rfd2, register int size, bool is_lt) { static int bw_cnt = 0; @@ -44,7 +47,8 @@ void Receive(int rfd1, int rfd2, register int size, bool is_lt) #ifdef DEBUG_ON printf("latency: %0.4f\n", lt); #endif - + if (raw_data_on) + fprintf(raw_data_fd, "%0.4f\n", lt); if(lt > 0) { lt_cnt++; total += lt; @@ -294,11 +298,21 @@ void Measure_latency(void) perror("fork"); return; default: + if (raw_data_on) { + raw_data_fd = fopen("socket-latency.csv", "w"); + if (raw_data_fd == NULL) { + perror("fopen"); + return; + } + fprintf(raw_data_fd, "Latency\n"); + } Receive(fd1[1], fd2[1], msize, true); close(fd1[1]); close(fd2[1]); printf("min: %0.4f(us), max: %0.4f(us), avg: %0.4f(us)\n", min, max, total/lt_cnt); waitpid(pid, NULL, 0); + if (raw_data_on) + fclose(raw_data_fd); return; } } @@ -316,7 +330,7 @@ main(int argc, char **argv) msize = 3; lt_on = bw_on = false; - while((opt = getopt(argc, argv, "m:p:blh")) != -1) { + while((opt = getopt(argc, argv, "m:p:blrh")) != -1) { switch(opt) { case 'm': msize = atoi(optarg); @@ -338,6 +352,9 @@ main(int argc, char **argv) case 'l': lt_on = true; break; + case 'r': + raw_data_on = true; /* dump raw data */ + break; case 'h': print_help(argv); exit(0); -- 2.34.1