Logging is one of the oldest and most widely used software debugging tools: for decades, developers have put printf-like statements in their code to find out what their code is really doing, in situ. Even today, logging is still crucial for finding bugs in software, especially sporadic problems in concurrent and event-driven systems.
Fortunately, most programming environments come with powerful logging facilities (like Android’s Log) — but what if you are working on a highly-constrained system that simply can’t afford them?
Let’s have a look at an example that uses printf-like logging:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
#include "log.h" uint32_t readInput() { log_info("Enter readInput"); uint32_t sampledValue = IoGetRawInput(); ... if (sampledValue > SAMPLED_VALUE_MAX) { log_warn("Sampled value exceeded threshold: %d", sampledValue); sampledValue = 0; } ... log_info("Exit readInput"); return sampledValue; } |
Traditional (printf-like) logging is expensive because:
- Log strings consume memory (ROM), which can easily increase the overall size of the executable by 10% to 30%.
- printf-based logging is extremely flexible, but the parsing of format strings can incur a significant run-time overhead.
- The amount of log data produced at run-time is quite large because all the log strings need to be transmitted (or stored locally, in case you keep logging data in a file), usually accompanied with timestamps and other bookkeeping information.
I recently had a crazy idea how to compress a log string of (almost) arbitrary size to a single byte: Instead of using real (read: expensive) C strings, why not define a constant whose symbol name serves as the “log string” and only log it’s address?
|
1 2 3 4 5 6 |
... static const uint8_t A_log_string_that_consumes_only_a_single_byte = 0; mlog_impl(&A_log_string_that_consumes_only_a_single_byte); ... |
On the receiving side, you can reconstruct the original log strings from the map file produced by the linker.
Given an appropriate set of magic macros, the example above looks like this:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
#include "mlog.h" uint32_t readInput() { MLOG_INFO(Enter_readInput); uint32_t sampledValue = IoGetRawInput(); ... if (sampledValue > MAX_SAMPLE_VALUE) { MLOG_WARN_VALUE(Sampled_value_exceeded_threshold, sampledValue); sampledValue = 0; } ... MLOG_INFO(Exit_readInput); return sampledValue; } |
It may be hard to believe, but these three “log strings” really only consume three bytes of memory. To send out their addresses, four bytes are needed (assuming 32-bit addresses are used) and ‘sampledValue’ requires the transmission of another four bytes. Let’s compare these two approaches assuming that ‘sampledValue’ is 42 (two digits) and taking into account that the size of a C string is the number of characters plus one for a trailing ‘\0’:
| footprint (bytes) | transmission (bytes) | |
| traditional logging | ||
| MLOG logging | ||
| savings % |
That’s what I call an improvement!
I’ve implemented this idea for the GCC toolchain. The log server emits MLOG traces via UDP, which are received by a little tool that converts them back into human-readable log messages by exchanging MLOG symbol addresses with (beautified) MLOG symbol names from the linker map file. Extracting the MLOG symbols from the map file is the most GCC-dependent part. I believe it is a straightforward task to port MLOG to other platforms and toolchains.
Check it out at GitHub.
EPILOGUE:
This is my 100th blog post (actually 101st, damn)! Thanks, faithful reader, for bearing with me through all these years.
— Yours Truly