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 {
 125
 126 void dumpTime(std::chrono::duration<double> value)
 127 {
 128         double const val = value.count();
 129         std::cerr << std::fixed << std::setprecision(2);
 130         if (val >= 1.0)
 131                 std::cerr << val << " s";
 132         else if (val >= 0.001)
 133                 std::cerr << val * 1000 << " ms";
 134         else
 135                 std::cerr << val * 1000000 << " us";
 136 }
 137
 138 void dump(std::chrono::duration<double> total, unsigned long long count) {
 139         dumpTime(total / count);
 140         std::cerr << ", count=" << count
 141                           << ", total=";
 142         dumpTime(total);
 143         std::cerr << std::endl;
 144 }
 145
 146 } // namespace
 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), count_(0), miss_count_(0) {}
 158
 159         ~PMProfStat() {
 160                 if (count_>0) {
 161                         if (miss_count_ == 0) {
 162                                 std::cerr << "#pmprof# " << name_ << ": ";
 163                                 dump(dur_, count_);
 164                         }
 165                         else {
 166                                 std::cerr << "#pmprof# " << name_ << ": ";
 167                                 dump(dur_ + miss_dur_, count_ + miss_count_);
 168                                 std::cerr << "   hit: " << 100 * count_ / (count_ + miss_count_) << "%, ";
 169                                 dump(dur_, count_);
 170                                 std::cerr << "  miss: " << 100 * miss_count_ / (count_ + miss_count_) << "%, ";
 171                                 dump(miss_dur_, miss_count_);
 172                         }
 173                 }
 174         }
 175
 176         void add(std::chrono::duration<double> d, const bool hit) {
 177                 if (hit) {
 178                         dur_ += d;
 179                         count_++;
 180                 } else {
 181                         miss_dur_ += d;
 182                         miss_count_++;
 183                 }
 184         }
 185
 186 private:
 187         char const * name_;
 188         std::chrono::duration<double> dur_, miss_dur_;
 189         unsigned long long count_, miss_count_;
 190 };
 191
 192
 193 /* Helper class which gathers data at the end of the scope. One
 194  * instance of this one should be created at each execution of the
 195  * block. At the end of the block, it sends statistics to the static
 196  * PMProfStat object.
 197  */
 198 class PMProfInstance {
 199 public:
 200         PMProfInstance(PMProfStat * stat) : hit(true), stat_(stat)
 201         {
 202                 before_ = std::chrono::system_clock::now();
 203         }
 204
 205         ~PMProfInstance() {
 206                 stat_->add(std::chrono::system_clock::now() - before_, hit);
 207         }
 208
 209         bool hit;
 210
 211 private:
 212         std::chrono::system_clock::time_point before_;
 213         PMProfStat * stat_;
 214 };
 215
 216
 217 #define PROFILE_THIS_BLOCK(a) \
 218         static PMProfStat PMPS_##a(#a);\
 219         PMProfInstance PMPI_##a(&PMPS_##a);
 220
 221 #define PROFILE_CACHE_MISS(a) \
 222         PMPI_##a.hit = false;
 223
 224 #endif // !defined(DISABLE_PMPROF)
 225
 226 #endif