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 #include <chrono>
 116 #include <iomanip>
 117 #include <iostream>
 118
 119
 120 #if defined(__GNUG__) && defined(_GLIBCXX_DEBUG)
 121 #error Profiling is not usable when run-time debugging is in effect
 122 #endif
 123
 124 namespace _pmprof {
 125
 126 using namespace std;
 127 using namespace chrono;
 128
 129 namespace {
 130
 131 void dump_time(system_clock::duration value)
 132 {
 133         auto musec = duration_cast<microseconds>(value).count();
 134         cerr << fixed << setprecision(2);
 135         if (musec >= 1000000)
 136                 cerr << musec / 1000000.0 << " s";
 137         else if (musec >= 1000)
 138                 cerr << musec / 1000.0 << " ms";
 139         else
 140                 cerr << musec << " us";
 141 }
 142
 143 void dump(system_clock::duration total, unsigned long long count) {
 144         if (count > 0) {
 145                 dump_time(total / count);
 146                 cerr << ", count=" << count << ", total=";
 147                 dump_time(total);
 148         } else
 149                 std::cerr << "no data";
 150         cerr << endl;
 151 }
 152
 153 } // namespace
 154
 155
 156 /* Helper class for gathering data. Instantiate this as a static
 157  * variable, so that its destructor will be executed when the program
 158  * ends.
 159  */
 160 class stat {
 161 public:
 162         stat(char const * name) : name_(name) {}
 163
 164         ~stat() {
 165                 if (count_ + miss_count_ > 0) {
 166                         if (miss_count_ == 0) {
 167                                 cerr << "#pmprof# " << name_ << ": ";
 168                                 dump(dur_, count_);
 169                         }
 170                         else {
 171                                 cerr << "#pmprof# " << name_ << ": ";
 172                                 dump(dur_ + miss_dur_, count_ + miss_count_);
 173                                 cerr << "   hit: " << 100 * count_ / (count_ + miss_count_) << "%, ";
 174                                 dump(dur_, count_);
 175                                 cerr << "  miss: " << 100 * miss_count_ / (count_ + miss_count_) << "%, ";
 176                                 dump(miss_dur_, miss_count_);
 177                         }
 178                 } else
 179                         std::cerr << "#pmprof# " << name_ << ": no data" << std::endl;
 180         }
 181
 182         void add(system_clock::duration d, const bool hit) {
 183                 if (hit) {
 184                         dur_ += d;
 185                         count_++;
 186                 } else {
 187                         miss_dur_ += d;
 188                         miss_count_++;
 189                 }
 190         }
 191
 192 private:
 193         char const * name_;
 194         system_clock::duration dur_, miss_dur_;
 195         unsigned long long count_ = 0, miss_count_ = 0;
 196 };
 197
 198
 199 /* Helper class which gathers data at the end of the scope. One
 200  * instance of this one should be created at each execution of the
 201  * block. At the end of the block, it sends statistics to the static
 202  * stat object.
 203  */
 204 class instance {
 205 public:
 206         instance(stat * stat) : hit(true), stat_(stat)
 207         {
 208                 before_ = system_clock::now();
 209         }
 210
 211         ~instance() {
 212                 stat_->add(system_clock::now() - before_, hit);
 213         }
 214
 215         bool hit;
 216
 217 private:
 218         system_clock::time_point before_;
 219         stat * stat_;
 220 };
 221
 222 }
 223
 224 #define PROFILE_THIS_BLOCK(a) \
 225         static _pmprof::stat _pmps_##a(#a);     \
 226         _pmprof::instance _pmpi_##a(&_pmps_##a);
 227
 228 #define PROFILE_CACHE_MISS(a) \
 229         _pmpi_##a.hit = false;
 230
 231 #endif // !defined(DISABLE_PMPROF)
 232
 233 #endif