[Dune] [#991] Unified logging tags (Attachment added)

[Dune]

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

A new Flyspray task has been opened.  Details are below. 

User who did this - Jö Fahlke (joe) 

Attached to Project - Dune
Summary - Unified logging tags
Task Type - Bug Report
Category - Common
Status - New
Assigned To - 
Operating System - Unspecified / All
Severity - Low
Priority - Normal
Reported Version - SVN (pre2.2)
Due in Version - Undecided
Due Date - Undecided
Details - 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.


One or more files have been attached.

More information can be found at the following URL:
http://www.dune-project.org/flyspray/index.php?do=details&task_id=991

You are receiving this message because you have requested it from the Flyspray bugtracking system.  If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.