Binary Logs in Real Time Embedded System

Logging is  one of the important technique used by the software developer to debug their code. C/C++ developer usually define macros which can be used to log debugging text. Following snippet gives  sample.

LOG(<category>,<level> <format_string>[,variable number of arguments);

Usually log provides mechanism to enable disable during compile time and run time. Log level can be defined as ERROR, WARN, INFO, DEBUG etc. Log level can be enabled disabled at run time. It is always good to provide file name and line number where log entry present in the code with log message. This text log can be displayed on console, or written into file or send it over network to logging server.

Aim of this article to discuss logging in the context of hard real time application where there will be time constraints to finish the job. Definitely it is impractical to display these text format logs on the screen.  Better approach is to write these text logs to file or send it over socket. Since it is hard real time application usage of  blocking socket or file write is a problematic.

Now we are going to discuss binary logging, a technique of logging without compromising the any of the benefit we see in the text format logging what we discussed at the beginning of this article.

We can write a script which scans the source code and assigns numerical identifier to each of the logs. At the same time it can prepare meta data which contains mapping between format string and assigned identifier. It is always good to prefix some new literals to logging macro and suffix by information about number of argument, once script assigns identifier so that anybody can distinguish between converted and newly added logs.

Let us assume developer adds logs as follows.
#include "logging.h"
int main ()
{
             int i = 10;
             set_log_level(MAIN, DEBUG);
             LOG(MAIN, INFO, "Entering main\n");
             LOG(MAIN, DEBUG, "Value of i = %d\n", i);
             printf ("Hello world\n");
             LOG (MAIN, INFO, "Exiting main\n");
 
}

after running the script the above code will be modified/instrumented by the script as follows.

#include "binary_logging.h"
int main ()
{
             int i = 10;
             set_log_level(MAIN, DEBUG);
             BIN_LOG_0(0,MAIN, INFO, "Entering main\n");
             BIN_LOG_1(1,MAIN, DEBUG, "Value of i = %d\n", i);
             printf ("Hello world\n");
             BIN_LOG_0 (2,MAIN, INFO, "Exiting main\n");
 }

Meta data can look as follows for above log.
#num_of_arg:category:level:format string
0:MAIN:INFO:Entering main\n
1:MAIN:DEBUG:Value of i = %d\n
0:MAIN:INFO:Exiting main\n


We can use circular buffer to store logging information such as log id and argument values, which will be read by separate thread and converts binary logs to user readable text logs.
It is always important to read logs quickly such that buffer full condition does not reach otherwise we might loose some of the logs. It is very necessary to avoid mutex instead we can use automatic set operation where writer thread/process  updates writer index without race condition.Another important aspect is supporting multi thread. We can allocate circular buffer for each thread flow and pointer to circular buffer can be stored in thread specific context using posix api. So each log function firs gets associated circular buffer reference from thread specific area and puts the log entry in the circular buffer. It is always good to reserve segment at the begining of circular buffer to store information such as reader_index, writer_index, log missed counter etc which helps debugging if there is any problem in the log.


Following link provides source code of binary log implementation. Script is written in perl.Here circular buffer is implemented over shared memory and log reader and log writer implemented as separate process.

<proof of concept code will be provided soon>