Skip to content
Permalink
Browse files

Feature: NewGRF callback profiling (#7868)

Adds a console command newgrf_profile to collect some profiling data about NewGRF action 2 callbacks and produce a CSV file.
  • Loading branch information
nielsmh committed Jan 26, 2020
1 parent f88ac83 commit c8779fb311c2665d3fc45c18b2f3460cd998d179
@@ -99,3 +99,43 @@ The following is an explanation of the different statistics:
If the frame rate window is shaded, the title bar will instead show just the
current simulation rate and the game speed factor.

## 3.0) NewGRF callback profiling

NewGRF developers can profile callback chains via the `newgrf_profile`
console command. The command controls a profiling mode where every sprite
request is measured and logged, and written to a CSV file in the end.

The NewGRF developer tools need to be enabled for the command to function.

View the syntax for the command in-game with the console command
`help newgrf_profile`.

Profiling only works during game or in the editor, it's not possible to
profile across the main menu, world generation, or loading savegames.

The CSV files contain one line per sprite request during the profiling.
They can get very large, especially on large games with many objects from
the GRF. Start profiling short periods such as 3 or 7 days, and watch the
file sizes.

The produced CSV file contains the following fields:

- *Tick* - Game tick counter, this may wrap to zero during recording.
Mainly useful to distinguish events from separate ticks.
- *Sprite* - Index of the root Action 2 sprite in the GRF file. This is
the sprite group being resolved.
- *Feature* - NewGRF feature number the sprite group is being resolved for.
This will be 0xFF for AI purchase selection and ambient sound callbacks.
- *Item* - The id of the item within the GRF. For cargotypes, railtypes,
roadtypes, and tramtypes, this is the integer representation of the label.
- *CallbackID* - The type of callback being resolved. ID 0 is regular graphics
lookup. See the `newgrf_callbacks.h` file in the OpenTTD source code for the
full list of callback IDs.
- *Microseconds* - Total time spent to resolve the Action 2, in microseconds.
- *Depth* - Number of recursive Action 2 lookups were made during resolution.
Value zero means the sprite group resolved directly.
- *Result* - Result of the callback resolution. For lookups that result in
a sprite, this is the index of the base action 2 in the GRF file. For
callbacks that give a numeric result, this is the callback result value.
For lookups that result in an industry production or tilelayout, this
is the sprite index of the action 2 defining the production/tilelayout.
@@ -583,6 +583,7 @@
<ClInclude Include="..\src\newgrf_industries.h" />
<ClInclude Include="..\src\newgrf_industrytiles.h" />
<ClInclude Include="..\src\newgrf_object.h" />
<ClInclude Include="..\src\newgrf_profiling.h" />
<ClInclude Include="..\src\newgrf_properties.h" />
<ClInclude Include="..\src\newgrf_railtype.h" />
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
<ClCompile Include="..\src\newgrf_industries.cpp" />
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
<ClCompile Include="..\src\newgrf_object.cpp" />
<ClCompile Include="..\src\newgrf_profiling.cpp" />
<ClCompile Include="..\src\newgrf_railtype.cpp" />
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
<ClCompile Include="..\src\newgrf_sound.cpp" />
@@ -837,6 +837,9 @@
<ClInclude Include="..\src\newgrf_object.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_profiling.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_properties.h">
<Filter>Header Files</Filter>
</ClInclude>
@@ -2796,6 +2799,9 @@
<ClCompile Include="..\src\newgrf_object.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_profiling.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_railtype.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
@@ -583,6 +583,7 @@
<ClInclude Include="..\src\newgrf_industries.h" />
<ClInclude Include="..\src\newgrf_industrytiles.h" />
<ClInclude Include="..\src\newgrf_object.h" />
<ClInclude Include="..\src\newgrf_profiling.h" />
<ClInclude Include="..\src\newgrf_properties.h" />
<ClInclude Include="..\src\newgrf_railtype.h" />
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
<ClCompile Include="..\src\newgrf_industries.cpp" />
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
<ClCompile Include="..\src\newgrf_object.cpp" />
<ClCompile Include="..\src\newgrf_profiling.cpp" />
<ClCompile Include="..\src\newgrf_railtype.cpp" />
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
<ClCompile Include="..\src\newgrf_sound.cpp" />
@@ -837,6 +837,9 @@
<ClInclude Include="..\src\newgrf_object.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_profiling.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_properties.h">
<Filter>Header Files</Filter>
</ClInclude>
@@ -2796,6 +2799,9 @@
<ClCompile Include="..\src\newgrf_object.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_profiling.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_railtype.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
@@ -583,6 +583,7 @@
<ClInclude Include="..\src\newgrf_industries.h" />
<ClInclude Include="..\src\newgrf_industrytiles.h" />
<ClInclude Include="..\src\newgrf_object.h" />
<ClInclude Include="..\src\newgrf_profiling.h" />
<ClInclude Include="..\src\newgrf_properties.h" />
<ClInclude Include="..\src\newgrf_railtype.h" />
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
<ClCompile Include="..\src\newgrf_industries.cpp" />
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
<ClCompile Include="..\src\newgrf_object.cpp" />
<ClCompile Include="..\src\newgrf_profiling.cpp" />
<ClCompile Include="..\src\newgrf_railtype.cpp" />
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
<ClCompile Include="..\src\newgrf_sound.cpp" />
@@ -837,6 +837,9 @@
<ClInclude Include="..\src\newgrf_object.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_profiling.h">
<Filter>Header Files</Filter>
</ClInclude>
<ClInclude Include="..\src\newgrf_properties.h">
<Filter>Header Files</Filter>
</ClInclude>
@@ -2796,6 +2799,9 @@
<ClCompile Include="..\src\newgrf_object.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_profiling.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
<ClCompile Include="..\src\newgrf_railtype.cpp">
<Filter>NewGRF</Filter>
</ClCompile>
@@ -270,6 +270,7 @@ newgrf_house.h
newgrf_industries.h
newgrf_industrytiles.h
newgrf_object.h
newgrf_profiling.h
newgrf_properties.h
newgrf_railtype.h
newgrf_roadtype.h
@@ -986,6 +987,7 @@ newgrf_house.cpp
newgrf_industries.cpp
newgrf_industrytiles.cpp
newgrf_object.cpp
newgrf_profiling.cpp
newgrf_railtype.cpp
newgrf_roadtype.cpp
newgrf_sound.cpp
@@ -33,6 +33,7 @@
#include "ai/ai.hpp"
#include "ai/ai_config.hpp"
#include "newgrf.h"
#include "newgrf_profiling.h"
#include "console_func.h"
#include "engine_base.h"
#include "game/game.hpp"
@@ -1877,6 +1878,135 @@ DEF_CONSOLE_CMD(ConNewGRFReload)
return true;
}

