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 dump(long long sec, long long usec, unsigned long long count) {
 149         double const total = sec * 1000000 + usec;
 150         std::cerr << std::fixed << std::setprecision(2)
 151                           << total / count
 152                           << "usec, count=" << count
 153                           << ", total=" << total * 0.001 << "msec"
 154                           << std::endl;
 155 }
 156
 157 } // namespace
 158
 159
 160 /* Helper class for gathering data. Instantiate this as a static
 161  * variable, so that its destructor will be executed when the program
 162  * ends.
 163  */
 164
 165
 166 class PMProfStat {
 167 public:
 168         PMProfStat(char const * name) : name_(name), sec_(0), usec_(0), count_(0),
 169                                     miss_sec_(0), miss_usec_(0), miss_count_(0) {}
 170
 171         ~PMProfStat() {
 172                 if (count_>0) {
 173                         if (miss_count_ == 0) {
 174                                 std::cerr << "#pmprof# " << name_ << ": ";
 175                                 dump(sec_, usec_, count_);
 176                         }
 177                         else {
 178                                 std::cerr << "#pmprof# " << name_ << ": ";
 179                                 dump(sec_ + miss_sec_, usec_ + miss_usec_, count_ + miss_count_);
 180                                 std::cerr << "   hit: " << 100 * count_ / (count_ + miss_count_) << "%, ";
 181                                 dump(sec_, usec_, count_);
 182                                 std::cerr << "  miss: " << 100 * miss_count_ / (count_ + miss_count_) << "%, ";
 183                                 dump(miss_sec_, miss_usec_, miss_count_);
 184                         }
 185                 }
 186         }
 187
 188         void add(const long long s, const long long u, const bool hit) {
 189                 if (hit) {
 190                         sec_ += s;
 191                         usec_ += u;
 192                         count_++;
 193                 } else {
 194                         miss_sec_ += s;
 195                         miss_usec_ += u;
 196                         miss_count_++;
 197                 }
 198         }
 199
 200 private:
 201         char const * name_;
 202         long long sec_, usec_;
 203         unsigned long long count_;
 204         long long miss_sec_, miss_usec_;
 205         unsigned long long miss_count_;
 206 };
 207
 208
 209 /* Helper class which gathers data at the end of the scope. One
 210  * instance of this one should be created at each execution of the
 211  * block. At the end of the block, it sends statistics to the static
 212  * PMProfStat object.
 213  */
 214 class PMProfInstance {
 215 public:
 216         PMProfInstance(PMProfStat * stat) : hit(true), stat_(stat)
 217         {
 218                 gettimeofday(&before_, 0);
 219         }
 220
 221         ~PMProfInstance() {
 222                 gettimeofday(&after_, 0);
 223                 stat_->add(after_.tv_sec - before_.tv_sec,
 224                            after_.tv_usec - before_.tv_usec, hit);
 225         }
 226
 227         bool hit;
 228
 229 private:
 230         timeval before_, after_;
 231         PMProfStat * stat_;
 232 };
 233
 234
 235 #define PROFILE_THIS_BLOCK(a) \
 236         static PMProfStat PMPS_##a(#a);\
 237         PMProfInstance PMPI_##a(&PMPS_##a);
 238
 239 #define PROFILE_CACHE_MISS(a) \
 240         PMPI_##a.hit = false;
 241
 242 #endif // !defined(DISABLE_PMPROF)
 243
 244 #endif