High Speed Fine Grained Diagnostic Logging

The sxe-log package of the libsxe library (see libsxe.org) has always had macro based logging with a decent feature set:

  • Trace and dump level messages compiled out in non-debug builds
  • In-line level checking for absolutely minimal performance impact when level is reduced
  • Environmental and programmatic control over the global log level

Today I merged and committed new fined grained controls into sxe-log. This a great step forward. The log level can now be set globally (via the SXE_LOG_LEVEL environment variable or the sxe_log_set_level function), for the libsxe library using SXE_LOG_LEVEL_LIBSXE, or for any package. For example, the level for the sxe-list package can be controlled with the SXE_LOG_LEVEL_LIBSXE_LIB_SXE_LIST environment variable. More specific settings take precedence.

I’ve never seen a log package that takes the approach we’ve taken. To achieve maximum performance in both release and debug builds, each file that includes sxe-log.h automatically declares a private log control object per thread using thread local storage. The macro wrappers of all log calls check the log level in this object before calling the into the log package. Once the log control’s level has been set, log calls at a higher level will not even be executed.

In case the log control level has not been set or is at least as high as the level of the log function being called, the log function is called. The first time a thread executes a function in the file, the control structure is added to a global list of all control structures. Thread safety is insured using lock-less atomic instructions:

/* If this is the first time this control structure has been accessed, link it into the list
if (control_self->next == NULL) {
    /* Keep trying to make our control structure the first in the list until we don't race with another thread.
    do {
        control_head = sxe_log_control_list;
    } while (__sync_val_compare_and_swap(&sxe_log_control_list, control_head, control_self) != control_head);

    control_self->next = control_head == NULL ? control_self : control_head;

Once linked, the various log levels that apply are checked, most to least specific. The names are derived from the file’s path name. For example, if you created a database subdirectory in your organizer project and it contained a file called main.c, the log level in that file would be set based on the value of SXE_LOG_LEVEL_ORGANIZER_DATABASE_MAIN or, if that were not set, SXE_LOG_LEVEL_ORGANIZER_DATABASE, or SXE_LOG_LEVEL_ORGANIZER, or, finally, the global log level.

As you can see, this is both flexible and efficient. Future enhancements planned for sxe_log include:

  • Add programmatic control of more specific levels
  • Add the stack traceback on abort
  • Add variadic macro wrappers to eliminate the need to count arguments to log functions
  • Automatically add the function name to function entry trace messages

About jimbelton

I'm a software developer, and a writer of both fiction and non-fiction, and I blog about movies, books, and philosophy. My interest in religious philosophy and the search for the truth inspires much of my writing.
This entry was posted in libsxe, programming and tagged , , , , , . Bookmark the permalink.

Leave a Comment

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )


Connecting to %s