| 1 | /*
 | 
|---|
| 2 |  *    vmg - a versatile multigrid solver
 | 
|---|
| 3 |  *    Copyright (C) 2012 Institute for Numerical Simulation, University of Bonn
 | 
|---|
| 4 |  *
 | 
|---|
| 5 |  *  vmg is free software: you can redistribute it and/or modify
 | 
|---|
| 6 |  *  it under the terms of the GNU General Public License as published by
 | 
|---|
| 7 |  *  the Free Software Foundation, either version 3 of the License, or
 | 
|---|
| 8 |  *  (at your option) any later version.
 | 
|---|
| 9 |  *
 | 
|---|
| 10 |  *  vmg is distributed in the hope that it will be useful,
 | 
|---|
| 11 |  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 | 
|---|
| 12 |  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 | 
|---|
| 13 |  *  GNU General Public License for more details.
 | 
|---|
| 14 |  *
 | 
|---|
| 15 |  *  You should have received a copy of the GNU General Public License
 | 
|---|
| 16 |  *  along with this program.  If not, see <http://www.gnu.org/licenses/>.
 | 
|---|
| 17 |  */
 | 
|---|
| 18 | 
 | 
|---|
| 19 | /**
 | 
|---|
| 20 |  * @file   timer.cpp
 | 
|---|
| 21 |  * @author Julian Iseringhausen <isering@ins.uni-bonn.de>
 | 
|---|
| 22 |  * @date   Tue Sep 6 16:17:40 2011
 | 
|---|
| 23 |  *
 | 
|---|
| 24 |  * @brief  Class to measure timings.
 | 
|---|
| 25 |  *
 | 
|---|
| 26 |  */
 | 
|---|
| 27 | 
 | 
|---|
| 28 | #ifdef HAVE_CONFIG_H
 | 
|---|
| 29 | #include <libvmg_config.h>
 | 
|---|
| 30 | #endif
 | 
|---|
| 31 | 
 | 
|---|
| 32 | #ifdef HAVE_MPI
 | 
|---|
| 33 | #include <mpi.h>
 | 
|---|
| 34 | #ifdef HAVE_MARMOT
 | 
|---|
| 35 | #include <enhancempicalls.h>
 | 
|---|
| 36 | #include <sourceinfompicalls.h>
 | 
|---|
| 37 | #endif
 | 
|---|
| 38 | #endif
 | 
|---|
| 39 | 
 | 
|---|
| 40 | #include <iostream>
 | 
|---|
| 41 | #include <limits>
 | 
|---|
| 42 | #include <sstream>
 | 
|---|
| 43 | 
 | 
|---|
| 44 | #include "base/helper.hpp"
 | 
|---|
| 45 | #include "base/timer.hpp"
 | 
|---|
| 46 | #include "comm/comm.hpp"
 | 
|---|
| 47 | #include "thirdparty/pugixml/pugixml.hpp"
 | 
|---|
| 48 | #include "mg.hpp"
 | 
|---|
| 49 | 
 | 
|---|
| 50 | using namespace VMG;
 | 
|---|
| 51 | 
 | 
|---|
| 52 | std::map<std::string, TimerData> Timer::td;
 | 
|---|
| 53 | 
 | 
|---|
| 54 | template <class T>
 | 
|---|
| 55 | static T min(T* data, int num_data, int& at_rank)
 | 
|---|
| 56 | {
 | 
|---|
| 57 |   at_rank = 0;
 | 
|---|
| 58 |   T min = data[0];
 | 
|---|
| 59 | 
 | 
|---|
| 60 |   for (int i=1; i<num_data; ++i)
 | 
|---|
| 61 |     if (data[i] < min) {
 | 
|---|
| 62 |       at_rank = i;
 | 
|---|
| 63 |       min = data[i];
 | 
|---|
| 64 |     }
 | 
|---|
| 65 |   return min;
 | 
|---|
| 66 | }
 | 
|---|
| 67 | 
 | 
|---|
| 68 | template <class T>
 | 
|---|
| 69 | static T max(T* data, int num_data, int& at_rank)
 | 
|---|
| 70 | {
 | 
|---|
| 71 |   at_rank = 0;
 | 
|---|
| 72 |   T max = data[0];
 | 
|---|
| 73 | 
 | 
|---|
| 74 |   for (int i=1; i<num_data; ++i)
 | 
|---|
| 75 |     if (data[i] > max) {
 | 
|---|
| 76 |       at_rank = i;
 | 
|---|
| 77 |       max = data[i];
 | 
|---|
| 78 |     }
 | 
|---|
| 79 |   return max;
 | 
|---|
| 80 | }
 | 
|---|
| 81 | 
 | 
|---|
| 82 | template <class T>
 | 
|---|
| 83 | static vmg_float avg(T* data, int num_data)
 | 
|---|
| 84 | {
 | 
|---|
| 85 |   vmg_float average = 0.0;
 | 
|---|
| 86 |   vmg_float num_data_inv = 1.0 / static_cast<vmg_float>(num_data);
 | 
|---|
| 87 |   for (int i=0; i<num_data; ++i)
 | 
|---|
| 88 |     average += data[i] * num_data_inv;
 | 
|---|
| 89 |   return average;
 | 
|---|
| 90 | }
 | 
