IpplTimings.cpp 12 KB
Newer Older
gsell's avatar
gsell committed
1 2 3 4
// -*- C++ -*-
/***************************************************************************
 *
 * The IPPL Framework
kraus's avatar
kraus committed
5 6
 *
 * This program was prepared by PSI.
gsell's avatar
gsell committed
7 8 9 10 11 12 13 14 15 16 17 18 19
 * All rights in the program are reserved by PSI.
 * Neither PSI nor the author(s)
 * makes any warranty, express or implied, or assumes any liability or
 * responsibility for the use of this software
 *
 * Visit www.amas.web.psi for more details
 *
 ***************************************************************************/

// -*- C++ -*-
/***************************************************************************
 *
 * The IPPL Framework
kraus's avatar
kraus committed
20
 *
gsell's avatar
gsell committed
21 22 23 24 25 26 27 28 29 30 31 32
 *
 * Visit http://people.web.psi.ch/adelmann/ for more details
 *
 ***************************************************************************/

// include files
#include "Utility/IpplTimings.h"
#include "Utility/Inform.h"
#include "Utility/IpplInfo.h"
#include "Message/GlobalComm.h"
#include "PETE/IpplExpressions.h"

kraus's avatar
kraus committed
33 34
#include <boost/algorithm/string/predicate.hpp>

gsell's avatar
gsell committed
35 36
#include <fstream>
#include <iostream>
kraus's avatar
kraus committed
37
#include <algorithm>
gsell's avatar
gsell committed
38 39
// static data members of IpplTimings class

40 41
Timing* IpplTimings::instance = new Timing();
std::stack<Timing*> IpplTimings::stashedInstance;
gsell's avatar
gsell committed
42 43 44

//////////////////////////////////////////////////////////////////////
// default constructor
45 46 47 48
Timing::Timing():
    TimerList(),
    TimerMap()
{ }
gsell's avatar
gsell committed
49 50 51 52


//////////////////////////////////////////////////////////////////////
// destructor
53 54 55 56 57 58 59 60
Timing::~Timing() {
    for (TimerMap_t::iterator it = TimerMap.begin(); it != TimerMap.end(); ++ it) {
        it->second = 0;
    }
    TimerMap.clear();

    TimerList.clear();
}
gsell's avatar
gsell committed
61 62 63 64


//////////////////////////////////////////////////////////////////////
// create a timer, or get one that already exists
65 66 67 68 69 70 71 72 73 74 75 76 77 78
Timing::TimerRef Timing::getTimer(const char *nm) {
    std::string s(nm);
    TimerInfo *tptr = 0;
    TimerMap_t::iterator loc = TimerMap.find(s);
    if (loc == TimerMap.end()) {
        tptr = new TimerInfo;
        tptr->indx = TimerList.size();
        tptr->name = s;
        TimerMap.insert(TimerMap_t::value_type(s,tptr));
        TimerList.push_back(my_auto_ptr<TimerInfo>(tptr));
    } else {
        tptr = (*loc).second;
    }
    return tptr->indx;
gsell's avatar
gsell committed
79 80 81 82 83
}


//////////////////////////////////////////////////////////////////////
// start a timer
84 85 86 87
void Timing::startTimer(TimerRef t) {
    if (t >= TimerList.size())
        return;
    TimerList[t]->start();
gsell's avatar
gsell committed
88 89 90 91 92
}


//////////////////////////////////////////////////////////////////////
// stop a timer, and accumulate it's values
93
void Timing::stopTimer(TimerRef t) {
gsell's avatar
gsell committed
94
    if (t >= TimerList.size())
95 96
        return;
    TimerList[t]->stop();
gsell's avatar
gsell committed
97 98 99 100 101
}


//////////////////////////////////////////////////////////////////////
// clear a timer, by turning it off and throwing away its time
102 103 104 105
void Timing::clearTimer(TimerRef t) {
    if (t >= TimerList.size())
        return;
    TimerList[t]->clear();
gsell's avatar
gsell committed
106 107 108 109 110
}

