src/newgrf_profiling.cpp

   1 /*
   2  * This file is part of OpenTTD.
   3  * OpenTTD is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, version 2.
   4  * OpenTTD is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
   5  * See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with OpenTTD. If not, see <http://www.gnu.org/licenses/>.
   6  */
   7
   8  /** @file newgrf_profiling.cpp Profiling of NewGRF action 2 handling. */
   9
  10 #include "newgrf_profiling.h"
  11 #include "fileio_func.h"
  12 #include "string_func.h"
  13 #include "console_func.h"
  14 #include "spritecache.h"
  15 #include "3rdparty/fmt/chrono.h"
  16 #include "timer/timer.h"
  17 #include "timer/timer_game_tick.h"
  18
  19 #include <chrono>
  20
  21
  22 std::vector<NewGRFProfiler> _newgrf_profilers;
  23
  24
  25 /**
  26  * Create profiler object and begin profiling session.
  27  * @param grffile   The GRF file to collect profiling data on
  28  * @param end_date  Game date to end profiling on
  29  */
  30 NewGRFProfiler::NewGRFProfiler(const GRFFile *grffile) : grffile{ grffile }, active{ false }, cur_call{}
  31 {
  32 }
  33
  34 /**
  35  * Complete profiling session and write data to file
  36  */
  37 NewGRFProfiler::~NewGRFProfiler()
  38 {
  39 }
  40
  41 /**
  42  * Capture the start of a sprite group resolution.
  43  * @param resolver  Data about sprite group being resolved
  44  */
  45 void NewGRFProfiler::BeginResolve(const ResolverObject &resolver)
  46 {
  47         using namespace std::chrono;
  48         this->cur_call.root_sprite = resolver.root_spritegroup->nfo_line;
  49         this->cur_call.subs = 0;
  50         this->cur_call.time = (uint32_t)time_point_cast<microseconds>(high_resolution_clock::now()).time_since_epoch().count();
  51         this->cur_call.tick = TimerGameTick::counter;
  52         this->cur_call.cb = resolver.callback;
  53         this->cur_call.feat = resolver.GetFeature();
  54         this->cur_call.item = resolver.GetDebugID();
  55 }
  56
  57 /**
  58  * Capture the completion of a sprite group resolution.
  59  */
  60 void NewGRFProfiler::EndResolve(const SpriteGroup *result)
  61 {
  62         using namespace std::chrono;
  63         this->cur_call.time = (uint32_t)time_point_cast<microseconds>(high_resolution_clock::now()).time_since_epoch().count() - this->cur_call.time;
  64
  65         if (result == nullptr) {
  66                 this->cur_call.result = 0;
  67         } else if (result->type == SGT_CALLBACK) {
  68                 this->cur_call.result = static_cast<const CallbackResultSpriteGroup *>(result)->result;
  69         } else if (result->type == SGT_RESULT) {
  70                 this->cur_call.result = GetSpriteLocalID(static_cast<const ResultSpriteGroup *>(result)->sprite);
  71         } else {
  72                 this->cur_call.result = result->nfo_line;
  73         }
  74
  75         this->calls.push_back(this->cur_call);
  76 }
  77
  78 /**
  79  * Capture a recursive sprite group resolution.
  80  */
  81 void NewGRFProfiler::RecursiveResolve()
  82 {
  83         this->cur_call.subs += 1;
  84 }
  85
  86 void NewGRFProfiler::Start()
  87 {
  88         this->Abort();
  89         this->active = true;
  90         this->start_tick = TimerGameTick::counter;
  91 }
  92
  93 uint32_t NewGRFProfiler::Finish()
  94 {
  95         if (!this->active) return 0;
  96
  97         if (this->calls.empty()) {
  98                 IConsolePrint(CC_DEBUG, "Finished profile of NewGRF [{:08X}], no events collected, not writing a file.", BSWAP32(this->grffile->grfid));
  99
 100                 this->Abort();
 101                 return 0;
 102         }
 103
 104         std::string filename = this->GetOutputFilename();
 105         IConsolePrint(CC_DEBUG, "Finished profile of NewGRF [{:08X}], writing {} events to '{}'.", BSWAP32(this->grffile->grfid), this->calls.size(), filename);
 106
 107         uint32_t total_microseconds = 0;
 108
 109         auto f = FioFOpenFile(filename, "wt", Subdirectory::NO_DIRECTORY);
 110
 111         if (!f.has_value()) {
 112                 IConsolePrint(CC_ERROR, "Failed to open '{}' for writing.", filename);
 113         } else {
 114                 fmt::print(*f, "Tick,Sprite,Feature,Item,CallbackID,Microseconds,Depth,Result\n");
 115                 for (const Call &c : this->calls) {
 116                         fmt::print(*f, "{},{},{:#X},{},{:#X},{},{},{}\n", c.tick, c.root_sprite, c.feat, c.item, (uint)c.cb, c.time, c.subs, c.result);
 117                         total_microseconds += c.time;
 118                 }
 119         }
 120
 121         this->Abort();
 122         return total_microseconds;
 123 }
 124
 125 void NewGRFProfiler::Abort()
 126 {
 127         this->active = false;
 128         this->calls.clear();
 129 }
 130
 131 /**
 132  * Get name of the file that will be written.
 133  * @return File name of profiling output file.
 134  */
 135 std::string NewGRFProfiler::GetOutputFilename() const
 136 {
 137         return fmt::format("{}grfprofile-{:%Y%m%d-%H%M}-{:08X}.csv", FiosGetScreenshotDir(), fmt::localtime(time(nullptr)), BSWAP32(this->grffile->grfid));
 138 }
 139
 140 /* static */ uint32_t NewGRFProfiler::FinishAll()
 141 {
 142         NewGRFProfiler::AbortTimer();
 143
 144         uint64_t max_ticks = 0;
 145         uint32_t total_microseconds = 0;
 146         for (NewGRFProfiler &pr : _newgrf_profilers) {
 147                 if (pr.active) {
 148                         total_microseconds += pr.Finish();
 149                         max_ticks = std::max(max_ticks, TimerGameTick::counter - pr.start_tick);
 150                 }
 151         }
 152
 153         if (total_microseconds > 0 && max_ticks > 0) {
 154                 IConsolePrint(CC_DEBUG, "Total NewGRF callback processing: {} microseconds over {} ticks.", total_microseconds, max_ticks);
 155         }
 156
 157         return total_microseconds;
 158 }
 159
 160 /**
 161  * Check whether profiling is active and should be finished.
 162  */
 163 static TimeoutTimer<TimerGameTick> _profiling_finish_timeout({ TimerGameTick::Priority::NONE, 0 }, []()
 164 {
 165         NewGRFProfiler::FinishAll();
 166 });
 167
 168 /**
 169  * Start the timeout timer that will finish all profiling sessions.
 170  */
 171 /* static */ void NewGRFProfiler::StartTimer(uint64_t ticks)
 172 {
 173         _profiling_finish_timeout.Reset({ TimerGameTick::Priority::NONE, static_cast<uint>(ticks) });
 174 }
 175
 176 /**
 177  * Abort the timeout timer, so the timer callback is never called.
 178  */
 179 /* static */ void NewGRFProfiler::AbortTimer()
 180 {
 181         _profiling_finish_timeout.Abort();
 182 }