|---|
| 91 | 
 | 
|---|
| 92 | void Timer::Start(std::string event)
 | 
|---|
| 93 | {
 | 
|---|
| 94 | #ifdef HAVE_MPI
 | 
|---|
| 95 | #ifdef OUTPUT_TIMING
 | 
|---|
| 96 |   std::map<std::string, TimerData>::iterator iter = td.find(event);
 | 
|---|
| 97 |   if (iter == td.end())
 | 
|---|
| 98 |     iter = td.insert(std::make_pair(event, TimerData())).first;
 | 
|---|
| 99 | 
 | 
|---|
| 100 |   iter->second.time_start = MPI_Wtime();
 | 
|---|
| 101 | #endif
 | 
|---|
| 102 | #endif
 | 
|---|
| 103 | }
 | 
|---|
| 104 | 
 | 
|---|
| 105 | void Timer::Stop(std::string event)
 | 
|---|
| 106 | {
 | 
|---|
| 107 | #ifdef HAVE_MPI
 | 
|---|
| 108 | #ifdef OUTPUT_TIMING
 | 
|---|
| 109 |   double time_end = MPI_Wtime();
 | 
|---|
| 110 | 
 | 
|---|
| 111 |   std::map<std::string, TimerData>::iterator iter = td.find(event);
 | 
|---|
| 112 | 
 | 
|---|
| 113 |   if (time_end - iter->second.time_start < std::numeric_limits<double>::min())
 | 
|---|
| 114 |     ++(iter->second.warning);
 | 
|---|
| 115 | 
 | 
|---|
| 116 |   ++(iter->second.total);
 | 
|---|
| 117 | 
 | 
|---|
| 118 |   iter->second.duration += time_end - iter->second.time_start;
 | 
|---|
| 119 | #endif
 | 
|---|
| 120 | #endif
 | 
|---|
| 121 | }
 | 
|---|
| 122 | 
 | 
|---|
| 123 | void Timer::Clear()
 | 
|---|
| 124 | {
 | 
|---|
| 125 |   td.clear();
 | 
|---|
| 126 | }
 | 
|---|
| 127 | 
 | 
|---|
| 128 | pugi::xml_node Timer::ToXMLNode()
 | 
|---|
| 129 | {
 | 
|---|
| 130 |  std::map<std::string, TimerData>::iterator iter;
 | 
|---|
| 131 | 
 | 
|---|
| 132 |  pugi::xml_node node_process;
 | 
|---|
| 133 |  node_process.append_attribute("Rank").set_value(MG::GetComm()->GlobalRank());
 | 
|---|
| 134 | 
 | 
|---|
| 135 |  pugi::xml_node node_timings = node_process.append_child("Timings");
 | 
|---|
| 136 | 
 | 
|---|
| 137 |  for (iter=Timer::td.begin(); iter!=Timer::td.end(); ++iter) {
 | 
|---|
| 138 | 
 | 
|---|
| 139 |    pugi::xml_node node_entry = node_timings.append_child("Sample");
 | 
|---|
| 140 |    node_entry.append_attribute("Name").set_value(Helper::ToString(iter->first).c_str());
 | 
|---|
| 141 | 
 | 
|---|
| 142 |    node_entry.append_child("Duration")
 | 
|---|
| 143 |      .append_child(pugi::node_pcdata)
 | 
|---|
| 144 |      .set_value(Helper::ToString(iter->second.duration).c_str());
 | 
|---|
| 145 | 
 | 
|---|
| 146 |    node_entry.append_child("Warnings")
 | 
|---|
| 147 |      .append_child(pugi::node_pcdata)
 | 
|---|
| 148 |      .set_value(Helper::ToString(iter->second.warning).c_str());
 | 
|---|
| 149 | 
 | 
|---|
| 150 |    node_entry.append_child("Total")
 | 
|---|
| 151 |      .append_child(pugi::node_pcdata)
 | 
|---|
| 152 |      .set_value(Helper::ToString(iter->second.total).c_str());
 | 
|---|
| 153 | 
 | 
|---|
| 154 |  }
 | 
|---|
| 155 | 
 | 
|---|
| 156 |  return node_process;
 | 
|---|
| 157 | }
 | 
|---|
| 158 | 
 | 
|---|
| 159 | std::string Timer::ToString()
 | 
|---|
| 160 | {
 | 
|---|
| 161 |   pugi::xml_node node = Timer::ToXMLNode();
 | 
|---|
| 162 |   std::stringstream str;
 | 
|---|
| 163 |   node.print(str);
 | 
|---|
| 164 |   return str.str();
 | 
|---|
| 165 | }
 | 
|---|
| 166 | 
 | 
|---|
| 167 | void Timer::Print()
 | 
