commit a3ee406b6ec642435a107c5c1b2130e9d32c9fb3 Author: Harald Welte Date: Sat Sep 26 17:10:29 2020 +0200 initial checkin of tool to analyze libosmocore logging latency diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..20b9261 --- /dev/null +++ b/Makefile @@ -0,0 +1,9 @@ +LIBS:=`pkg-config --libs libosmocore` +CFLAGS:=-g -Wall `pkg-config --cflags libosmocore` + + +osmo-logbench: osmo-logbench.o + $(CC) $(CFLAGS) -o $@ $^ $(LIBS) + +%.o: %.c + $(CC) -o $@ -c $^ diff --git a/libosmo-log.bt b/libosmo-log.bt new file mode 100755 index 0000000..a1b697f --- /dev/null +++ b/libosmo-log.bt @@ -0,0 +1,22 @@ +#!/usr/bin/env bpftrace + +BEGIN +{ + printf("Tracing libosmocore log latency... Hit Ctrl-C to end.\n"); +} + +usdt:/usr/local/lib/libosmocore.so.16.0.0:libosmocore:log_start +{ + @start[tid] = nsecs; +} + +usdt:/usr/local/lib/libosmocore.so.16.0.0:libosmocore:log_done +{ + @usecs = hist((nsecs - @start[tid]) / 1000); + delete(@start[tid]); +} + +END +{ + clear(@start); +} diff --git a/libosmocore-usdt.patch b/libosmocore-usdt.patch new file mode 100644 index 0000000..97cf3c2 --- /dev/null +++ b/libosmocore-usdt.patch @@ -0,0 +1,246 @@ +From d08b4443ea1e5cd64a394832c4af685e06110fcc Mon Sep 17 00:00:00 2001 +From: Harald Welte +Date: Sat, 26 Sep 2020 11:51:32 +0200 +Subject: [PATCH] initial support for static userspace probes via systemtap + +This adds a --enable-systemtap configure option, which will then +add static tracepoints to the generated libosmocore binary. + +At this point, only two tracepoints are supported: stderr_start +and stderr_done. They can be used to trace the amount of time +a libosmocore-using application spends in blocking calls to log +to stderr. + +Change-Id: I7e1ab664241deb524c9582cbd1bec31af46c747e +--- + Makefile.am | 2 +- + configure.ac | 33 +++++++++++++++++++++++++++++++++ + src/Makefile.am | 12 ++++++++++++ + src/logging.c | 23 ++++++++++++++++++++++- + src/probes.d | 7 +++++++ + tapset/Makefile.am | 22 ++++++++++++++++++++++ + tapset/libosmocore.stp | 18 ++++++++++++++++++ + 7 files changed, 115 insertions(+), 2 deletions(-) + create mode 100644 src/probes.d + create mode 100644 tapset/Makefile.am + create mode 100644 tapset/libosmocore.stp + +diff --git a/Makefile.am b/Makefile.am +index f2a05a96..ab2aad92 100644 +--- a/Makefile.am ++++ b/Makefile.am +@@ -1,7 +1,7 @@ + ACLOCAL_AMFLAGS = -I m4 + + AM_CPPFLAGS = $(all_includes) -I$(top_srcdir)/include +-SUBDIRS = include src src/vty src/codec src/gsm src/coding src/gb src/ctrl src/sim src/pseudotalloc src/usb utils tests ++SUBDIRS = include src src/vty src/codec src/gsm src/coding src/gb src/ctrl src/sim src/pseudotalloc src/usb utils tapset tests + + pkgconfigdir = $(libdir)/pkgconfig + pkgconfig_DATA = libosmocore.pc libosmocodec.pc libosmovty.pc libosmogsm.pc \ +diff --git a/configure.ac b/configure.ac +index b07a3bd6..e26d8a8b 100644 +--- a/configure.ac ++++ b/configure.ac +@@ -392,6 +392,38 @@ AC_MSG_CHECKING([whether to enable ARM NEON instructions support]) + AC_MSG_RESULT([$neon]) + AM_CONDITIONAL(HAVE_NEON, [test "x$neon" != "xno"]) + ++# ++# SystemTap support ++# ++AC_MSG_CHECKING([whether to include systemtap tracing support]) ++AC_ARG_ENABLE([systemtap], ++ [AS_HELP_STRING([--enable-systemtap], ++ [Enable inclusion of systemtap trace support])], ++ [ENABLE_SYSTEMTAP="${enableval}"], [ENABLE_SYSTEMTAP='no']) ++AM_CONDITIONAL([ENABLE_SYSTEMTAP], [test x$ENABLE_SYSTEMTAP = xyes]) ++AC_MSG_RESULT(${ENABLE_SYSTEMTAP}) ++ ++if test "x${ENABLE_SYSTEMTAP}" = xyes; then ++ # Additional configuration for --enable-systemtap is HERE ++ AC_CHECK_PROGS(DTRACE, dtrace) ++ if test -z "$DTRACE"; then ++ AC_MSG_ERROR([dtrace not found]) ++ fi ++ AC_CHECK_HEADER([sys/sdt.h], [SDT_H_FOUND='yes'], ++ [SDT_H_FOUND='no'; ++ AC_MSG_ERROR([systemtap support needs sys/sdt.h header])]) ++ AC_DEFINE([HAVE_SYSTEMTAP], [1], [Define to 1 if using SystemTap probes.]) ++ AC_ARG_WITH([tapset-install-dir], ++ [AS_HELP_STRING([--with-tapset-install-dir], ++ [The absolute path where the tapset dir will be installed])], ++ [if test "x${withval}" = x; then ++ ABS_TAPSET_DIR="\$(datadir)/systemtap/tapset" ++ else ++ ABS_TAPSET_DIR="${withval}" ++ fi], [ABS_TAPSET_DIR="\$(datadir)/systemtap/tapset"]) ++ AC_SUBST(ABS_TAPSET_DIR) ++fi ++ + + OSMO_AC_CODE_COVERAGE + +@@ -446,6 +478,7 @@ AC_OUTPUT( + src/gb/Makefile + src/ctrl/Makefile + src/pseudotalloc/Makefile ++ tapset/Makefile + tests/Makefile + tests/atlocal + utils/Makefile +diff --git a/src/Makefile.am b/src/Makefile.am +index 891b4a6f..f03ce559 100644 +--- a/src/Makefile.am ++++ b/src/Makefile.am +@@ -28,6 +28,7 @@ libosmocore_la_SOURCES = context.c timer.c timer_gettimeofday.c timer_clockgetti + sockaddr_str.c \ + use_count.c \ + exec.c \ ++ probes.d \ + $(NULL) + + if HAVE_SSSE3 +@@ -71,5 +72,16 @@ if ENABLE_SERIAL + libosmocore_la_SOURCES += serial.c + endif + ++if ENABLE_SYSTEMTAP ++probes.h: probes.d ++ $(DTRACE) -C -h -s $< -o $@ ++ ++probes.lo: probes.d ++ $(LIBTOOL) --mode=compile $(AM_V_lt) --tag=CC env CFLAGS="$(CFLAGS)" $(DTRACE) -C -G -s $< -o $@ ++ ++BUILT_SOURCES += probes.h probes.lo ++libosmocore_la_LIBADD += probes.lo ++endif ++ + crc%gen.c: crcXXgen.c.tpl + $(AM_V_GEN)sed -e's/XX/$*/g' $< > $@ +diff --git a/src/logging.c b/src/logging.c +index 212b0b99..b480f0b5 100644 +--- a/src/logging.c ++++ b/src/logging.c +@@ -44,6 +44,17 @@ + #include + #endif + ++#ifdef HAVE_SYSTEMTAP ++/* include the generated probes header and put markers in code */ ++#include "probes.h" ++#define TRACE(probe) probe ++#define TRACE_ENABLED(probe) probe ## _ENABLED() ++#else ++/* Wrap the probe to allow it to be removed when no systemtap available */ ++#define TRACE(probe) ++#define TRACE_ENABLED(probe) (0) ++#endif /* HAVE_SYSTEMTAP */ ++ + #include + #include + #include +@@ -642,9 +653,11 @@ void logp2(int subsys, unsigned int level, const char *file, int line, int cont, + { + va_list ap; + ++ LIBOSMOCORE_LOG_START(); + va_start(ap, format); + osmo_vlogp(subsys, level, file, line, cont, format, ap); + va_end(ap); ++ LIBOSMOCORE_LOG_DONE(); + } + + /*! Register a new log target with the logging core +@@ -831,6 +844,14 @@ void log_set_category_filter(struct log_target *target, int category, + } + + #if (!EMBEDDED) ++static void _stderr_output(struct log_target *target, unsigned int level, ++ const char *log) ++{ ++ LIBOSMOCORE_STDERR_START(strlen(log)); ++ fprintf(target->tgt_file.out, "%s", log); ++ fflush(target->tgt_file.out); ++ LIBOSMOCORE_STDERR_DONE(); ++} + static void _file_output(struct log_target *target, unsigned int level, + const char *log) + { +@@ -898,7 +919,7 @@ struct log_target *log_target_create_stderr(void) + + target->type = LOG_TGT_TYPE_STDERR; + target->tgt_file.out = stderr; +- target->output = _file_output; ++ target->output = _stderr_output; + return target; + #else + return NULL; +diff --git a/src/probes.d b/src/probes.d +new file mode 100644 +index 00000000..12840577 +--- /dev/null ++++ b/src/probes.d +@@ -0,0 +1,7 @@ ++provider libosmocore { ++ probe stderr_start(int); /* (int number of octets) */ ++ probe stderr_done() ++ ++ probe log_start(); ++ probe log_done() ++}; +diff --git a/tapset/Makefile.am b/tapset/Makefile.am +new file mode 100644 +index 00000000..a07a3b1d +--- /dev/null ++++ b/tapset/Makefile.am +@@ -0,0 +1,22 @@ ++.PHONY: clean-local install-data-hook uninstall-local ++ ++EXTRA_DIST = libosmocore.stp ++TAPSET_FILES = $(EXTRA_DIST) ++TAPSET_INSTALL_DIR = $(DESTDIR)@ABS_TAPSET_DIR@ ++ ++if ENABLE_SYSTEMTAP ++all-local: $(TAPSET_FILES) ++ ++clean-local: ++ ++install-data-hook: ++ $(MKDIR_P) $(TAPSET_INSTALL_DIR) ++ $(INSTALL_DATA) $(TAPSET_FILES) $(TAPSET_INSTALL_DIR) ++ ++uninstall-local: ++ @list='$(TAPSET_FILES)'; for p in $$list; do \ ++ echo " rm -f '$(TAPSET_INSTALL_DIR)/$$p'"; \ ++ rm -f "$(TAPSET_INSTALL_DIR)/$$p"; \ ++ done ++ ++endif +diff --git a/tapset/libosmocore.stp b/tapset/libosmocore.stp +new file mode 100644 +index 00000000..10fa7b24 +--- /dev/null ++++ b/tapset/libosmocore.stp +@@ -0,0 +1,18 @@ ++/* libosmocore tapset ++ * ++ * This file is part of libosmocore. ++ * ++ * Each probe defines the probe name and a full probestr which consist of the probe name and between ++ * brackets all argument names and values. ++ */ ++ ++probe libosmocore_stderr_start = process("libosmocore").mark("stderr_start") ++{ ++ count = $arg1; ++ probestr = sprintf("%s(count=%d), $$name, count); ++} ++ ++probe libosmocore_stderr_done = process("libosmocore").mark("stderr_done") ++{ ++ probestr = sprintf("%s", $$name); ++} +-- +2.28.0 + diff --git a/osmo-logbench.c b/osmo-logbench.c new file mode 100644 index 0000000..b85de94 --- /dev/null +++ b/osmo-logbench.c @@ -0,0 +1,47 @@ +#include + +#include +#include + +#define MAX_LINE_LEN 512 + +static unsigned int gen_len(void) +{ + int rnd; + do { + rnd = rand() % MAX_LINE_LEN; + } while (rnd <= 0); + return rnd; +} + +static void fill_buf(char *buf, unsigned int len) +{ + unsigned int i; + for (i = 0; i < len; i++) + buf[i] = 'a' + (i % 25); + buf[len] = '\0'; +} + +static void print_random_log(void) +{ + char buf[MAX_LINE_LEN+1]; + fill_buf(buf, gen_len()); + + LOGP(DLGLOBAL, LOGL_ERROR, "stress: %s\n", buf); +} +int main(int argc, char **argv) +{ + osmo_init_logging2(NULL, NULL); + +#if 0 + log_target_destroy(osmo_stderr_target); + struct log_target *tgt = log_target_create_gsmtap("localhost", 4729, "logbench", 0, 1); + log_add_target(tgt); + log_set_all_filter(tgt, 1); +#endif + + //for (int i = 0; i < 1000000; i++) { + while (1) { + print_random_log(); + } +} diff --git a/results/lenovo-x260/devnull.txt b/results/lenovo-x260/devnull.txt new file mode 100644 index 0000000..1057cf1 --- /dev/null +++ b/results/lenovo-x260/devnull.txt @@ -0,0 +1,32 @@ +@usecs: +[1] 2202080 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[2, 4) 26966 | | +[4, 8) 1107 | | +[8, 16) 305 | | +[16, 32) 10 | | +[32, 64) 6 | | +[64, 128) 0 | | +[128, 256) 0 | | +[256, 512) 1 | | +[512, 1K) 0 | | +[1K, 2K) 0 | | +[2K, 4K) 0 | | +[4K, 8K) 0 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 153 | | diff --git a/results/lenovo-x260/file-btrfs-ssd.txt b/results/lenovo-x260/file-btrfs-ssd.txt new file mode 100644 index 0000000..69fa203 --- /dev/null +++ b/results/lenovo-x260/file-btrfs-ssd.txt @@ -0,0 +1,31 @@ +@usecs: +[2, 4) 2275464 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[4, 8) 265612 |@@@@@@ | +[8, 16) 9384 | | +[16, 32) 368 | | +[32, 64) 4 | | +[64, 128) 24 | | +[128, 256) 3 | | +[256, 512) 1 | | +[512, 1K) 0 | | +[1K, 2K) 0 | | +[2K, 4K) 0 | | +[4K, 8K) 0 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 95 | | diff --git a/results/lenovo-x260/gnome-terminal.txt b/results/lenovo-x260/gnome-terminal.txt new file mode 100644 index 0000000..7945b31 --- /dev/null +++ b/results/lenovo-x260/gnome-terminal.txt @@ -0,0 +1,31 @@ +@usecs: +[2, 4) 32387 |@@@ | +[4, 8) 457668 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[8, 16) 44408 |@@@@@ | +[16, 32) 466 | | +[32, 64) 63 | | +[64, 128) 9 | | +[128, 256) 3 | | +[256, 512) 53 | | +[512, 1K) 0 | | +[1K, 2K) 0 | | +[2K, 4K) 0 | | +[4K, 8K) 1 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 39 | | +[64K, 128K) 125 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 1 | | diff --git a/results/lenovo-x260/gsmtap-nowqueue.txt b/results/lenovo-x260/gsmtap-nowqueue.txt new file mode 100644 index 0000000..88f05a7 --- /dev/null +++ b/results/lenovo-x260/gsmtap-nowqueue.txt @@ -0,0 +1,31 @@ +@usecs: +[4, 8) 776978 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[8, 16) 1771 | | +[16, 32) 60 | | +[32, 64) 0 | | +[64, 128) 1 | | +[128, 256) 0 | | +[256, 512) 0 | | +[512, 1K) 0 | | +[1K, 2K) 0 | | +[2K, 4K) 0 | | +[4K, 8K) 0 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 0 | | +[2G, 4G) 82 | | diff --git a/results/lenovo-x260/screen-attached-uxterm.txt b/results/lenovo-x260/screen-attached-uxterm.txt new file mode 100644 index 0000000..f9bce1d --- /dev/null +++ b/results/lenovo-x260/screen-attached-uxterm.txt @@ -0,0 +1,31 @@ +@usecs: +[2, 4) 2 | | +[4, 8) 67887 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[8, 16) 30378 |@@@@@@@@@@@@@@@@@@@@@@@ | +[16, 32) 58881 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | +[32, 64) 5188 |@@@ | +[64, 128) 301 | | +[128, 256) 61 | | +[256, 512) 3963 |@@@ | +[512, 1K) 7603 |@@@@@ | +[1K, 2K) 407 | | +[2K, 4K) 42 | | +[4K, 8K) 20 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 1 | | diff --git a/results/lenovo-x260/screen-detached.txt b/results/lenovo-x260/screen-detached.txt new file mode 100644 index 0000000..39207bc --- /dev/null +++ b/results/lenovo-x260/screen-detached.txt @@ -0,0 +1,31 @@ +@usecs: +[2, 4) 107649 |@@@@@@@@ | +[4, 8) 699672 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[8, 16) 15262 |@ | +[16, 32) 622 | | +[32, 64) 5840 | | +[64, 128) 42728 |@@@ | +[128, 256) 14000 |@ | +[256, 512) 68 | | +[512, 1K) 3 | | +[1K, 2K) 0 | | +[2K, 4K) 1 | | +[4K, 8K) 0 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 50 | | diff --git a/results/lenovo-x260/systemd-journald.txt b/results/lenovo-x260/systemd-journald.txt new file mode 100644 index 0000000..6a03222 --- /dev/null +++ b/results/lenovo-x260/systemd-journald.txt @@ -0,0 +1,30 @@ +[2, 4) 1060607 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[4, 8) 75133 |@@@ | +[8, 16) 724 | | +[16, 32) 107 | | +[32, 64) 8 | | +[64, 128) 8 | | +[128, 256) 0 | | +[256, 512) 0 | | +[512, 1K) 0 | | +[1K, 2K) 0 | | +[2K, 4K) 0 | | +[4K, 8K) 0 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 38 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 0 | | +[1G, 2G) 1 | | diff --git a/results/lenovo-x260/uxterm.txt b/results/lenovo-x260/uxterm.txt new file mode 100644 index 0000000..0bccbf4 --- /dev/null +++ b/results/lenovo-x260/uxterm.txt @@ -0,0 +1,30 @@ +@usecs: +[2, 4) 30 | | +[4, 8) 199963 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| +[8, 16) 82294 |@@@@@@@@@@@@@@@@@@@@@ | +[16, 32) 6897 |@ | +[32, 64) 1649 | | +[64, 128) 57 | | +[128, 256) 221 | | +[256, 512) 8588 |@@ | +[512, 1K) 13062 |@@@ | +[1K, 2K) 144 | | +[2K, 4K) 14 | | +[4K, 8K) 3 | | +[8K, 16K) 0 | | +[16K, 32K) 0 | | +[32K, 64K) 0 | | +[64K, 128K) 0 | | +[128K, 256K) 0 | | +[256K, 512K) 0 | | +[512K, 1M) 0 | | +[1M, 2M) 0 | | +[2M, 4M) 0 | | +[4M, 8M) 0 | | +[8M, 16M) 0 | | +[16M, 32M) 0 | | +[32M, 64M) 0 | | +[64M, 128M) 0 | | +[128M, 256M) 0 | | +[256M, 512M) 0 | | +[512M, 1G) 28 | |