initial checkin of tool to analyze libosmocore logging latency

This commit is contained in:
Harald Welte 2020-09-26 17:10:29 +02:00
commit a3ee406b6e
12 changed files with 571 additions and 0 deletions

9
Makefile Normal file
View File

@ -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 $^

22
libosmo-log.bt Executable file
View File

@ -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);
}

246
libosmocore-usdt.patch Normal file
View File

@ -0,0 +1,246 @@
From d08b4443ea1e5cd64a394832c4af685e06110fcc Mon Sep 17 00:00:00 2001
From: Harald Welte <laforge@osmocom.org>
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 <syslog.h>
#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 <time.h>
#include <sys/time.h>
#include <errno.h>
@@ -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

47
osmo-logbench.c Normal file
View File

@ -0,0 +1,47 @@
#include <stdlib.h>
#include <osmocom/core/logging.h>
#include <osmocom/core/application.h>
#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();
}
}

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |

View File

@ -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 | |