Skip to content

Commit

Permalink
logging: Remove linker 'magic' and just use statics for logging calls…
Browse files Browse the repository at this point in the history 
…ites (#322)

It is my (and several others') opinion that the linker 'magic' used to maintain callsite data in libqb is hugely over complicated and unnecessarily fragile. It's main purpose seems to have been to improve performance but empirical testing shows this to be tiny at best. The overhead of sprintf makes minor optimisations in this code pointless.

With this code removed, libqb allocates callsites using a C static variable at run-time. This sounds bad but in actuality it merely moves the allocation from program load time to the first few milliseconds of program run-time. Applications like corosync and pacemaker spend most of their time in small loops doing the same work over and over again so the overhead doesn't apply and jitter does not occur.

We've tested this with corosync and pacemaker under valgrind and massif and the differences are minimal and even then only show up under artificial stress testing.

For this change I've bumped the soname up to 20 to indicate this is an incompatible change. I'm open to suggestions as to a release number but am currently thinking of 2.0.0
  • Loading branch information
@chrissie-c
chrissie-c authored Sep 27, 2018
1 parent d0ec0a6 commit 633f262
Show file tree
Hide file tree
Showing 6 changed files with 2 additions and 433 deletions.
150 changes: 0 additions & 150 deletions configure.ac
View file
Original file line number Diff line number Diff line change
Expand Up @@ -314,7 +314,6 @@ case $host_cpu in
powerpc*)
AC_MSG_RESULT([powerpc])
AC_DEFINE_UNQUOTED([QB_ARCH_POWERPC], [1], [powerpc])
ac_cv_link_attribute_section=no
nongcc_memory_barrier_needed=yes
arch_force_shmlba=yes
;;
Expand Down Expand Up @@ -360,7 +359,6 @@ case "$host_os" in
*cygwin*)
AC_DEFINE_UNQUOTED([QB_CYGWIN], [1],
[Compiling for Cygwin platform])
ac_cv_link_attribute_section=no
nongcc_memory_barrier_needed=yes
gcc_has_builtin_sync_operations=no
AC_MSG_RESULT([Cygwin])
Expand All @@ -369,7 +367,6 @@ case "$host_os" in
AC_DEFINE_UNQUOTED([QB_DARWIN], [1],
[Compiling for Darwin platform])
CP=rsync
ac_cv_link_attribute_section=no
dnl Attribute section appears to work here but fails later with:
dnl cc1: error in backend: Global variable 'descriptor.4902'
dnl has an invalid section specifier '__verbose': mach-o
Expand All @@ -384,9 +381,6 @@ case "$host_os" in
[Compiling for BSD platform])
case "$host_os" in
*netbsd*)
# this is because dlopen within a dl_iterate_phdr
# callback locks up.
ac_cv_link_attribute_section=no
AC_DEFINE_UNQUOTED([UNIX_PATH_MAX], [103],
[Unix path length])
;;
Expand All @@ -398,7 +392,6 @@ case "$host_os" in
AC_MSG_RESULT([BSD])
;;
*solaris*)
ac_cv_link_attribute_section=no
AC_DEFINE_UNQUOTED(DISABLE_IPC_SHM, 1,
[Disable shared mem ipc])
AC_DEFINE_UNQUOTED([QB_SOLARIS], [1],
Expand Down Expand Up @@ -530,10 +523,6 @@ AC_ARG_ENABLE([interlib-deps],
[AS_HELP_STRING([--disable-interlib-deps],
[disable inter-library dependencies (might break builds)])])

AC_ARG_ENABLE([nosection-fallback],
[AS_HELP_STRING([--enable-nosection-fallback],
[allow (logging compat-breaking?) fallback when orphan section dead-ended])])

AC_ARG_ENABLE([slow-tests],
[AS_HELP_STRING([--enable-slow-tests],[build and run slow tests])])

Expand Down Expand Up @@ -665,145 +654,6 @@ fi
AM_CONDITIONAL(HAVE_SLOW_TESTS, [test "x${enable_slow_tests}" = xyes])
AC_SUBST(HAVE_SLOW_TESTS)

# --- callsite sections ---
if test "x${GCC}" = xyes; then
AX_SAVE_FLAGS
AC_MSG_CHECKING([whether GCC supports __attribute__((section()) + ld supports orphan sections])
if test "x${ac_cv_link_attribute_section}" = x ; then
LDFLAGS="${LDFLAGS_save} -shared -fPIC" # we are compiling shared lib
AC_LINK_IFELSE(
[AC_LANG_SOURCE(
[[#include <assert.h>
extern int __start___verbose[], __stop___verbose[];
int test(void) {
static int my_var __attribute__((section("__verbose"))) = 3;
assert("L:non-empty data section"
&& __start___verbose != __stop___verbose);
assert("L:no data section value loss"
&& my_var == 3 /* for 2.29.1+ */);
return *((int *) __start___verbose); }]]
)],
[gcc_has_attribute_section=yes; cp "conftest${ac_exeext}" "conftest${shrext_cmds}"],
[gcc_has_attribute_section=no]
)
AX_RESTORE_FLAGS
else
gcc_has_attribute_section=${ac_cv_link_attribute_section}
fi
AC_MSG_RESULT($gcc_has_attribute_section)

# in the failing case (e.g. with ld from binutils 2.29), it's likely the
# following will fail readily in linkage (hidden symbol `__stop___verbose'
# in conftest is referenced by DSO), but keep the sensible test
# (in-executable symbol is expected to be propagated into the library,
# and to draw the full circle back to the executable through standard
# return value passing (respectively no-exec probing to spot the issue);
# -rpath passed because LD_LIBRARY_PATH exporting is unwieldy here);
# moreover, "my_var" == 3 assertion above (respectively checking if the
# boundary symbol visibility differs from DEFAULT in readelf output) is
# necessary so that binutils 2.29.1+ will not slip other parts of the
# overall is-workaround-needed harness, as it restored some (but not
# all) of the original behaviour, but the workaround is still provably
# needed
if test "x${gcc_has_attribute_section}" = xyes; then
AC_MSG_CHECKING([whether linker emits global boundary symbols for orphan sections])
LIBS="${LIBS} -L. -l:conftest${shrext_cmds} -Wl,-rpath=$(pwd)"
dnl could be turned to AC_TRY_RUN (first assertion is equivalent to
dnl the further check in action-if-true), but that would prevent
dnl cross-building
AC_LINK_IFELSE(
[AC_LANG_PROGRAM(
[[#include <assert.h>
extern int __start___verbose[], __stop___verbose[];
int test(void);]],
[[static int my_var __attribute__((section("__verbose"))) = 5;
assert("E:non-empty data section"
&& __start___verbose != __stop___verbose);
assert("E:no data section value loss"
&& my_var == test() /*5?*/);]]
)],
[# alternatively something like (but requires number parsing):
# readelf -SW "conftest${ac_exeext}" \
# | sed -n '/__verbose/s/^[[:space:]]*//p' | tr -s ' ' | cut -d" " -f6
verbose_start_addr=$(${NM} -g --portability -- "conftest${ac_exeext}" \
| grep __start___verbose | cut -d" " -f 3)
verbose_stop_addr=$(${NM} -g --portability -- "conftest${ac_exeext}" \
| grep __stop___verbose | cut -d" " -f 3)
test "${verbose_start_addr}" = "${verbose_stop_addr}" \
&& gcc_has_attribute_section_visible=no \
|| { verbose_start_type=$(${READELF} -s "conftest${shrext_cmds}" \
| sed -n \
'/__start___verbose/{s/^[[[[:space:]]]]*//p;q;}' \
| tr -s ' ' \
| cut -d" " -f6)
test "${verbose_start_type}" = DEFAULT \
&& gcc_has_attribute_section_visible=yes \
|| gcc_has_attribute_section_visible=no; }],
[gcc_has_attribute_section_visible=no]
)
AX_RESTORE_FLAGS
AC_MSG_RESULT($gcc_has_attribute_section_visible)
rm -f "conftest${shrext_cmds}"

if test "x${gcc_has_attribute_section_visible}" = xno; then
# check if the linker script based workaround is
# feasible at all, otherwise fallback to using no
# section attribute while making some noise about it
# as combining with-without accustomed logging
# participants is currently uncharted waters
AC_MSG_CHECKING([whether linker workaround for orphan sections usable])
>conftest.ld cat <<-EOF
SECTIONS {
__verbose : {
__start___verbose = .;
*(__verbose);
__stop___verbose = .;
}
}
EOF
LDFLAGS="${LDFLAGS} -Wl,conftest.ld"
AC_LINK_IFELSE(
[AC_LANG_PROGRAM(
[[#include <assert.h>
extern int __start___verbose[], __stop___verbose[];
int test(void);]],
[[static int my_var __attribute__((section("__verbose"))) = 5;
assert("E:non-empty data section"
&& __start___verbose != __stop___verbose);
assert("E:no data section value loss"
&& my_var == 5);]]
)],
[],
[gcc_has_attribute_section=no]
)
AX_RESTORE_FLAGS
AC_MSG_RESULT([$gcc_has_attribute_section])
rm -f "conftest.ld"
fi

if test "x${gcc_has_attribute_section}" = xyes; then
AC_DEFINE([QB_HAVE_ATTRIBUTE_SECTION], 1,
[Enabling code using __attribute__((section))])
AC_SUBST([client_dlopen_LIBS],[$dlopen_LIBS])
if test "x${gcc_has_attribute_section_visible}" = xyes; then
PACKAGE_FEATURES="$PACKAGE_FEATURES attribute-section"
else
AC_DEFINE([QB_NEED_ATTRIBUTE_SECTION_WORKAROUND], 1,
[Enabling code using __attribute__((section))])
PACKAGE_FEATURES="$PACKAGE_FEATURES attribute-section-workaround"
fi
elif test "x${enable_nosection_fallback}" = xyes; then
AC_MSG_NOTICE([Falling back to not using orphan section])
else
AC_MSG_ERROR([Would use section attribute, cannot; see --enable-nosection-fallback])
fi
fi
fi
AM_CONDITIONAL(HAVE_GCC_ATTRIBUTE_SECTION, [test "x${gcc_has_attribute_section}" = xyes])
AM_CONDITIONAL(NEED_GCC_ATTRIBUTE_SECTION_WORKAROUND,
[test "x${gcc_has_attribute_section}" = xyes \
&& test "x${gcc_has_attribute_section_visible}" != xyes])

# --- ansi ---
if test "x${enable_ansi}" = xyes && \
cc_supports_flag -std=iso9899:199409 ; then
Expand Down
3 changes: 0 additions & 3 deletions include/qb/qbconfig.h.in
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,9 +27,6 @@
/* need atomic memory barrier */
#undef QB_ATOMIC_OP_MEMORY_BARRIER_NEEDED

/* Enabling code using __attribute__((section)) */
#undef QB_HAVE_ATTRIBUTE_SECTION

/* versioning info: MAJOR, MINOR, MICRO, and REST components;
note that static compile-time info is not that useful as consulting
the respectively named members of qb_version struct constant under
Expand Down
130 changes: 0 additions & 130 deletions include/qb/qblog.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,15 +39,6 @@ extern "C" {
#include <qb/qbutil.h>
#include <qb/qbconfig.h>

#if defined(QB_KILL_ATTRIBUTE_SECTION) || defined(S_SPLINT_S)
#undef QB_HAVE_ATTRIBUTE_SECTION
#endif /* defined(QB_KILL_ATTRIBUTE_SECTION) || defined(S_SPLINT_S) */

#ifdef QB_HAVE_ATTRIBUTE_SECTION
#include <assert.h> /* possibly needed for QB_LOG_INIT_DATA */
#include <dlfcn.h> /* dynamic linking: dlopen, dlsym, dladdr, ... */
#endif

/**
* @file qblog.h
* The logging API provides four main parts (basics, filtering, threading & blackbox).
Expand Down Expand Up @@ -287,119 +278,7 @@ struct qb_log_callsite {

typedef void (*qb_log_filter_fn)(struct qb_log_callsite * cs);

/* will be assigned by linker magic (assuming linker supports that):
* https://sourceware.org/binutils/docs/ld/Orphan-Sections.html
*/
#ifdef QB_HAVE_ATTRIBUTE_SECTION

#define QB_ATTR_SECTION __verbose /* conforms to C ident. */
#define QB_ATTR_SECTION_STR QB_PP_STRINGIFY(QB_ATTR_SECTION)
#define QB_ATTR_SECTION_START QB_PP_JOIN(__start_, QB_ATTR_SECTION)
#define QB_ATTR_SECTION_STOP QB_PP_JOIN(__stop_, QB_ATTR_SECTION)
#define QB_ATTR_SECTION_START_STR QB_PP_STRINGIFY(QB_ATTR_SECTION_START)
#define QB_ATTR_SECTION_STOP_STR QB_PP_STRINGIFY(QB_ATTR_SECTION_STOP)

extern struct qb_log_callsite QB_ATTR_SECTION_START[];
extern struct qb_log_callsite QB_ATTR_SECTION_STOP[];

/* Related to the next macro that is -- unlike this one -- a public API */
#ifndef _GNU_SOURCE
#define QB_NONAPI_LOG_INIT_DATA_EXTRA_(name) \
_Pragma(QB_PP_STRINGIFY(GCC warning QB_PP_STRINGIFY( \
without "_GNU_SOURCE" defined (directly or not) \
QB_LOG_INIT_DATA cannot check sanity of libqb proper \
nor of the target site originating this check alone)))
#else
#define QB_NONAPI_LOG_INIT_DATA_EXTRA_(name) \
{ Dl_info work_dli; \
/* libqb sanity (locating libqb by it's relatively unique \
non-functional symbols -- the two are mutually exclusive, the \
ordinarily latter was introduced by accident, the former is \
intentional -- due to possible confusion otherwise) */ \
if ((dladdr(dlsym(RTLD_DEFAULT, "qb_ver_str"), &work_dli) \
|| dladdr(dlsym(RTLD_DEFAULT, "facilitynames"), &work_dli)) \
&& (work_handle = dlopen(work_dli.dli_fname, \
RTLD_LOCAL|RTLD_LAZY)) != NULL) { \
work_s1 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_START_STR); \
work_s2 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_STOP_STR); \
assert("libqb's callsite section is observable, otherwise \
libqb's build is at fault, preventing reliable logging" \
&& work_s1 != NULL && work_s2 != NULL); \
assert("libqb's callsite section is populated, otherwise \
libqb's build is at fault, preventing reliable logging" \
&& work_s1 != work_s2); \
dlclose(work_handle); } \
/* sanity of the target site originating this check alone */ \
if (dladdr(dlsym(RTLD_DEFAULT, QB_PP_STRINGIFY(name)), &work_dli) \
&& (work_handle = dlopen(work_dli.dli_fname, \
RTLD_LOCAL|RTLD_LAZY)) != NULL) { \
work_s1 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_START_STR); \
work_s2 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_STOP_STR); \
assert("target's own callsite section observable, otherwise \
target's own linkage at fault and logging would not work reliably \
(unless QB_LOG_INIT_DATA macro used unexpectedly in no-logging context)"\
&& work_s1 != NULL && work_s2 != NULL); \
assert("target's own callsite section non-empty, otherwise \
target's own linkage at fault and logging would not work reliably \
(unless QB_LOG_INIT_DATA macro used unexpectedly in no-logging context)"\
&& work_s1 != work_s2); \
dlclose(work_handle); } }
#endif /* _GNU_SOURCE */

