Type-agnostic Tracing Using {fmt}

About eleven years ago, I was responsible for adding types that looked a bit like Listing 1 to a young C++ code base that lacked a standard way to do tracing for debugging. The implementation of AlwaysTrace::operator() wrote the trace message to an appropriate place.

struct NeverTrace {
    void operator()(const char *, ...)
      __attribute__((format(printf, 2, 3))) {}
};

struct AlwaysTrace {
    void operator()(const char *, ...)
      __attribute__((format(printf, 2, 3)));
};

#if DEBUG>0
typedef AlwaysTrace DebugTrace;
#else
typedef NeverTrace DebugTrace;
#endif
			

The intention was that each file could declare one or more instances of these types and use it throughout the code:

  static DebugTrace TRACE;
  void my_function(int i)
  {
    TRACE("A helpful message: %d\n", i);
  }

The real classes had various other helpful functions of course, and eventually we ended up with a global TRACE_ERROR instance that would always be emitted.

This worked reasonably well, and although we always had plans to improve the mechanism, we’ve never really got round to it. Some adornments to enable GCC’s printf format string checking and using -Werror meant that the risk of getting the format string wrong was low. It was annoying to have to use c_str() when tracing std::string instances, but we just lived with that.

I’d always planned to support tracing compound and custom types by adding some iostreams-like functionality but I never got round to it. In any case, my coworkers and I were generally not keen on iostreams for its verbosity and other reasons recently well described in [Ignatchenko18].

We continued to use these tracing classes for many years whilst targeting 32-bit MIPS and later ARM targets. We ended up with code like Listing 2.

#include <inttypes.h>
void foo(uint64_t value)
{
  TRACE("foo passed %llu\n", value);
  //...
}
void bar(size_t length)
{
  TRACE("bar passed %zu\n", length);
  //...
}
			

This all worked fine, until we tried to compile for our first 64-bit target.

The ugliness of <inttypes.h>

The <inttypes.h> header (along with the <cinttypes> that we probably ought to have been using from C++) contains handy definitions for types with specific numbers of bits. It contains declarations like:

  #if defined(__LP64)
  typedef unsigned long uint64_t;
  typedef long int64_t;
  #else
  typedef unsigned long long uint64_t;
  typedef long long int64_t;
  #endif

Unfortunately, this means that when compiling for a 32-bit target the %llu and %lld format specifiers are correct, but when compiling for a 64-bit target %lu and %ld must be used. <inttypes.h> provides the PRIu64 and PRId64 macros that expand to the correct form. Unfortunately, since they need to be used in a string literal, they are extremely ugly to use. (The full set of macros is at [CppRef].)

The relatively sensible:

  void ReportProgress(uint64_t current, 
    uint64_t max)
  {
    TRACE("Progress %llu/%llu %llu%%\n", current,
      max, current * 100 / max);
  }

becomes the hard-to-read, hard-to-type and hard-to-maintain:

  void ReportProgress(uint64_t current, 
    uint64_t max)
  {
    TRACE("Progress %" PRIu64 "/" PRIu64 " " PRIu64
      "%%\n", current, max, current * 100 / max);
  }

So I went looking for an alternative and I found {fmt}.

{fmt}

The {fmt} library [fmt] provides a safe alternative to printf. It provides a Python-like formatting mechanism for C++, taking advantage of C++ type safety:

fmt::print("The {} is {}{}\n", "answer", 42L, '.');

But for me, the most interesting feature was its printf-compatible interface. When using this interface it will parse printf format strings, but mostly disregard the type information. This means that you can write:

  void ReportProgress(uint64_t current, 
   uint64_t max)
  {
    TRACE("Progress %u/%u %u%%\n", current, max,
      current * 100 / max);
  }

without caring whether the three integers are unsigned long or unsigned long long, or any other integer type for that matter. This turned out to be the solution to my 64-bit tracing problem without needing to change all my code.

Using fmt::printf

The first step was to implement AlwaysTrace::operator() in terms of fmt::printf (see Listing 3).

struct NeverTrace {
  template <typename... Args>
  void operator()(const char *format,
    Args&&... args) {}
};
struct AlwaysTrace {
  template <typename... Args>
  void operator()(const char *format, 
    Args&&... Args) {
      fmt::printf(format,
        std::forward<Args>(args)...);
    }
};
			

Catching exceptions

This worked, but if I accidentally wrote:

  void ReportProgress(uint64_t current, 
    uint64_t max)
  {
    TRACE("Progress %d/%d%%\n", current);
  }

then GCC’s format string checker was no longer there to generate a compilation error; {fmt} would instead throw a FormatError exception. If there are too many parameters then it silently ignores the extra ones.

Tracing isn’t important enough for us to want to risk terminating the program. This is especially important if tracing is not always enabled. I considered modifying {fmt} itself to stop it throwing, but that would mean disabling exception throwing even if we were to make use of the library in normal code too.

The simplest solution is to just catch exceptions and emit an error message along with the format string so that the offending line can be found and fixed (see Listing 4).

