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  *
  32  * ==== ABOUT PROFILING SCOPE:
  33  *
  34  * The code measured by the profiler corresponds to the lifetime of a
  35  * local variable declared by the PROFILE_THIS_BLOCK macro.
  36  *
  37  * Some examples of profiling scope: In the snippets below, c1, c2...
  38  * designate code chunks, and the identifiers of profiling blocks are
  39  * chosen to reflect what they count.
  40  *
  41  * {
  42  *   c1
  43  *   PROFILE_THIS_BLOCK(c2)
  44  *   c2
  45  * }
  46  *
  47  *
  48  * {
  49  *   PROFILE_THIS_BLOCK(c1_c2)
  50  *   c1
  51  *   PROFILE_THIS_BLOCK(c2)
  52  *   c2
  53  * }
  54  *
  55  *
  56  * {
  57  *   {
  58  *     PROFILE_THIS_BLOCK(c1)
  59  *     c1
  60  *   }
  61  *   PROFILE_THIS_BLOCK(c2)
  62  *   c2
  63  * }
  64  *
  65  *
  66  * {
  67  *   PROFILE_THIS_BLOCK(c1_c2_c3)
  68  *   c1
  69  *   {
  70  *     PROFILE_THIS_BLOCK(c2)
  71  *     c2
  72  *   }
  73  *   c3
  74  * }
  75  *
  76  * Influence of identifier names: they are mainly used for display
  77  * purpose, but the same name should not be used twice in the same
  78  * scope.
  79  *
  80  * {
  81  *   PROFILE_THIS_BLOCK(foo)
  82  *   c1
  83  *   PROFILE_THIS_BLOCK(foo) // error: identifier clash
  84  *   c2
  85  * }
  86  *
  87  * In the example below, c1+c2 and c2 are counted separately, but in
  88  * the output, both are confusingly labelled `foo'.
  89  *
  90  * {
  91  *   PROFILE_THIS_BLOCK(foo)
  92  *   c1
  93  *   {
  94  *     PROFILE_THIS_BLOCK(foo) // error: identifier clash
  95  *     c2
  96  *   }
  97  * }
  98
  99  */
 100
 101 #ifndef PMPROF_H
 102 #define PMPROF_H
 103
 104 #ifdef _WIN32
 105 #include <windows.h>
 106 #else
 107 #include <sys/time.h>
 108 #endif
 109
 110 #include <iomanip>
 111 #include <iostream>
 112
 113
 114 #if defined(__GNUG__) && defined(_GLIBCXX_DEBUG)
 115 #error Profiling is not usable when run-time debugging is in effect
 116 #endif
 117
 118 #ifdef _WIN32
 119 /* This function does not really returns the "time of day",
 120  * but it will suffice to evaluate elapsed times.
 121  */
 122 int gettimeofday(struct timeval * tv, struct timezone * /*tz*/)
 123 {
 124         LARGE_INTEGER frequency, t;
 125         QueryPerformanceFrequency(&frequency);
 126         QueryPerformanceCounter(&t);
 127
 128         tv->tv_sec = long(t.QuadPart / frequency.QuadPart);
 129         tv->tv_usec = long((1000000.0 * (t.QuadPart % frequency.QuadPart)) / frequency.QuadPart);
 130         return 0;
 131 }
 132
 133 #endif // _WIN32
 134
 135 namespace {
 136
 137 void dump(long long sec, long long usec, unsigned long long count) {
 138         double const total = sec * 1000000 + usec;
 139         std::cerr << std::fixed << std::setprecision(2)
 140                           << total / count
 141                           << "usec, count=" << count
 142                           << ", total=" << total * 0.001 << "msec"
 143                           << std::endl;
 144 }
 145
 146 }
 147
 148
 149 /* Helper class for gathering data. Instantiate this as a static
 150  * variable, so that its destructor will be executed when the program
 151  * ends.
 152  */
 153
 154
 155 class PMProfStat {
 156 public:
 157         PMProfStat(char const * name) : name_(name), sec_(0), usec_(0), count_(0),
 158                                     miss_sec_(0), miss_usec_(0), miss_count_(0) {}
 159
 160         ~PMProfStat() {
 161                 if (count_>0) {
 162                         if (miss_count_ == 0) {
 163                                 std::cerr << "#pmprof# " << name_ << ": ";
 164                                 dump(sec_, usec_, count_);
 165                         }
 166                         else {
 167                                 std::cerr << "#pmprof# " << name_ << ": ";
 168                                 dump(sec_ + miss_sec_, usec_ + miss_usec_, count_ + miss_count_);
 169                                 std::cerr << "   hit: " << 100 * count_ / (count_ + miss_count_) << "%, ";
 170                                 dump(sec_, usec_, count_);
 171                                 std::cerr << "  miss: " << 100 * miss_count_ / (count_ + miss_count_) << "%, ";
 172                                 dump(miss_sec_, miss_usec_, miss_count_);
 173                         }
 174                 }
 175         }
 176
 177         void add(const long long s, const long long u, const bool hit) {
 178                 if (hit) {
 179                         sec_ += s;
 180                         usec_ += u;
 181                         count_++;
 182                 } else {
 183                         miss_sec_ += s;
 184                         miss_usec_ += u;
 185                         miss_count_++;
 186                 }
 187         }
 188
 189 private:
 190         char const * name_;
 191         long long sec_, usec_;
 192         unsigned long long count_;
 193         long long miss_sec_, miss_usec_;
 194         unsigned long long miss_count_;
 195 };
 196
 197
 198 /* Helper class which gathers data at the end of the scope. One
 199  * instance of this one should be created at each execution of the
 200  * block. At the end of the block, it sends statistics to the static
 201  * PMProfStat object.
 202  */
 203 class PMProfInstance {
 204 public:
 205         PMProfInstance(PMProfStat * stat) : hit(true), stat_(stat)
 206         {
 207                 gettimeofday(&before_, 0);
 208         }
 209
 210         ~PMProfInstance() {
 211                 gettimeofday(&after_, 0);
 212                 stat_->add(after_.tv_sec - before_.tv_sec,
 213                            after_.tv_usec - before_.tv_usec, hit);
 214         }
 215
 216         bool hit;
 217
 218 private:
 219         timeval before_, after_;
 220         PMProfStat * stat_;
 221 };
 222
 223
 224 #define PROFILE_THIS_BLOCK(a) \
 225         static PMProfStat PMPS_##a(#a);\
 226         PMProfInstance PMPI_##a(&PMPS_##a);
 227
 228 #define PROFILE_CACHE_MISS(a) \
 229         PMPI_##a.hit = false;
 230
 231
 232 #endif