/**
* Optional on-demand self-check of 1/ toolchain sanity (prerequisite for
* the logging subsystem to work properly) and 2/ non-void active use of
* logging (satisfied with a justifying existence of a logging callsite as
* defined with a @c qb_logt invocation) at the target (but see below), which
* is supposedly assured by it's author(!) as of relying on this very macro
* [technically, the symbols that happen to be resolved under the respective
* identifiers do not necessarily originate in the same compilation unit as
* when it's not the end executable (or by induction, a library positioned
* earlier in the symbol lookup order) but a shared library, the former takes
* a precedence unless that site comes short of exercising the logging,
* making its callsite section empty and, in turn, without such boundary
* symbols, hence making the resolution continue further in the lookup order
* -- despite fuzzily targeted attestation, the check remains reasonable];
* only effective when link-time ("run-time amortizing") callsite collection
* is; as a side effect, it can ensure the boundary-denoting symbols for the
* target collection area are kept alive with some otherwise unkind linkers.
*
* Applying this macro in the target program/library is strongly recommended
* whenever the logging as framed by this header file is in use.
* Moreover, it's important to state that using this check while not ensuring
* @c _GNU_SOURCE macro definition is present at compile-time means only half
* of the available sanity checking will be performed, possibly resulting
* in libqb's own internally logged messages being lost without warning.
*/
#define QB_LOG_INIT_DATA(name) \
void name(void); \
void name(void) { \
void *work_handle; struct qb_log_callsite *work_s1, *work_s2; \
/* our own (target's) sanity, or possibly that of higher priority \
symbol resolution site (unless target equals end executable) \
or even the lower one if no such predecessor defines these */ \
if ((work_handle = dlopen(NULL, RTLD_LOCAL|RTLD_LAZY)) != NULL) { \
work_s1 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_START_STR); \
work_s2 = (struct qb_log_callsite *) \
dlsym(work_handle, QB_ATTR_SECTION_STOP_STR); \
assert("implicit callsite section is observable, otherwise \
target's and/or libqb's build is at fault, preventing reliable logging" \
&& work_s1 != NULL && work_s2 != NULL); \
dlclose(work_handle); /* perhaps overly eager thing to do */ } \
QB_NONAPI_LOG_INIT_DATA_EXTRA_(name); \
/* finally, original, straightforward check */ \
assert("implicit callsite section is populated, otherwise \
target's build is at fault, preventing reliable logging" \
&& QB_ATTR_SECTION_START != QB_ATTR_SECTION_STOP); } \
void __attribute__ ((constructor)) name(void);
#else
#define QB_LOG_INIT_DATA(name)
#endif /* QB_HAVE_ATTRIBUTE_SECTION */

/**
* Internal function: use qb_log() or qb_logt()
Expand Down Expand Up @@ -477,21 +356,12 @@ void qb_log_from_external_source_va(const char *function,
* @param fmt usual printf style format specifiers
* @param args usual printf style args
*/
#ifdef QB_HAVE_ATTRIBUTE_SECTION
#define qb_logt(priority, tags, fmt, args...) do { \
static struct qb_log_callsite descriptor \
__attribute__((section(QB_ATTR_SECTION_STR), aligned(8))) = \
{ __func__, __FILE__, fmt, priority, __LINE__, 0, tags }; \
qb_log_real_(&descriptor, ##args); \
} while(0)
#else
#define qb_logt(priority, tags, fmt, args...) do { \
struct qb_log_callsite* descriptor_pt = \
qb_log_callsite_get(__func__, __FILE__, fmt, \
priority, __LINE__, tags); \
qb_log_real_(descriptor_pt, ##args); \
} while(0)
#endif /* QB_HAVE_ATTRIBUTE_SECTION */


/**
Expand Down
Loading

0 comments on commit 633f262

Please sign in to comment.