#ifdef IPPL_XT3
//////////////////////////////////////////////////////////////////////
// print out the timing results
111
void Timing::print() {
gsell's avatar
gsell committed
112 113 114
    int i,j;
    if (TimerList.size() < 1)
	return;
kraus's avatar
kraus committed
115

gsell's avatar
gsell committed
116 117
    // report the average time for each timer
    Inform msg("Timings");
kraus's avatar
kraus committed
118 119
    msg << level1 << "-----------------------------------------------------------------\n";
    msg << "     Timing (dclock) results for " << Ippl::getNodes() << " nodes:" << "\n";
gsell's avatar
gsell committed
120
    msg << "-----------------------------------------------------------------";
kraus's avatar
kraus committed
121
    msg << "\n";
gsell's avatar
gsell committed
122 123
    for (i=0; i<1; ++i){
	TimerInfo *tptr = TimerList[i].get();
kraus's avatar
kraus committed
124
	double walltotal = 0.0;
gsell's avatar
gsell committed
125 126 127 128 129 130 131
	reduce(tptr->wallTime, walltotal, OpMaxAssign());
	msg << tptr->name.c_str() << " ";
	for (j=strlen(tptr->name.c_str()); j < 10; ++j)
	    msg << ".";
	msg << " Wall tot = ";
	msg.width(10);
	msg << walltotal;
kraus's avatar
kraus committed
132
	msg << "\n\n";
gsell's avatar
gsell committed
133 134 135 136 137 138 139 140 141 142 143 144 145 146
    }

    for (i=1; i < TimerList.size(); ++i) {
	TimerInfo *tptr = TimerList[i].get();
	double wallmax = 0.0, wallmin = 0.0;
	double wallavg = 0.0 ;
	reduce(tptr->wallTime, wallmax, OpMaxAssign());
	reduce(tptr->wallTime, wallmin, OpMinAssign());
	reduce(tptr->wallTime, wallavg, OpAddAssign());
	msg << tptr->name.c_str() << " ";
	for (j=strlen(tptr->name.c_str()); j < 10; ++j)
	    msg << ".";
	msg << " Wall max = ";
	msg.width(10);
kraus's avatar
kraus committed
147
	msg << wallmax << "\n";
gsell's avatar
gsell committed
148 149 150 151
	for (j = 0; j < 21; ++j)
	    msg << " ";
	msg << " Wall avg = ";
	msg.width(10);
kraus's avatar
kraus committed
152
	msg << wallavg / Ippl::getNodes() << "\n";
gsell's avatar
gsell committed
153 154 155 156
	for (j = 0; j < 21; ++j)
	    msg << " ";
	msg << " Wall min = ";
	msg.width(10);
kraus's avatar
kraus committed
157
	msg << wallmin << "\n\n";
gsell's avatar
gsell committed
158 159 160 161 162 163 164 165 166
    }
    msg << "-----------------------------------------------------------------";
    msg << endl;
}

#else