DEF_CONSOLE_CMD(ConNewGRFProfile)
{
if (argc == 0) {
IConsoleHelp("Collect performance data about NewGRF sprite requests and callbacks. Sub-commands can be abbreviated.");
IConsoleHelp("Usage: newgrf_profile [list]");
IConsoleHelp(" List all NewGRFs that can be profiled, and their status.");
IConsoleHelp("Usage: newgrf_profile select <grf-num>...");
IConsoleHelp(" Select one or more GRFs for profiling.");
IConsoleHelp("Usage: newgrf_profile unselect <grf-num>...");
IConsoleHelp(" Unselect one or more GRFs from profiling. Use the keyword \"all\" instead of a GRF number to unselect all. Removing an active profiler aborts data collection.");
IConsoleHelp("Usage: newgrf_profile start [<num-days>]");
IConsoleHelp(" Begin profiling all selected GRFs. If a number of days is provided, profiling stops after that many in-game days.");
IConsoleHelp("Usage: newgrf_profile stop");
IConsoleHelp(" End profiling and write the collected data to CSV files.");
IConsoleHelp("Usage: newgrf_profile abort");
IConsoleHelp(" End profiling and discard all collected data.");
return true;
}

extern const std::vector<GRFFile *> &GetAllGRFFiles();
const std::vector<GRFFile *> &files = GetAllGRFFiles();

/* "list" sub-command */
if (argc == 1 || strncasecmp(argv[1], "lis", 3) == 0) {
IConsolePrint(CC_INFO, "Loaded GRF files:");
int i = 1;
for (GRFFile *grf : files) {
auto profiler = std::find_if(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; });
bool selected = profiler != _newgrf_profilers.end();
bool active = selected && profiler->active;
TextColour tc = active ? TC_LIGHT_BLUE : selected ? TC_GREEN : CC_INFO;
const char *statustext = active ? " (active)" : selected ? " (selected)" : "";
IConsolePrintF(tc, "%d: [%08X] %s%s", i, BSWAP32(grf->grfid), grf->filename, statustext);
i++;
}
return true;
}

/* "select" sub-command */
if (strncasecmp(argv[1], "sel", 3) == 0 && argc >= 3) {
for (size_t argnum = 2; argnum < argc; ++argnum) {
int grfnum = atoi(argv[argnum]);
if (grfnum < 1 || grfnum > (int)files.size()) { // safe cast, files.size() should not be larger than a few hundred in the most extreme cases
IConsolePrintF(CC_WARNING, "GRF number %d out of range, not added.", grfnum);
continue;
}
GRFFile *grf = files[grfnum - 1];
if (std::any_of(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; })) {
IConsolePrintF(CC_WARNING, "GRF number %d [%08X] is already selected for profiling.", grfnum, BSWAP32(grf->grfid));
continue;
}
_newgrf_profilers.emplace_back(grf);
}
return true;
}

