src/myrlog.cpp

Go to the documentation of this file.

//
// C++ Implementation: myrlog
//
// Description:
//
//
// Author: Roman Geus <geus@maxwell>, (C) 2004
//
// Copyright: See COPYING file that comes with this distribution
//
//

#include <unistd.h>
#if defined(__QK_USER__)
#    include <catamount/catmalloc.h>
#    include <catamount/data.h>
#    include <papi.h>
#endif
#include <sys/times.h>
#include <time.h>
#include <fstream>
#include <iterator>
#include <sstream>
#include "Epetra_Comm.h"
#include "Epetra_Map.h"
#include "Epetra_CrsMatrix.h"
#include "rlog/RLogChannel.h"
#include "myrlog.h"

using namespace std;
using namespace rlog;

namespace rlog {

std::string bytes2str(unsigned long long size) {
    char suffix;
    if (size < 10000)
        suffix = 'b';
    else {
        size /= 1024;
        if (size < 10000)
            suffix = 'k';
        else {
            size /= 1024;
            suffix = 'm';
        }
    }
    std::ostringstream buf;
    buf << size << suffix;
    return buf.str();
}

MyStdioNode::MyStdioNode(string prefix, int _fdOut)
    : StdioNode(_fdOut, true), prefix_(prefix)
{
    // override: always use color
    colorize = true;
}

MyStdioNode::~MyStdioNode()
{
}

void
MyStdioNode::publish( const RLogData &data )
{
    const char kNormalColor[] = "\033[0m";
    const char kRedColor[]    = "\033[31m";
    const char kGreenColor[]  = "\033[32m";
    const char kYellowColor[] = "\033[33m";    
//    const char kBlueColor[] = "\033[34m";
//    const char kPurpleColor[] = "\033[35m";    
    const char kMagentaColor[] = "\033[36m";    
    char timeStamp[32];
    time_t errTime = data.time;
    tm currentTime;

#ifdef HAVE_LOCALTIME_R
    localtime_r( &errTime, &currentTime );
#else
    currentTime = *localtime( &errTime );
#endif

    const char *color = NULL;
    if(colorize)
    {
        sprintf(timeStamp, "%s%02i:%02i:%02i%s %s%s ",
                kGreenColor,
                currentTime.tm_hour,
                currentTime.tm_min,
                currentTime.tm_sec,
                kMagentaColor,
                prefix_.c_str(),
                kNormalColor);

        string channel = data.publisher->channel->name();
        LogLevel level = data.publisher->channel->logLevel();

        switch(level)
        {
        case Log_Critical:
        case Log_Error:
            color = kRedColor;
            break;
        case Log_Warning:
            color = kYellowColor;
            break;
        case Log_Notice:
        case Log_Info:
        case Log_Debug:
        case Log_Undef:
            break;
        }
    } else
    {
        sprintf(timeStamp, "%02i:%02i:%02i %s ",
                currentTime.tm_hour,
                currentTime.tm_min,
                currentTime.tm_sec,
                prefix_.c_str());
    }

    ostringstream ss;

    ss << timeStamp;
    //ss << '[' << data.publisher->channel->name << "] ";
    //ss << "(" << data.publisher->fileName << ':'
    //    << data.publisher->lineNum << ") ";

    if(color)
        ss << color;

    ss << data.msg;

    if(color)
        ss << kNormalColor;

    ss << '\n';

    string out = ss.str();
    write( fdOut, out.c_str(), out.length() );
}

} // namespace rlog

string get_log_file_name(string prefix) {
    char buf_time[128];
    char buf_pid[128];

    // get local time
    time_t tim = time(NULL);

    // convert to tm structure
    struct tm* ts = localtime(&tim);

    // format time
    int info = strftime(buf_time, sizeof(buf_time), "%Y%m%d-%H%M%S", ts);
    rAssert(info > 0);

    // format id
    unsigned int pid;
#if defined(__QK_USER__)
    pid = _my_yod_cmd_pid;
#else
    pid = getpid();
#endif
    info = snprintf(buf_pid, sizeof(buf_pid), "-%d", pid);
    rAssert(0 <= info && info < static_cast<int>(sizeof(buf_pid)));

    // return file name
    return prefix + buf_time + buf_pid + ".log";
}

#if defined(__QK_USER__)

size_t get_mem_footprint() {
  size_t fragments;
  unsigned long total_free;
  unsigned long largest_free;
  unsigned long total_used;

  int info =  heap_info(&fragments,
                        &total_free,
                        &largest_free,
                        &total_used);
  assert(info == 0);
  return total_used;
}

#else

#  if defined(USE_SBRK)

size_t get_mem_footprint() {
    // extract memory footprint sbrk
    static size_t base = 0;
    size_t p = reinterpret_cast<size_t>(sbrk(0));
    // if called for the 1st time, set base
    if (base == 0)
        base = p;
    return p - base;
}
// call function to make sure base gets initialised
namespace {
    size_t dummy = get_mem_footprint();
}

#  else

size_t get_mem_footprint() {
    // extract memory footprint from /proc/$PID/status
    pid_t pid = getpid();
    ostringstream buf;
    buf << "/proc/" << pid << "/status";
    ifstream istr(buf.str().c_str());
    istream_iterator<string> ifile(istr);
    istream_iterator<string> eos;
    for (; ifile != eos && *ifile != "VmSize:"; ++ ifile)
        ;
    rAssert(ifile != eos);
    ++ ifile;
    istringstream buf2(*ifile);
    ++ ifile;
    rAssert(*ifile == "kB");
    size_t size;
    buf2 >> size;
    return 1024 * size;
}

