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>