/* "unselect" sub-command */
if (strncasecmp(argv[1], "uns", 3) == 0 && argc >= 3) {
for (size_t argnum = 2; argnum < argc; ++argnum) {
if (strcasecmp(argv[argnum], "all") == 0) {
_newgrf_profilers.clear();
break;
}
int grfnum = atoi(argv[argnum]);
if (grfnum < 1 || grfnum > (int)files.size()) {
IConsolePrintF(CC_WARNING, "GRF number %d out of range, not removing.", grfnum);
continue;
}
GRFFile *grf = files[grfnum - 1];
auto pos = std::find_if(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; });
if (pos != _newgrf_profilers.end()) _newgrf_profilers.erase(pos);
}
return true;
}

/* "start" sub-command */
if (strncasecmp(argv[1], "sta", 3) == 0) {
std::string grfids;
size_t started = 0;
for (NewGRFProfiler &pr : _newgrf_profilers) {
if (!pr.active) {
pr.Start();
started++;

if (!grfids.empty()) grfids += ", ";
char grfidstr[12]{ 0 };
seprintf(grfidstr, lastof(grfidstr), "[%08X]", BSWAP32(pr.grffile->grfid));
grfids += grfidstr;
}
}
if (started > 0) {
IConsolePrintF(CC_DEBUG, "Started profiling for GRFID%s %s", (started > 1) ? "s" : "", grfids.c_str());
if (argc >= 3) {
int days = max(atoi(argv[2]), 1);
_newgrf_profile_end_date = _date + days;

char datestrbuf[32]{ 0 };
SetDParam(0, _newgrf_profile_end_date);
GetString(datestrbuf, STR_JUST_DATE_ISO, lastof(datestrbuf));
IConsolePrintF(CC_DEBUG, "Profiling will automatically stop on game date %s", datestrbuf);
} else {
_newgrf_profile_end_date = MAX_DAY;
}
} else if (_newgrf_profilers.empty()) {
IConsolePrintF(CC_WARNING, "No GRFs selected for profiling, did not start.");
} else {
IConsolePrintF(CC_WARNING, "Did not start profiling for any GRFs, all selected GRFs are already profiling.");
}
return true;
}

/* "stop" sub-command */
if (strncasecmp(argv[1], "sto", 3) == 0) {
NewGRFProfiler::FinishAll();
return true;
}

/* "abort" sub-command */
if (strncasecmp(argv[1], "abo", 3) == 0) {
for (NewGRFProfiler &pr : _newgrf_profilers) {
pr.Abort();
}
_newgrf_profile_end_date = MAX_DAY;
return true;
}

return false;
}

#ifdef _DEBUG
/******************
* debug commands
@@ -2056,4 +2186,5 @@ void IConsoleStdLibRegister()

/* NewGRF development stuff */
IConsoleCmdRegister("reload_newgrfs", ConNewGRFReload, ConHookNewGRFDeveloperTool);
IConsoleCmdRegister("newgrf_profile", ConNewGRFProfile, ConHookNewGRFDeveloperTool);
}
@@ -18,6 +18,7 @@
#include "rail_gui.h"
#include "linkgraph/linkgraph.h"
#include "saveload/saveload.h"
#include "newgrf_profiling.h"

#include "safeguards.h"

@@ -245,6 +246,10 @@ static void OnNewMonth()
*/
static void OnNewDay()
{
if (!_newgrf_profilers.empty() && _newgrf_profile_end_date <= _date) {
NewGRFProfiler::FinishAll();
}

if (_network_server) NetworkServerDailyLoop();

DisasterDailyLoop();
@@ -29,6 +29,7 @@
#include "station_kdtree.h"
#include "town_kdtree.h"
#include "viewport_kdtree.h"
#include "newgrf_profiling.h"

#include "safeguards.h"

@@ -69,6 +70,8 @@ void InitializeGame(uint size_x, uint size_y, bool reset_date, bool reset_settin
_thd.redsq = INVALID_TILE;
if (reset_settings) MakeNewgameSettingsLive();

_newgrf_profilers.clear();

if (reset_date) {
SetDate(ConvertYMDToDate(_settings_game.game_creation.starting_year, 0, 1), 0);
InitializeOldNames();

0 comments on commit c8779fb

Please sign in to comment.
You can’t perform that action at this time.