Merge pull request #209 from torbjoernk/feature/pimp-logging

some minor tweaks to logging output

Author: memmett

include/pfasst/logging.hpp

@@ -103,7 +103,7 @@ const string OUT::reset = "\033[0m";
 
 #ifndef PFASST_LOGGER_DEFAULT_GLOBAL_MILLISECOND_WIDTH
   //! precision of milliseconds to be printed
-  #define PFASST_LOGGER_DEFAULT_GLOBAL_MILLISECOND_WIDTH "4"
+  #define PFASST_LOGGER_DEFAULT_GLOBAL_MILLISECOND_WIDTH "2"
 #endif
 
 #ifndef VLOG_FUNC_START
@@ -145,7 +145,7 @@ const string OUT::reset = "\033[0m";
  *
  * @see pfasst::log::add_custom_logger()
  */
-#define LOGGER_ID_LENGTH 8
+#define LOGGER_ID_LENGTH 10
 
 
 namespace pfasst
@@ -177,6 +177,13 @@ namespace pfasst
      */
     static size_t stack_position;
 
+    /**
+     * internal flag identifying whether the default logger has been initialized.
+     *
+     * @since v1.0.0
+     */
+    static bool initialized = false;
+
     /**
      * Formats the local MPI world rank as a string.
      *
@@ -275,6 +282,11 @@ namespace pfasst
      *
      *     <TIME> [MYCUSTOM, INFO ] a logging message
      *
+     * In case MPI is enabled, the line will also contain the MPI rank as given by
+     * pfasst::config::get_rank():
+     *
+     *     <TIME> [MYCUSTOM, INFO , MPI  <rank> ] a logging message
+     *
      * @param[in] id the ID of the logger; this is used in logging calls
      *
      * @note Please make sure to use `CLOG` (and `CVLOG` for verbose logging) to be able to specify
@@ -303,14 +315,17 @@ namespace pfasst
       const string POSITION = "%fbase:%line";
       const string MESSAGE = "%msg";
 #ifdef WITH_MPI
-      const string MPI_RANK = ", rank " + format_mpi_rank();
+      const string MPI_RANK = ", MPI " + format_mpi_rank();
 #else
       const string MPI_RANK = "";
 #endif
 
       const size_t id_length = id.size();
       string id2print = id.substr(0, LOGGER_ID_LENGTH);
       boost::to_upper(id2print);
+      if (initialized) {
+        CLOG(DEBUG, "default") << "initializing custom logger '" << id << "' as '" << id2print << "'";
+      }
       if (id_length < LOGGER_ID_LENGTH) {
         id2print.append(LOGGER_ID_LENGTH - id_length, ' ');
       }
@@ -352,7 +367,9 @@ namespace pfasst
       el::Loggers::setDefaultConfigurations(defaultConf, true);
 
       add_custom_logger("default");
+      pfasst::log::initialized = true;
       add_custom_logger("Controller");
+      add_custom_logger("Communicator");
       add_custom_logger("Sweeper");
       add_custom_logger("Encap");
       add_custom_logger("Quadrature");

include/pfasst/mpi_communicator.hpp

@@ -8,6 +8,7 @@ using namespace std;
 #include <mpi.h>
 
 #include "pfasst/interfaces.hpp"
+#include "pfasst/logging.hpp"
 
 
 namespace pfasst
@@ -33,6 +34,7 @@ namespace pfasst
         //! @{
         int _rank;
         int _size;
+        string _name;
         //! @}
 
       public:
@@ -49,6 +51,7 @@ namespace pfasst
         virtual void set_comm(MPI_Comm comm);
         virtual int size();
         virtual int rank();
+        virtual string name();
         //! @}
     };
 
@@ -72,6 +75,9 @@ namespace pfasst
   }  // ::pfasst::mpi
 }  // ::pfasst
 
+
+inline MAKE_LOGGABLE(MPI_Status, mpi_status, os);
+
 #include "pfasst/mpi_communicator_impl.hpp"
 
 #endif

src/pfasst/mpi_communicator_impl.hpp

@@ -30,6 +30,14 @@ namespace pfasst
       this->comm = comm;
       MPI_Comm_size(this->comm, &(this->_size));
       MPI_Comm_rank(this->comm, &(this->_rank));
+      int len = 0;
+      char buff[MPI_MAX_OBJECT_NAME];
+      MPI_Comm_get_name(this->comm, buff, &len);
+      if (len == 0) {
+        this->_name = string("world");
+      } else {
+        this->_name = string(buff, len);
+      }
 
       shared_ptr<MPIStatus> status = make_shared<MPIStatus>();
       this->status = status;
@@ -46,6 +54,11 @@ namespace pfasst
       return this->_rank;
     }
 
+    string MPICommunicator::name()
+    {
+      return this->_name;
+    }
+
 
     void MPIStatus::set_comm(ICommunicator* comm)
     {
@@ -62,7 +75,7 @@ namespace pfasst
 
     void MPIStatus::set_converged(bool converged)
     {
-      LOG(DEBUG) << "mpi rank " << this->comm->rank() << " set converged to " << converged;
+      CLOG(DEBUG, "Controller") << "set converged to " << boolalpha << converged;
       this->converged.at(this->comm->rank()) = converged;
     }
 
@@ -84,10 +97,12 @@ namespace pfasst
 
       int iconverged = converged.at(mpi->rank()) ? 1 : 0;
 
-      LOG(DEBUG) << "mpi rank " << this->comm->rank() << " status send " << iconverged;
+      int dest_rank = (mpi->rank() + 1) % mpi->size();
+      CLOG(DEBUG, "Controller") << "sending status " << iconverged
+                                << " to " << dest_rank << " of communicator " << mpi->name();
 
       int err = MPI_Send(&iconverged, sizeof(int), MPI_INT,
-                         (mpi->rank() + 1) % mpi->size(), 1, mpi->comm);
+                         dest_rank, 1, mpi->comm);
 
       if (err != MPI_SUCCESS) {
         throw MPIError();
@@ -101,22 +116,33 @@ namespace pfasst
       if (mpi->rank() == 0) { return; }
 
       if (get_converged(mpi->rank()-1)) {
-        LOG(DEBUG) << "mpi rank " << this->comm->rank() << " skipping status recv";
+        CLOG(DEBUG, "Controller") << "skipping status recv";
         return;
       }
 
       MPI_Status stat;
       int iconverged;
+      int src_rank = (mpi->rank() - 1) % mpi->size();
       int err = MPI_Recv(&iconverged, sizeof(iconverged), MPI_INT,
-                         (mpi->rank() - 1) % mpi->size(), 1, mpi->comm, &stat);
+                         src_rank, 1, mpi->comm, &stat);
 
       if (err != MPI_SUCCESS) {
         throw MPIError();
       }
 
       converged.at(mpi->rank()-1) = iconverged == 1 ? true : false;
 
-      LOG(DEBUG) << "mpi rank " << this->comm->rank() << " status recv " << iconverged;
+      CLOG(DEBUG, "Controller") << "recieved status " << iconverged
+                                << " from rank " << src_rank << " of communicator " << mpi->name();
     }
   }  // ::pfasst::mpi
 }  // ::pfasst
+
+
+MAKE_LOGGABLE(MPI_Status, mpi_status, os)
+{
+  os << "MPI_Status(source=" << mpi_status.MPI_SOURCE << ", "
+                << "tag=" << mpi_status.MPI_TAG << ", "
+                << "error=" << mpi_status.MPI_ERROR << ")";
+  return os;
+}