//////////////////////////////////////////////////////////////////////
// print out the timing results
167
void Timing::print() {
kraus's avatar
kraus committed
168 169
    if (TimerList.size() < 1)
        return;
gsell's avatar
gsell committed
170

kraus's avatar
kraus committed
171 172
    // report the average time for each timer
    Inform msg("Timings");
kraus's avatar
kraus committed
173 174 175 176
    msg << level1
        << "-----------------------------------------------------------------";
    msg << "\n";
    msg << "     Timing results for " << Ippl::getNodes() << " nodes:" << "\n";
kraus's avatar
kraus committed
177
    msg << "-----------------------------------------------------------------";
kraus's avatar
kraus committed
178
    msg << "\n";
gsell's avatar
gsell committed
179

kraus's avatar
kraus committed
180 181 182 183 184 185 186 187 188 189
    {
        TimerInfo *tptr = TimerList[0].get();
        double walltotal = 0.0, cputotal = 0.0;
        reduce(tptr->wallTime, walltotal, OpMaxAssign());
        reduce(tptr->cpuTime, cputotal, OpMaxAssign());
        size_t lengthName = std::min(tptr->name.length(), 19lu);
        msg << tptr->name.substr(0,lengthName)
            << std::string().assign(20 - lengthName,'.')
            << " Wall tot = " << std::setw(10) << walltotal << ","
            << " CPU tot = " << std::setw(10) << cputotal << "\n"
kraus's avatar
kraus committed
190
            << "\n";
kraus's avatar
kraus committed
191 192 193 194
    }

    auto begin = ++ TimerList.begin();
    auto end = TimerList.end();
195
    std::sort(begin, end, [](const my_auto_ptr<TimerInfo>& a, const my_auto_ptr<TimerInfo>& b)
kraus's avatar
kraus committed
196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221
              {
                  return boost::ilexicographical_compare(a->name, b->name);
              });

    for (unsigned int i=1; i < TimerList.size(); ++i) {
        TimerInfo *tptr = TimerList[i].get();
        double wallmax = 0.0, cpumax = 0.0, wallmin = 0.0, cpumin = 0.0;
        double wallavg = 0.0, cpuavg = 0.0;
        reduce(tptr->wallTime, wallmax, OpMaxAssign());
        reduce(tptr->cpuTime,  cpumax,  OpMaxAssign());
        reduce(tptr->wallTime, wallmin, OpMinAssign());
        reduce(tptr->cpuTime,  cpumin,  OpMinAssign());
        reduce(tptr->wallTime, wallavg, OpAddAssign());
        reduce(tptr->cpuTime,  cpuavg,  OpAddAssign());
        size_t lengthName = std::min(tptr->name.length(), 19lu);

        msg << tptr->name.substr(0,lengthName)
            << std::string().assign(20 - lengthName, '.')
            << " Wall max = " << std::setw(10) << wallmax << ","
            << " CPU max = " << std::setw(10) << cpumax << "\n"
            << std::string().assign(20,' ')
            << " Wall avg = " << std::setw(10) << wallavg / Ippl::getNodes() << ","
            << " CPU avg = " << std::setw(10) << cpuavg / Ippl::getNodes() << "\n"
            << std::string().assign(20,' ')
            << " Wall min = " << std::setw(10) << wallmin << ","
            << " CPU min = " << std::setw(10) << cpumin << "\n"
kraus's avatar
kraus committed
222
            << "\n";
kraus's avatar
kraus committed
223 224 225
    }
    msg << "-----------------------------------------------------------------";
    msg << endl;
gsell's avatar
gsell committed
226 227 228 229 230
}
#endif

