src/support/pmprof.h

   1 // -*- C++ -*-
   2 /* \file pmprof.h
   3  * This file is part of LyX, the document processor.
   4  * Licence details can be found in the file COPYING.
   5  *
   6  * \author Jean-Marc Lasgouttes
   7  *
   8  * Full author contact details are available in file CREDITS.
   9  */
  10
  11 /**
  12  * ==== HOW TO USE THIS TRIVIAL PROFILER:
  13  *
  14  * * at the beginning of the interesting block, just add:
  15  *   PROFILE_THIS_BLOCK(some_identifier)
  16  *
  17  *   A trailing semicolon can be added at your discretion.
  18  *
  19  * * when the program ends, statistics will be sent to standard error, like:
  20  *
  21  *   #pmprof# some_identifier: 6.51usec, count=7120, total=46.33msec
  22  *
  23  * * It is also possible to profile caching schemes. All it takes is an additional
  24  *   PROFILE_CACHE_MISS(some_identifier)
  25  *   in the place that takes care of cache misses. Then the output at the end will change to
  26  *
  27  *   #pmprof# some_identifier: 6.51usec, count=7120, total=46.33msec
  28  *      hit: 96%, 4.36usec, count=6849, total=29.89msec
  29  *     miss: 3%, 60.65usec, count=271, total=16.43msec
  30  *
  31  * * if DISABLE_PMPROF is defined before including pmprof.h, the
  32  *   profiler is replaced by empty macros. This is useful for quickly
  33  *   checking the overhead.
  34  *
  35  * ==== ABOUT PROFILING SCOPE:
  36  *
  37  * The code measured by the profiler corresponds to the lifetime of a
  38  * local variable declared by the PROFILE_THIS_BLOCK macro.
  39  *
  40  * Some examples of profiling scope: In the snippets below, c1, c2...
  41  * designate code chunks, and the identifiers of profiling blocks are
  42  * chosen to reflect what they count.
  43  *
  44  * {
  45  *   c1
  46  *   PROFILE_THIS_BLOCK(c2)
  47  *   c2
  48  * }
  49  *
  50  *
  51  * {
  52  *   PROFILE_THIS_BLOCK(c1_c2)
  53  *   c1
  54  *   PROFILE_THIS_BLOCK(c2)
  55  *   c2
  56  * }
  57  *
  58  *
  59  * {
  60  *   {
  61  *     PROFILE_THIS_BLOCK(c1)
  62  *     c1
  63  *   }
  64  *   PROFILE_THIS_BLOCK(c2)
  65  *   c2
  66  * }
  67  *
  68  *
  69  * {
  70  *   PROFILE_THIS_BLOCK(c1_c2_c3)
  71  *   c1
  72  *   {
  73  *     PROFILE_THIS_BLOCK(c2)
  74  *     c2
  75  *   }
  76  *   c3
  77  * }
  78  *
  79  * Influence of identifier names: they are mainly used for display
  80  * purpose, but the same name should not be used twice in the same
  81  * scope.
  82  *
  83  * {
  84  *   PROFILE_THIS_BLOCK(foo)
  85  *   c1
  86  *   PROFILE_THIS_BLOCK(foo) // error: identifier clash
  87  *   c2
  88  * }
  89  *
  90  * In the example below, c1+c2 and c2 are counted separately, but in
  91  * the output, both are confusingly labelled `foo'.
  92  *
  93  * {
  94  *   PROFILE_THIS_BLOCK(foo)
  95  *   c1
  96  *   {
  97  *     PROFILE_THIS_BLOCK(foo) // error: identifier clash
  98  *     c2
  99  *   }
 100  * }
 101
 102  */
 103
 104 #ifndef PMPROF_H
 105 #define PMPROF_H
 106
 107 #if defined(DISABLE_PMPROF)
 108
 109 // Make pmprof an empty shell
 110 #define PROFILE_THIS_BLOCK(a)
 111 #define PROFILE_CACHE_MISS(a)
 112
 113 #else
 114
 115 #ifdef _WIN32
 116 #include <windows.h>
 117 #else
 118 #include <sys/time.h>
 119 #endif
 120
 121 #include <iomanip>
 122 #include <iostream>
 123
 124
 125 #if defined(__GNUG__) && defined(_GLIBCXX_DEBUG)
 126 #error Profiling is not usable when run-time debugging is in effect
 127 #endif
 128
 129 #ifdef _WIN32
 130 /* This function does not really returns the "time of day",
 131  * but it will suffice to evaluate elapsed times.
 132  */
 133 int gettimeofday(struct timeval * tv, struct timezone * /*tz*/)
 134 {
 135         LARGE_INTEGER frequency, t;
 136         QueryPerformanceFrequency(&frequency);
 137         QueryPerformanceCounter(&t);
 138
 139         tv->tv_sec = long(t.QuadPart / frequency.QuadPart);
 140         tv->tv_usec = long((1000000.0 * (t.QuadPart % frequency.QuadPart)) / frequency.QuadPart);
 141         return 0;
 142 }
 143
 144 #endif // _WIN32
 145
 146 namespace {
 147
 148 void dumpTime(long long value)
 149 {
 150         std::cerr << std::fixed << std::setprecision(2);
 151         if (value >= 1000000)
 152                 std::cerr << value / 1000000 << "sec";
 153         else if (value >= 1000)
 154                 std::cerr << value / 1000 << "msec";
 155         else
 156                 std::cerr << value << "usec";
 157 }
 158
 159 void dump(long long sec, long long usec, unsigned long long count) {
 160         double const total = sec * 1000000 + usec;
 161         dumpTime(total / count);
 162         std::cerr << ", count=" << count
 163                           << ", total=";
 164         dumpTime(total);
 165         std::cerr << std::endl;
 166 }
 167
 168 } // namespace
 169
 170
 171 /* Helper class for gathering data. Instantiate this as a static
 172  * variable, so that its destructor will be executed when the program
 173  * ends.
 174  */
 175
 176
 177 class PMProfStat {
 178 public:
 179         PMProfStat(char const * name) : name_(name), sec_(0), usec_(0), count_(0),
 180                                     miss_sec_(0), miss_usec_(0), miss_count_(0) {}
 181
 182         ~PMProfStat() {
 183                 if (count_>0) {
 184                         if (miss_count_ == 0) {
 185                                 std::cerr << "#pmprof# " << name_ << ": ";
 186                                 dump(sec_, usec_, count_);
 187                         }
 188                         else {
 189                                 std::cerr << "#pmprof# " << name_ << ": ";
 190                                 dump(sec_ + miss_sec_, usec_ + miss_usec_, count_ + miss_count_);
 191                                 std::cerr << "   hit: " << 100 * count_ / (count_ + miss_count_) << "%, ";
 192                                 dump(sec_, usec_, count_);
 193                                 std::cerr << "  miss: " << 100 * miss_count_ / (count_ + miss_count_) << "%, ";
 194                                 dump(miss_sec_, miss_usec_, miss_count_);
 195                         }
 196                 }
 197         }
 198
 199         void add(const long long s, const long long u, const bool hit) {
 200                 if (hit) {
 201                         sec_ += s;
 202                         usec_ += u;
 203                         count_++;
 204                 } else {
 205                         miss_sec_ += s;
 206                         miss_usec_ += u;
 207                         miss_count_++;
 208                 }
 209         }
 210
 211 private:
 212         char const * name_;
 213         long long sec_, usec_;
 214         unsigned long long count_;
 215         long long miss_sec_, miss_usec_;
 216         unsigned long long miss_count_;
 217 };
 218
 219
 220 /* Helper class which gathers data at the end of the scope. One
 221  * instance of this one should be created at each execution of the
 222  * block. At the end of the block, it sends statistics to the static
 223  * PMProfStat object.
 224  */
 225 class PMProfInstance {
 226 public:
 227         PMProfInstance(PMProfStat * stat) : hit(true), stat_(stat)
 228         {
 229                 gettimeofday(&before_, 0);
 230         }
 231
 232         ~PMProfInstance() {
 233                 gettimeofday(&after_, 0);
 234                 stat_->add(after_.tv_sec - before_.tv_sec,
 235                            after_.tv_usec - before_.tv_usec, hit);
 236         }
 237
 238         bool hit;
 239
 240 private:
 241         timeval before_, after_;
 242         PMProfStat * stat_;
 243 };
 244
 245
 246 #define PROFILE_THIS_BLOCK(a) \
 247         static PMProfStat PMPS_##a(#a);\
 248         PMProfInstance PMPI_##a(&PMPS_##a);
 249
 250 #define PROFILE_CACHE_MISS(a) \
 251         PMPI_##a.hit = false;
 252
 253 #endif // !defined(DISABLE_PMPROF)
 254
 255 #endif