/* * This file is part of OpenTTD. * 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. * 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. * 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 . */ /** @file newgrf_profiling.cpp Profiling of NewGRF action 2 handling. */ #include "newgrf_profiling.h" #include "fileio_func.h" #include "string_func.h" #include "console_func.h" #include "spritecache.h" #include "3rdparty/fmt/chrono.h" #include "timer/timer.h" #include "timer/timer_game_tick.h" #include std::vector _newgrf_profilers; /** * Create profiler object and begin profiling session. * @param grffile The GRF file to collect profiling data on * @param end_date Game date to end profiling on */ NewGRFProfiler::NewGRFProfiler(const GRFFile *grffile) : grffile{ grffile }, active{ false }, cur_call{} { } /** * Complete profiling session and write data to file */ NewGRFProfiler::~NewGRFProfiler() { } /** * Capture the start of a sprite group resolution. * @param resolver Data about sprite group being resolved */ void NewGRFProfiler::BeginResolve(const ResolverObject &resolver) { using namespace std::chrono; this->cur_call.root_sprite = resolver.root_spritegroup->nfo_line; this->cur_call.subs = 0; this->cur_call.time = (uint32_t)time_point_cast(high_resolution_clock::now()).time_since_epoch().count(); this->cur_call.tick = TimerGameTick::counter; this->cur_call.cb = resolver.callback; this->cur_call.feat = resolver.GetFeature(); this->cur_call.item = resolver.GetDebugID(); } /** * Capture the completion of a sprite group resolution. */ void NewGRFProfiler::EndResolve(const SpriteGroup *result) { using namespace std::chrono; this->cur_call.time = (uint32_t)time_point_cast(high_resolution_clock::now()).time_since_epoch().count() - this->cur_call.time; if (result == nullptr) { this->cur_call.result = 0; } else if (result->type == SGT_CALLBACK) { this->cur_call.result = static_cast(result)->result; } else if (result->type == SGT_RESULT) { this->cur_call.result = GetSpriteLocalID(static_cast(result)->sprite); } else { this->cur_call.result = result->nfo_line; } this->calls.push_back(this->cur_call); } /** * Capture a recursive sprite group resolution. */ void NewGRFProfiler::RecursiveResolve() { this->cur_call.subs += 1; } void NewGRFProfiler::Start() { this->Abort(); this->active = true; this->start_tick = TimerGameTick::counter; } uint32_t NewGRFProfiler::Finish() { if (!this->active) return 0; if (this->calls.empty()) { IConsolePrint(CC_DEBUG, "Finished profile of NewGRF [{:08X}], no events collected, not writing a file.", BSWAP32(this->grffile->grfid)); this->Abort(); return 0; } std::string filename = this->GetOutputFilename(); IConsolePrint(CC_DEBUG, "Finished profile of NewGRF [{:08X}], writing {} events to '{}'.", BSWAP32(this->grffile->grfid), this->calls.size(), filename); FILE *f = FioFOpenFile(filename, "wt", Subdirectory::NO_DIRECTORY); FileCloser fcloser(f); uint32_t total_microseconds = 0; fmt::print(f, "Tick,Sprite,Feature,Item,CallbackID,Microseconds,Depth,Result\n"); for (const Call &c : this->calls) { fmt::print(f, "{},{},{:#X},{},{:#X},{},{},{}\n", c.tick, c.root_sprite, c.feat, c.item, (uint)c.cb, c.time, c.subs, c.result); total_microseconds += c.time; } this->Abort(); return total_microseconds; } void NewGRFProfiler::Abort() { this->active = false; this->calls.clear(); } /** * Get name of the file that will be written. * @return File name of profiling output file. */ std::string NewGRFProfiler::GetOutputFilename() const { return fmt::format("{}grfprofile-{:%Y%m%d-%H%M}-{:08X}.csv", FiosGetScreenshotDir(), fmt::localtime(time(nullptr)), BSWAP32(this->grffile->grfid)); } /* static */ uint32_t NewGRFProfiler::FinishAll() { NewGRFProfiler::AbortTimer(); uint64_t max_ticks = 0; uint32_t total_microseconds = 0; for (NewGRFProfiler &pr : _newgrf_profilers) { if (pr.active) { total_microseconds += pr.Finish(); max_ticks = std::max(max_ticks, TimerGameTick::counter - pr.start_tick); } } if (total_microseconds > 0 && max_ticks > 0) { IConsolePrint(CC_DEBUG, "Total NewGRF callback processing: {} microseconds over {} ticks.", total_microseconds, max_ticks); } return total_microseconds; } /** * Check whether profiling is active and should be finished. */ static TimeoutTimer _profiling_finish_timeout({ TimerGameTick::Priority::NONE, 0 }, []() { NewGRFProfiler::FinishAll(); }); /** * Start the timeout timer that will finish all profiling sessions. */ /* static */ void NewGRFProfiler::StartTimer(uint64_t ticks) { _profiling_finish_timeout.Reset({ TimerGameTick::Priority::NONE, static_cast(ticks) }); } /** * Abort the timeout timer, so the timer callback is never called. */ /* static */ void NewGRFProfiler::AbortTimer() { _profiling_finish_timeout.Abort(); }