#  endif

#endif

void log_mem_footprint(const Epetra_Comm& comm, string msg) {
    size_t local_size = get_mem_footprint();
    double local_size_d = static_cast<double>(local_size);
    double sum_size_d, max_size_d, min_size_d;
    comm.SumAll(&local_size_d, &sum_size_d, 1);
    comm.MaxAll(&local_size_d, &max_size_d, 1);
    comm.MinAll(&local_size_d, &min_size_d, 1);
    if (msg != "")
        msg = " (" + msg + ")";
    rDebug("Memory footprint%s: sum=%s, min=%s, max=%s",
           msg.c_str(),
           rlog::bytes2str(static_cast<unsigned long long>(sum_size_d)).c_str(),
           rlog::bytes2str(static_cast<unsigned long long>(min_size_d)).c_str(),
           rlog::bytes2str(static_cast<unsigned long long>(max_size_d)).c_str());
}

void log_command_line_args(int argc, char* argv[], rlog::RLogChannel* channel) {
    if (channel == 0)
        channel = RLOG_CHANNEL("debug");

    ostringstream buf;
    buf << argv[0] << " started with arguments";
    for (int i = 1; i < argc; ++ i) {
        buf << " \"" << argv[i] << "\"";
    }
    rLog(channel, "%s", buf.str().c_str());
}

size_t get_matrix_mem_footprint(const Epetra_CrsMatrix& A) {
    /* Memory consumption calculated according to mail by Mike Heroux:

       N=Global dimension
       NNZ=Global Nonzero count
       Nghost=Total number of redundant values needed for parallel execution
       Nrhs=Number of RHS.

       4*(N+NNZ)    - Array of pointer for Column Indices and NNZ total integer space.

       4*(2*N)      - Two integer arrays to manage insertion of matrix entries.

       4*(N+2*NNZ)  - Array of pointers for values and NNZ total doubles.

       4*N          - RowMap
       4*(N+Nghost) - ColMap

       8**Nrhs*(N+Nghost) - Import MultiVector (zero if on a single processor).
    */
    size_t local_size = 0;
    // col and val
    local_size += A.NumMyNonzeros() * (sizeof(int) + sizeof(double));
    // ptrs to indices in row and nof_per_row and alloc_per_row
    local_size += A.NumMyRows() * (sizeof(int*) + 2*sizeof(int));
    // ptrs to values in row
    local_size += A.NumMyRows() * sizeof(double*);
    // row map
    local_size += A.NumMyRows() * sizeof(int);
    // col map
    local_size += A.NumMyCols() * sizeof(int);
    // import vectors (assume nrhs == 1)
    if (A.Comm().NumProc() > 1)
        local_size += A.NumMyCols() * sizeof(double);
    return local_size;
}

static void get_local_nnz(const Epetra_CrsMatrix& A, int* nnz_diag, int* nnz_offdiag) {
    *nnz_diag = 0;
    *nnz_offdiag = 0;
    for (int i_row = 0; i_row < A.NumMyRows(); ++ i_row) {
        int num_entries;
        double* val;
        int* col;
        A.ExtractMyRowView(i_row, num_entries, val, col);        
        for (int k = 0; k < num_entries; ++ k) {
            if (A.DomainMap().MyGID(A.ColMap().GID(col[k]))) {
                *nnz_diag += 1;
            } else {
                *nnz_offdiag += 1;
            }
        }
    }
}

void log_matrix_stats(string matrix_name, const Epetra_CrsMatrix* A) {
    size_t local_size = get_matrix_mem_footprint(*A);
    double local_size_d = static_cast<double>(local_size);
    double sum_size_d, max_size_d;
    A->Comm().SumAll(&local_size_d, &sum_size_d, 1);
    A->Comm().MaxAll(&local_size_d, &max_size_d, 1);
    int nnz, local_nnz_diag, local_nnz_offdiag;
    nnz = A->NumGlobalNonzeros();
    get_local_nnz(*A, &local_nnz_diag, &local_nnz_offdiag);
    double local_nnz_diag_d = static_cast<double>(local_nnz_diag);
    double sum_nnz_diag_d;
    A->Comm().SumAll(&local_nnz_diag_d, &sum_nnz_diag_d, 1);
    rInfo("%s: nrows=%d, ncols=%d, nnz=%d, p_nnz_diag=%.1f%%, mem(sum)=%s, mem(max)=%s",
          matrix_name.c_str(),
          A->NumGlobalRows(),
          A->NumGlobalCols(),
          nnz,
          nnz == 0 ? 0.0 : 100.0*sum_nnz_diag_d/static_cast<double>(nnz),
          rlog::bytes2str(static_cast<unsigned long long>(sum_size_d)).c_str(),
          rlog::bytes2str(static_cast<unsigned long long>(max_size_d)).c_str());
}

#if defined(__QK_USER__)

clock_t times(struct tms *buf) {
    float rt, pt, ipc;
    long_long ins;
    int info;

    info = PAPI_ipc(&rt, &pt, &ins, &ipc);
    if (info != PAPI_OK)
        return -1;

    // Set user time to PAPI process time
    buf->tms_utime = (clock_t)(unsigned long long)(pt * CLK_TCK);
    // Set system time and child times to zero
    buf->tms_stime = 0;
    buf->tms_cutime = 0;
    buf->tms_cstime = 0;

    // Return wallclock time (overflow may happen here!)
    return (clock_t)(unsigned long long)(rt * CLK_TCK);
}

#endif

---