Skip to content

#991 Unified logging tags

Metadata

Property Value
Reported by Jö Fahlke (jorrit@jorrit.de)
Reported at Dec 13, 2011 00:52
Type Bug Report
Version Git (pre2.4) [autotools]
Operating System Unspecified / All

Description

Hi!

I have a proposal and a sample implementation that I would like your comments on, and which I would like to eventually integrate into Dune-Common.

Proposal:

I'd like a facility to easily prepend unified and configurable logging tags to most output lines produced by Dune. By "logging tag" I mean something that may contain for instance the hostname, or the rank, or the system time. The user should be able to easily change the information and the appearance of the tag (the "configurable" part). By "unified" I mean that there should be one place to configure this, and everything in Dune that wishes to prepend a logging tag should honour this central configuration. "Easily" of course means that it should be easy to use, so people will actually use in the Dune library.

A sample tag may for instance look like this:

[h:p=paranoia:25723|w=1323731743.847265|c= 0.008000] Hello world!

The tag is the part within square brackets and contains hostname, process id, wall time (in seconds since the unix epoch), and cpu time (the amount of cpu cycles used by the program so far in seconds).

What is this good for?

  • Can be used to take timings of your program.

  • Makes it immediately on what machine a program was running, even if you look at your logfiles later and don't remember exactly.

  • If you let each rank log its number, you know on which node in the cluster each rank was running.

What this proposal is not:

  • This doesn't tell you where output should go. (Look at the debugstreams for that).

  • Neither does it tell you whether you should do output (e.g. verbosity).

  • It doesn't help you with the non-atomicity of output, i.e. lines from different ranks getting mixed up.

Sample Implementation:

I've attached a sample implementation. It uses a iomanip-style manipulator function Dune::logtag() that can be inserted into an ostream. For instance, the above sample could have been produced with

cout << logtag << "Hello world!" << endl;

Of course, there is a little boilerplate associated with this:

#include <dune/common/logtag.hh> using Dune::logtag;

If someone wants to change the tag, this is easy:

Dune::setLogtagFormatFunc(Dune::hostPidWallCpuLogtagFormatFunc); // default Dune::setLogtagFormatFunc(Dune::hostRankWallCpuLogtagFormatFunc); Dune::setLogtagFormatFunc(Dune::nullLogtagFormatFunc); // disable tag

It's also possible to define your own function or functor:

void pidOnly(std::ostream &s) { s << "[" << getpid() << "] "; } Dune::setLogtagFormatFunc(pidOnly);

class progress { const double &time, t_end; public: progress(const double &time_, double t_end_) : time(time_), t_end(t_end_) {} void operator(std::ostream &s) const { s << std::fixed < std::setprecision(0) << std::setw(3) << 100*time/t_end << "% "; } }; double time = 0; double end = 42; Dune::setLogtagFormatFunc(progress(time, end));

It's even possible to temporarily and exception-safe switch the tag in some scope:

{ Dune::WithLogtag logtagGuard(Dune::nullLogtagFormatFunc); // do something noisy } // tag automatically switched back

Problems:

  • MPI: This facility must work at all times. However, at some points some information isn't known (yet), e.g. the rank before MPI_Init. In these cases the system can only print placeholders like '?'. Moreover, it must be explicitly notified when MPI has been initialized. This notification could of course be put into MPIHelper::instance(), so it would happen automatically.

  • Threads: The selection of the tag really should be thread-specific. However, there doesn't appear to be a way to automatically copy some data from a parent thread's local storage into the local storage of a freshly created child thread. So using setLogtagFormatFunc() or WithLogtag in one thread while another thread does output, or using WithLogtag concurrently in two threads my create races. As long as you set the logging tag only once in main(), you should be safe though.

  • Customizing the logging output is still too complicated. Instead of writing your own function or functor, you should be able to pass a formatstring, like:

    Dune::setLogtagFormatString("[%{host}|%{walltime}{%Y-%m-%d %H:%M:%S}|%6.3{cputime}]");

    I'll leave that as an excercise to the reader, however.

Attachments