|---|
| 168 | {
 | 
|---|
| 169 | #ifdef OUTPUT_TIMING
 | 
|---|
| 170 |   Comm& comm = *MG::GetComm();
 | 
|---|
| 171 |   if (comm.GlobalRank() == 0) {
 | 
|---|
| 172 |     std::map<std::string, TimerData>::const_iterator iter;
 | 
|---|
| 173 |     comm.PrintOnce(Timing, "Running times:");
 | 
|---|
| 174 |     for (iter=Timer::td.begin(); iter!=Timer::td.end(); ++iter)
 | 
|---|
| 175 |       comm.PrintOnce(Timing, "  %s: %e s (%d)", iter->first.c_str(), iter->second.duration, iter->second.total);
 | 
|---|
| 176 |   }
 | 
|---|
| 177 | #endif
 | 
|---|
| 178 | }
 | 
|---|
| 179 | void Timer::PrintGlobal()
 | 
|---|
| 180 | {
 | 
|---|
| 181 | #ifdef OUTPUT_TIMING
 | 
|---|
| 182 |   std::map<std::string, TimerData>::const_iterator iter;
 | 
|---|
| 183 |   Comm& comm = *MG::GetComm();
 | 
|---|
| 184 |   char name[80];
 | 
|---|
| 185 | 
 | 
|---|
| 186 |   int rank = comm.GlobalRank();
 | 
|---|
| 187 |   int size = comm.GlobalSize();
 | 
|---|
| 188 | 
 | 
|---|
| 189 |   vmg_float times[size];
 | 
|---|
| 190 |   int calls[size];
 | 
|---|
| 191 | 
 | 
|---|
| 192 |   comm.PrintOnce(Timing, "Running times (global):");
 | 
|---|
| 193 | 
 | 
|---|
| 194 |   int timer_size = Timer::td.size();
 | 
|---|
| 195 |   comm.GlobalBroadcast(timer_size);
 | 
|---|
| 196 | 
 | 
|---|
| 197 |   if (rank == 0) {
 | 
|---|
| 198 |       for (iter=Timer::td.begin(); iter!=Timer::td.end(); ++iter) {
 | 
|---|
| 199 |         std::strcpy(name, iter->first.c_str());
 | 
|---|
| 200 |         comm.GlobalBroadcast(name);
 | 
|---|
| 201 |         comm.GlobalGather(Timer::td[name].duration, times);
 | 
|---|
| 202 |         comm.GlobalGather(Timer::td[name].total, calls);
 | 
|---|
| 203 | 
 | 
|---|
| 204 |         int min_calls, max_calls;
 | 
|---|
| 205 |         vmg_float avg_calls;
 | 
|---|
| 206 |         vmg_float min_duration, max_duration, avg_duration;
 | 
|---|
| 207 |         int rank_min_calls, rank_max_calls, rank_min_duration, rank_max_duration;
 | 
|---|
| 208 | 
 | 
|---|
| 209 |         min_duration = min(times, size, rank_min_duration);
 | 
|---|
| 210 |         max_duration = max(times, size, rank_max_duration);
 | 
|---|
| 211 |         avg_duration = avg(times, size);
 | 
|---|
| 212 |         min_calls = min(calls, size, rank_min_calls);
 | 
|---|
| 213 |         max_calls = max(calls, size, rank_max_calls);
 | 
|---|
| 214 |         avg_calls = avg(calls, size);
 | 
|---|
| 215 | 
 | 
|---|
| 216 |         comm.PrintOnce(Timing, "  %s: %e s (%d)", iter->first.c_str(), iter->second.duration, iter->second.total);
 | 
|---|
| 217 |         comm.PrintOnce(Timing, "    Min: %e s @ %d", min_duration, rank_min_duration);
 | 
|---|
| 218 |         comm.PrintOnce(Timing, "    Max: %e s @ %d", max_duration, rank_max_duration);
 | 
|---|
| 219 |         comm.PrintOnce(Timing, "    Avg: %e s", avg_duration);
 | 
|---|
| 220 |         comm.PrintOnce(Timing, "    Min calls: %d @ %d", min_calls, rank_min_calls);
 | 
|---|
| 221 |         comm.PrintOnce(Timing, "    Max calls: %d @ %d", max_calls, rank_max_calls);
 | 
|---|
| 222 |         comm.PrintOnce(Timing, "    Avg calls: %f", avg_calls);
 | 
|---|
| 223 |     }
 | 
|---|
| 224 |   }else {
 | 
|---|
| 225 |     for (int i=0; i<timer_size; ++i) {
 | 
|---|
| 226 |       comm.GlobalBroadcast(name);
 | 
|---|
| 227 |       comm.GlobalGather(Timer::td[name].duration, times);
 | 
|---|
| 228 |       comm.GlobalGather(Timer::td[name].total, calls);
 | 
|---|
| 229 |     }
 | 
|---|
| 230 |   }
 | 
|---|
| 231 | 
 | 
|---|
| 232 | #endif
 | 
|---|
| 233 | }
 | 
|---|
| 234 | 
 | 
|---|
| 235 | std::ostream& VMG::operator<<(std::ostream& out, const Timer&)
 | 
|---|
| 236 | {
 | 
|---|
| 237 |   return out << Timer::ToString();
 | 
|---|
| 238 | }
 | 
|---|