/**
@page GRAS_tut_tour_logs Lesson 6: Logging informations properly
\section GRAS_tut_tour_logs_toc Table of Contents
- \ref GRAS_tut_tour_logs_intro
- \ref GRAS_tut_tour_logs_practice
- \ref GRAS_tut_tour_logs_recap
- \ref GRAS_tut_tour_logs_config
- \ref GRAS_tut_tour_logs_config_prio
- \ref GRAS_tut_tour_logs_config_layout
\section GRAS_tut_tour_logs_intro Introduction
Let's have another look at the output of the program we came up with in
lesson 5:
\include 05-globals.output
It is a bit difficult to read, isn't it? Indeed, it is hard to identify
which process printed which line. It would be possible to add [server] in
any messages comming from the server and do the same for every process
running. Idealy, we would also add the location at which the message was
generated (using __FILE__ and __LINE__) to help debuging, as well as a
timestamping so that we can still reorder the messages in RL when they get
intermixed (yeah, it happen, and there is not much to do against it).
At the end, each time we would like to print a little "hello" debugging
message, we would have to write 3 lines of arguments to fprintf, which is
not that practical.
That is why there is a support for proper logging in GRAS. Technically
speaking, it is not part of GRAS but of XBT, which is the toolbox on which
the whole SimGrid library is built, but that's the same for us.
This logging library follows the spirit of another one called log4j, which
is more or less the reference in the domain. The original version is for
Java, as the name implies, and there was reimplementation for Python
(log4py), C/C++ (log4c) and so on. Since one of the credo of the GRAS
framework is that we don't want any external dependency to ease the
deployment in grid settings, we reimplemented a version of our own.
One of the strong idea of log4j is that log events get structured to give
the user a fine control at run time of what gets displayed and what don't.
For that, log event are produced into log channels at a given
log priority. Then, you can select the minimal priority an event
should have on a given channel to get displayed.
Then, to keep things managable even when the number of channels increase,
the channels form a tree and properties get inherited from parent channel to
childs. Have a look at the existing channels in SimGrid: \ref XBT_log_cats.
You see that for example, the gras channel have 5 subchannels (at
time of writing): gras_ddt, gras_msg, gras_timer,
gras_trp and gras_virtu. If you open or close the
gras channel, it automatically affects all those subchannels (and
their respective subchannels too). Finally, channels are not just open or
closed, but filter messages below a given priority (as we said). The
priorities are defined by type #e_xbt_log_priority_t.
That is all you really need to know about the logs before diving into
practice. If you want more information on that topic, refer to the \ref
XBT_log section, which contains much more information than this page.
\section GRAS_tut_tour_logs_practice Putting logs into action
Enough with theory, let's change our example so that it uses proper
loggings. The first thing to do is to add a new channel in the existing
hierarchy. There is 4 macros to create log channels, depending on the kind
of channel we want:
- XBT_LOG_NEW_CATEGORY(MyCat,desc); Create a new root
- XBT_LOG_NEW_SUBCATEGORY(MyCat, ParentCat,desc); Create a new category being child of the category ParentCat
- XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat,desc); Like XBT_LOG_NEW_CATEGORY, but the new category is the default one in this file
- XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, ParentCat,desc); Like XBT_LOG_NEW_SUBCATEGORY, but the new category is the default one in this file
What we want here is a root category (it does not belong to any existing
channel, for sure), and we want it to be the default one in our file (of
course, it's the only one).
\dontinclude 06-logs.c
\skip XBT_LOG
\until XBT_LOG
Then, we change any call to fprintf to one of the logging macros. There is a
plenty of them, called <priority><nb args>, such as #XBT_DEBUG,
which produces a debuging log event onto the default category. Here is a
list of the existing macros: #XBT_DEBUG, #XBT_VERB, #XBT_INFO, #XBT_WARN,
#XBT_ERROR and #XBT_CRITICAL.
Note also that there is no need to add a '\\n' at the end of your format
line, it gets automatically added.
\section GRAS_tut_tour_logs_recap Recapping everything together
Once we changed any fprintf of our code to some of these macros, the program
may read:
\include 06-logs.c
And the output now looks better:
\include 06-logs.output
\section GRAS_tut_tour_logs_config The user side: configuring logs at run time
\subsection GRAS_tut_tour_logs_config_prio Choosing what gets displayed
Once we changed our program to use proper logging, it is naturally possible
to choose at run time what we want to see. For example, if we want more
details about our code, we should pass --log=test.thres:verbose
on the command line of our programs to change the thresold.
Note that a VERBOSE line appears on client side:
\include 06-logs.output.verbose
On the contrary, if we want to reduce the amount of logging, we may want to
do pass --log=test.thres:error:
\subsection GRAS_tut_tour_logs_config_layout Choosing how things get displayed
As with SimGrid 3.3, it is also possible to change how each and every
message get displayed from the command line without even recompiling
your code. This is done by changing the fmt field of the
category you want to change. The value of this field is somehow
similar to printf's format strings, with several existing specifiers.
For example, if you just want the message you passed to the macro
without any decoration about the host which raised it, its pid and
everything, just pass --log=test.fmt:%m:
\include 06-logs.output.fmt
For debuging purpose, you can even ask to get the backtrace at each
execution point:
\include 06-logs.output.fmt-bt
Again, you should refer to the \ref XBT_log section for more information on
how to configure the logs. Or you can proceed with the next lesson, of
course.
Go to \ref GRAS_tut_tour_timers
*/