namespace wrapped {
  template <typename... Args>
  inline void printf(const char *format, 
      Args&&... args) {
    try {
      fmt::printf(format,
        std::forward<Args>(args)...);
    }
    catch (const std::exception &e) {
      fmt::printf("Message '%s' threw '%s'\n",
        format, e.what());
    }
  }
}
struct AlwaysTrace {
  template <typename... Args>
  void operator()(const char *format, 
    Args&&... Args) {
      wrapped::printf(format,
        std::forward<Args>(args)...);
    }
};
			

Just before this article went to print, version 5 of {fmt} was released. This version supports compile-time verification of Python-style format strings [Zverovich17]. I look forward to being able to take advantage of this to support both the Python-style format strings and validation whilst keeping the existing printf-compatible functions for existing code.

Tracing errors

In many places we’d taken advantage of glibc’s %m format specifier to print the error message associated with the current value of errno. The upstream maintainer didn’t want to support such an extension [Crowe17a], so I applied a local patch to do so. I hope to come up with something similar that will be acceptable upstream in the future.

Tracing pointers

In certain sections of the code there were a large number of places where the this pointer was emitted as part of a trace message. This helped to tie the tracing from multiple instances together when reading the logs. It used the %p format specifier for this.

The {fmt} library supports the %p format specifier, but the corresponding parameter must be of const void * or void * type. It has good reasons for this, at least some of which are described in [Wilson09]. On its branch hopefully destined for standardisation, it provides a fmt::ptr` helper to cast arbitrary pointers to an acceptable type.

Unfortunately, I had lots of code using %p and casting all the corresponding parameters was painful. I decided to patch {fmt} locally to support arbitrary pointers [Crowe17b], despite the downsides. The upstream maintainer seems favourable to supporting this in the printf-compatible case only, if only I can find a clean way to do so.

Effect on compilation time and binary size

Of course, all this magic has to come at a cost. In my not-hugely-scientific experiments, on a project that contained about 7500 trace statements, compilation and linking with GCC of debug builds (with -g3) took about 5% longer. The same with -O2 and -g3 only took about 1% longer. So, whilst there is an effect, it’s not huge.

This code runs on an embedded system, albeit one with over a gigabyte of memory, but nonetheless the size of the generated code was a concern. Without making any attempt to catch exceptions the stripped binary was about 0.75% bigger. When catching exceptions it was about 1.5% bigger.

Enabling new behaviours

Now that we’re using the library, we no longer have to care about the exact types of integers we’re tracing, and can pass std::string without calling c_str(), which is a bonus. We no longer have to be picky about the exact type of integers either. In new code we don’t have to remember to say %zu when tracing a size_t.

Tracing custom types

We end up tracing std::chrono types in quite a few places. We can define a custom formatter with something like Listing 5, then write code like:

namespace fmt {
    /// Displays in microseconds or seconds
    template <typename Rep, typename Period>
    void format_arg(fmt::BasicFormatter<char> &f,
      const char *&format_str,
      const std::chrono::duration<Rep, Period>
        &duration)
      {
        if (duration < std::chrono::seconds(1))
          f.writer().write("{}us",
          std::chrono::duration<double,
          std::micro>(duration).count());
        else
          f.writer().write("{}s",
          std::chrono::duration<double>(duration)
            .count());
      }
}
			

  void f() {
    auto start = std::chrono::steady_clock::now();
    do_something_time_consuming();
    auto duration = 
      std::chrono::steady_clock::now() - start;
    TRACE("It took %ldms\n", duration);
  }

The future

Victor Zverovich, the primary author of the {fmt} library, has proposed the Python-style format strings subset of the library for standardisation and presented his work at the Jacksonville WG21 meeting [WG21]. I’m keen to see how it can be used to improve our tracing in the future.

Thanks

Thanks to Victor Zverovich, the primary author of {fmt}, for reviewing draft versions of this article and for helping with my attempts to mould it to our needs.

Thanks to Frances Buontempo and the Overload reviewers for their suggestions and advice.

References

[CppRef] ‘Fixed width integer types’ available at: http://en.cppreference.com/w/cpp/types/integer

[Crowe17a] Mike Crowe (2017) ‘printf: Add support for glibc’s %m format’ at https://github.com/fmtlib/fmt/pull/550, posted 22 July 2017

[Crowe17b] Mike Crowe (2017) ‘What are the downsides to disabling the private MakeValue::MakeValue<T*> overloads?’ at https://github.com/fmtlib/fmt/issues/608, posted 11 November 2017

[fmt] The {fmt} library http://fmtlib.net

[Ignatchenko18] Sergey Ignatchenko (2018) ‘This is NOT yet another printf-vs-cout debate’ in Overload 144, April 2018, available at: https://accu.org/index.php/journals/2486

[WG21] ‘Text Formatting at the ISO C++ standards meeting in Jacksonville’, available online at http://www.zverovich.net/2018/03/17/text-formatting-jacksonville.html

[Wilson09] Matthew Wilson (2009) ‘An Introduction to Fast Format (Part 1): The State of the Art’, Overload 89, available at https://accu.org/index.php/journals/1539

[Zverovich17] Victor Zverovich (2017) Verification of Python-style format strings: http://zverovich.net/2017/11/05/compile-time-format-strings.html