//////////////////////////////////////////////////////////////////////
// save the timing results into a file
adelmann's avatar
adelmann committed
231
void Timing::print(const std::string &fn, const std::map<std::string, unsigned int> &problemSize) {
gsell's avatar
gsell committed
232

kraus's avatar
kraus committed
233 234
    std::ofstream *timer_stream;
    Inform *msg;
gsell's avatar
gsell committed
235

kraus's avatar
kraus committed
236 237 238 239 240 241 242 243 244 245
    if (TimerList.size() < 1)
        return;

    timer_stream = new std::ofstream;
    timer_stream->open( fn.c_str(), std::ios::out );
    msg = new Inform( 0, *timer_stream, 0 );
    // report the average time for each timer
    // Inform msg("Timings");
    /*
     *msg << "---------------------------------------------------------------------------";
kraus's avatar
kraus committed
246 247
     *msg << "\n";
     *msg << "     Timing results for " << Ippl::getNodes() << " nodes:" << "\n";
kraus's avatar
kraus committed
248 249
     *msg << "---------------------------------------------------------------------------";
     *msg << " name nodes (cputot cpumax) (walltot wallmax) cpumin wallmin cpuav wallav  ";
kraus's avatar
kraus committed
250
     *msg << "\n";
kraus's avatar
kraus committed
251 252
     */

adelmann's avatar
adelmann committed
253 254 255 256 257 258 259 260
    if (problemSize.size() > 0) {
        *msg << "Problem size:\n";
        for (auto it: problemSize) {
            *msg << "    " << std::setw(10) << it.first << ": " << it.second << "\n";
        }
        *msg << endl;
    }

kraus's avatar
kraus committed
261 262 263 264
    *msg << std::setw(27) << "num Nodes"
         << std::setw(10) << "CPU tot"
         << std::setw(11) << "Wall tot\n"
         << std::string().assign(47,'=')
kraus's avatar
kraus committed
265
         << "\n";
kraus's avatar
kraus committed
266 267 268 269 270 271 272 273 274 275 276 277 278
    {
        TimerInfo *tptr = TimerList[0].get();
        double walltotal = 0.0, cputotal = 0.0;
        reduce(tptr->wallTime, walltotal, OpMaxAssign());
        reduce(tptr->cpuTime, cputotal, OpMaxAssign());
        size_t lengthName = std::min(tptr->name.length(), 19lu);
        *msg << tptr->name.substr(0,lengthName);
        for (int j=lengthName; j < 20; ++j) {
            *msg << ".";
        }
        *msg  << " " << std::setw(6)  << Ippl::getNodes()
              << " " << std::setw(9) << std::setprecision(4) << cputotal
              << " " << std::setw(9) << std::setprecision(4) << walltotal
kraus's avatar
kraus committed
279
              << "\n";
kraus's avatar
kraus committed
280 281 282 283
    }

    auto begin = ++ TimerList.begin();
    auto end = TimerList.end();
284
    std::sort(begin, end, [](const my_auto_ptr<TimerInfo>& a, const my_auto_ptr<TimerInfo>& b)
kraus's avatar
kraus committed
285 286 287 288 289 290 291 292 293 294 295 296 297
              {
                  return boost::ilexicographical_compare(a->name, b->name);
              });

    *msg << "\n"
         << std::setw(27) << "num Nodes"
         << std::setw(10) << "CPU max"
         << std::setw(10) << "Wall max"
         << std::setw(10) << "CPU min"
         << std::setw(10) << "Wall min"
         << std::setw(10) << "CPU avg"
         << std::setw(11) << "Wall avg\n"
         << std::string().assign(87,'=')
kraus's avatar
kraus committed
298
         << "\n";
299
    for (unsigned int i=0; i < TimerList.size(); ++i) {
kraus's avatar
kraus committed
300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325
        TimerInfo *tptr = TimerList[i].get();
        double wallmax = 0.0, cpumax = 0.0, wallmin = 0.0, cpumin = 0.0;
        double wallavg = 0.0, cpuavg = 0.0;
        reduce(tptr->wallTime, wallmax, OpMaxAssign());
        reduce(tptr->cpuTime,  cpumax,  OpMaxAssign());
        reduce(tptr->wallTime, wallmin, OpMinAssign());
        reduce(tptr->cpuTime,  cpumin,  OpMinAssign());
        reduce(tptr->wallTime, wallavg, OpAddAssign());
        reduce(tptr->cpuTime,  cpuavg,  OpAddAssign());
        size_t lengthName = std::min(tptr->name.length(), 19lu);
        *msg << tptr->name.substr(0,lengthName);
        for (int j=lengthName; j < 20; ++j) {
            *msg << ".";
        }
        *msg << " " << std::setw(6) << Ippl::getNodes()
             << " " << std::setw(9) << std::setprecision(4) << cpumax
             << " " << std::setw(9) << std::setprecision(4) << wallmax
             << " " << std::setw(9) << std::setprecision(4) << cpumin
             << " " << std::setw(9) << std::setprecision(4) << wallmin
             << " " << std::setw(9) << std::setprecision(4) << cpuavg / Ippl::getNodes()
             << " " << std::setw(9) << std::setprecision(4) << wallavg / Ippl::getNodes()
             << endl;
    }
    timer_stream->close();
    delete msg;
    delete timer_stream;
gsell's avatar
gsell committed
326 327
}

328 329 330 331
IpplTimings::IpplTimings() { }
IpplTimings::~IpplTimings() { }

void IpplTimings::stash() {
332
    PAssert_EQ(stashedInstance.size(), 0);
333 334 335 336 337 338

    stashedInstance.push(instance);
    instance = new Timing();
}

void IpplTimings::pop() {
339
    PAssert_GT(stashedInstance.size(), 0);
340 341 342 343 344

    delete instance;
    instance = stashedInstance.top();
    stashedInstance.pop();
}
gsell's avatar
gsell committed
345 346 347 348 349 350 351 352 353 354

/***************************************************************************
 * $RCSfile: IpplTimings.cpp,v $   $Author: adelmann $
 * $Revision: 1.1.1.1 $   $Date: 2003/01/23 07:40:33 $
 ***************************************************************************/


/***************************************************************************
 * $RCSfile: addheaderfooter,v $   $Author: adelmann $
 * $Revision: 1.1.1.1 $   $Date: 2003/01/23 07:40:17 $
kraus's avatar
kraus committed
355
 * IPPL_VERSION_ID: $Id: addheaderfooter,v 1.1.1.1 2003/01/23 07:40:17 adelmann Exp $
adelmann's avatar
adelmann committed
356
 ***************************************************************************/