Skip to content

Commit c8779fb

Browse files
authored
Feature: NewGRF callback profiling (OpenTTD#7868)
Adds a console command newgrf_profile to collect some profiling data about NewGRF action 2 callbacks and produce a CSV file.
1 parent f88ac83 commit c8779fb

40 files changed

+691
-20
lines changed

docs/logging_and_performance_metrics.md

+40
Original file line numberDiff line numberDiff line change
@@ -99,3 +99,43 @@ The following is an explanation of the different statistics:
9999
If the frame rate window is shaded, the title bar will instead show just the
100100
current simulation rate and the game speed factor.
101101

102+
## 3.0) NewGRF callback profiling
103+
104+
NewGRF developers can profile callback chains via the `newgrf_profile`
105+
console command. The command controls a profiling mode where every sprite
106+
request is measured and logged, and written to a CSV file in the end.
107+
108+
The NewGRF developer tools need to be enabled for the command to function.
109+
110+
View the syntax for the command in-game with the console command
111+
`help newgrf_profile`.
112+
113+
Profiling only works during game or in the editor, it's not possible to
114+
profile across the main menu, world generation, or loading savegames.
115+
116+
The CSV files contain one line per sprite request during the profiling.
117+
They can get very large, especially on large games with many objects from
118+
the GRF. Start profiling short periods such as 3 or 7 days, and watch the
119+
file sizes.
120+
121+
The produced CSV file contains the following fields:
122+
123+
- *Tick* - Game tick counter, this may wrap to zero during recording.
124+
Mainly useful to distinguish events from separate ticks.
125+
- *Sprite* - Index of the root Action 2 sprite in the GRF file. This is
126+
the sprite group being resolved.
127+
- *Feature* - NewGRF feature number the sprite group is being resolved for.
128+
This will be 0xFF for AI purchase selection and ambient sound callbacks.
129+
- *Item* - The id of the item within the GRF. For cargotypes, railtypes,
130+
roadtypes, and tramtypes, this is the integer representation of the label.
131+
- *CallbackID* - The type of callback being resolved. ID 0 is regular graphics
132+
lookup. See the `newgrf_callbacks.h` file in the OpenTTD source code for the
133+
full list of callback IDs.
134+
- *Microseconds* - Total time spent to resolve the Action 2, in microseconds.
135+
- *Depth* - Number of recursive Action 2 lookups were made during resolution.
136+
Value zero means the sprite group resolved directly.
137+
- *Result* - Result of the callback resolution. For lookups that result in
138+
a sprite, this is the index of the base action 2 in the GRF file. For
139+
callbacks that give a numeric result, this is the callback result value.
140+
For lookups that result in an industry production or tilelayout, this
141+
is the sprite index of the action 2 defining the production/tilelayout.

projects/openttd_vs140.vcxproj

+2
Original file line numberDiff line numberDiff line change
@@ -583,6 +583,7 @@
583583
<ClInclude Include="..\src\newgrf_industries.h" />
584584
<ClInclude Include="..\src\newgrf_industrytiles.h" />
585585
<ClInclude Include="..\src\newgrf_object.h" />
586+
<ClInclude Include="..\src\newgrf_profiling.h" />
586587
<ClInclude Include="..\src\newgrf_properties.h" />
587588
<ClInclude Include="..\src\newgrf_railtype.h" />
588589
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
12361237
<ClCompile Include="..\src\newgrf_industries.cpp" />
12371238
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
12381239
<ClCompile Include="..\src\newgrf_object.cpp" />
1240+
<ClCompile Include="..\src\newgrf_profiling.cpp" />
12391241
<ClCompile Include="..\src\newgrf_railtype.cpp" />
12401242
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
12411243
<ClCompile Include="..\src\newgrf_sound.cpp" />

projects/openttd_vs140.vcxproj.filters

+6
Original file line numberDiff line numberDiff line change
@@ -837,6 +837,9 @@
837837
<ClInclude Include="..\src\newgrf_object.h">
838838
<Filter>Header Files</Filter>
839839
</ClInclude>
840+
<ClInclude Include="..\src\newgrf_profiling.h">
841+
<Filter>Header Files</Filter>
842+
</ClInclude>
840843
<ClInclude Include="..\src\newgrf_properties.h">
841844
<Filter>Header Files</Filter>
842845
</ClInclude>
@@ -2796,6 +2799,9 @@
27962799
<ClCompile Include="..\src\newgrf_object.cpp">
27972800
<Filter>NewGRF</Filter>
27982801
</ClCompile>
2802+
<ClCompile Include="..\src\newgrf_profiling.cpp">
2803+
<Filter>NewGRF</Filter>
2804+
</ClCompile>
27992805
<ClCompile Include="..\src\newgrf_railtype.cpp">
28002806
<Filter>NewGRF</Filter>
28012807
</ClCompile>

projects/openttd_vs141.vcxproj

+2
Original file line numberDiff line numberDiff line change
@@ -583,6 +583,7 @@
583583
<ClInclude Include="..\src\newgrf_industries.h" />
584584
<ClInclude Include="..\src\newgrf_industrytiles.h" />
585585
<ClInclude Include="..\src\newgrf_object.h" />
586+
<ClInclude Include="..\src\newgrf_profiling.h" />
586587
<ClInclude Include="..\src\newgrf_properties.h" />
587588
<ClInclude Include="..\src\newgrf_railtype.h" />
588589
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
12361237
<ClCompile Include="..\src\newgrf_industries.cpp" />
12371238
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
12381239
<ClCompile Include="..\src\newgrf_object.cpp" />
1240+
<ClCompile Include="..\src\newgrf_profiling.cpp" />
12391241
<ClCompile Include="..\src\newgrf_railtype.cpp" />
12401242
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
12411243
<ClCompile Include="..\src\newgrf_sound.cpp" />

projects/openttd_vs141.vcxproj.filters

+6
Original file line numberDiff line numberDiff line change
@@ -837,6 +837,9 @@
837837
<ClInclude Include="..\src\newgrf_object.h">
838838
<Filter>Header Files</Filter>
839839
</ClInclude>
840+
<ClInclude Include="..\src\newgrf_profiling.h">
841+
<Filter>Header Files</Filter>
842+
</ClInclude>
840843
<ClInclude Include="..\src\newgrf_properties.h">
841844
<Filter>Header Files</Filter>
842845
</ClInclude>
@@ -2796,6 +2799,9 @@
27962799
<ClCompile Include="..\src\newgrf_object.cpp">
27972800
<Filter>NewGRF</Filter>
27982801
</ClCompile>
2802+
<ClCompile Include="..\src\newgrf_profiling.cpp">
2803+
<Filter>NewGRF</Filter>
2804+
</ClCompile>
27992805
<ClCompile Include="..\src\newgrf_railtype.cpp">
28002806
<Filter>NewGRF</Filter>
28012807
</ClCompile>

projects/openttd_vs142.vcxproj

+2
Original file line numberDiff line numberDiff line change
@@ -583,6 +583,7 @@
583583
<ClInclude Include="..\src\newgrf_industries.h" />
584584
<ClInclude Include="..\src\newgrf_industrytiles.h" />
585585
<ClInclude Include="..\src\newgrf_object.h" />
586+
<ClInclude Include="..\src\newgrf_profiling.h" />
586587
<ClInclude Include="..\src\newgrf_properties.h" />
587588
<ClInclude Include="..\src\newgrf_railtype.h" />
588589
<ClInclude Include="..\src\newgrf_roadtype.h" />
@@ -1236,6 +1237,7 @@
12361237
<ClCompile Include="..\src\newgrf_industries.cpp" />
12371238
<ClCompile Include="..\src\newgrf_industrytiles.cpp" />
12381239
<ClCompile Include="..\src\newgrf_object.cpp" />
1240+
<ClCompile Include="..\src\newgrf_profiling.cpp" />
12391241
<ClCompile Include="..\src\newgrf_railtype.cpp" />
12401242
<ClCompile Include="..\src\newgrf_roadtype.cpp" />
12411243
<ClCompile Include="..\src\newgrf_sound.cpp" />

projects/openttd_vs142.vcxproj.filters

+6
Original file line numberDiff line numberDiff line change
@@ -837,6 +837,9 @@
837837
<ClInclude Include="..\src\newgrf_object.h">
838838
<Filter>Header Files</Filter>
839839
</ClInclude>
840+
<ClInclude Include="..\src\newgrf_profiling.h">
841+
<Filter>Header Files</Filter>
842+
</ClInclude>
840843
<ClInclude Include="..\src\newgrf_properties.h">
841844
<Filter>Header Files</Filter>
842845
</ClInclude>
@@ -2796,6 +2799,9 @@
27962799
<ClCompile Include="..\src\newgrf_object.cpp">
27972800
<Filter>NewGRF</Filter>
27982801
</ClCompile>
2802+
<ClCompile Include="..\src\newgrf_profiling.cpp">
2803+
<Filter>NewGRF</Filter>
2804+
</ClCompile>
27992805
<ClCompile Include="..\src\newgrf_railtype.cpp">
28002806
<Filter>NewGRF</Filter>
28012807
</ClCompile>

source.list

+2
Original file line numberDiff line numberDiff line change
@@ -270,6 +270,7 @@ newgrf_house.h
270270
newgrf_industries.h
271271
newgrf_industrytiles.h
272272
newgrf_object.h
273+
newgrf_profiling.h
273274
newgrf_properties.h
274275
newgrf_railtype.h
275276
newgrf_roadtype.h
@@ -986,6 +987,7 @@ newgrf_house.cpp
986987
newgrf_industries.cpp
987988
newgrf_industrytiles.cpp
988989
newgrf_object.cpp
990+
newgrf_profiling.cpp
989991
newgrf_railtype.cpp
990992
newgrf_roadtype.cpp
991993
newgrf_sound.cpp

src/console_cmds.cpp

+131
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@
3333
#include "ai/ai.hpp"
3434
#include "ai/ai_config.hpp"
3535
#include "newgrf.h"
36+
#include "newgrf_profiling.h"
3637
#include "console_func.h"
3738
#include "engine_base.h"
3839
#include "game/game.hpp"
@@ -1877,6 +1878,135 @@ DEF_CONSOLE_CMD(ConNewGRFReload)
18771878
return true;
18781879
}
18791880

1881+
DEF_CONSOLE_CMD(ConNewGRFProfile)
1882+
{
1883+
if (argc == 0) {
1884+
IConsoleHelp("Collect performance data about NewGRF sprite requests and callbacks. Sub-commands can be abbreviated.");
1885+
IConsoleHelp("Usage: newgrf_profile [list]");
1886+
IConsoleHelp(" List all NewGRFs that can be profiled, and their status.");
1887+
IConsoleHelp("Usage: newgrf_profile select <grf-num>...");
1888+
IConsoleHelp(" Select one or more GRFs for profiling.");
1889+
IConsoleHelp("Usage: newgrf_profile unselect <grf-num>...");
1890+
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.");
1891+
IConsoleHelp("Usage: newgrf_profile start [<num-days>]");
1892+
IConsoleHelp(" Begin profiling all selected GRFs. If a number of days is provided, profiling stops after that many in-game days.");
1893+
IConsoleHelp("Usage: newgrf_profile stop");
1894+
IConsoleHelp(" End profiling and write the collected data to CSV files.");
1895+
IConsoleHelp("Usage: newgrf_profile abort");
1896+
IConsoleHelp(" End profiling and discard all collected data.");
1897+
return true;
1898+
}
1899+
1900+
extern const std::vector<GRFFile *> &GetAllGRFFiles();
1901+
const std::vector<GRFFile *> &files = GetAllGRFFiles();
1902+
1903+
/* "list" sub-command */
1904+
if (argc == 1 || strncasecmp(argv[1], "lis", 3) == 0) {
1905+
IConsolePrint(CC_INFO, "Loaded GRF files:");
1906+
int i = 1;
1907+
for (GRFFile *grf : files) {
1908+
auto profiler = std::find_if(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; });
1909+
bool selected = profiler != _newgrf_profilers.end();
1910+
bool active = selected && profiler->active;
1911+
TextColour tc = active ? TC_LIGHT_BLUE : selected ? TC_GREEN : CC_INFO;
1912+
const char *statustext = active ? " (active)" : selected ? " (selected)" : "";
1913+
IConsolePrintF(tc, "%d: [%08X] %s%s", i, BSWAP32(grf->grfid), grf->filename, statustext);
1914+
i++;
1915+
}
1916+
return true;
1917+
}
1918+
1919+
/* "select" sub-command */
1920+
if (strncasecmp(argv[1], "sel", 3) == 0 && argc >= 3) {
1921+
for (size_t argnum = 2; argnum < argc; ++argnum) {
1922+
int grfnum = atoi(argv[argnum]);
1923+
if (grfnum < 1 || grfnum > (int)files.size()) { // safe cast, files.size() should not be larger than a few hundred in the most extreme cases
1924+
IConsolePrintF(CC_WARNING, "GRF number %d out of range, not added.", grfnum);
1925+
continue;
1926+
}
1927+
GRFFile *grf = files[grfnum - 1];
1928+
if (std::any_of(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; })) {
1929+
IConsolePrintF(CC_WARNING, "GRF number %d [%08X] is already selected for profiling.", grfnum, BSWAP32(grf->grfid));
1930+
continue;
1931+
}
1932+
_newgrf_profilers.emplace_back(grf);
1933+
}
1934+
return true;
1935+
}
1936+
1937+
/* "unselect" sub-command */
1938+
if (strncasecmp(argv[1], "uns", 3) == 0 && argc >= 3) {
1939+
for (size_t argnum = 2; argnum < argc; ++argnum) {
1940+
if (strcasecmp(argv[argnum], "all") == 0) {
1941+
_newgrf_profilers.clear();
1942+
break;
1943+
}
1944+
int grfnum = atoi(argv[argnum]);
1945+
if (grfnum < 1 || grfnum > (int)files.size()) {
1946+
IConsolePrintF(CC_WARNING, "GRF number %d out of range, not removing.", grfnum);
1947+
continue;
1948+
}
1949+
GRFFile *grf = files[grfnum - 1];
1950+
auto pos = std::find_if(_newgrf_profilers.begin(), _newgrf_profilers.end(), [&](NewGRFProfiler &pr) { return pr.grffile == grf; });
1951+
if (pos != _newgrf_profilers.end()) _newgrf_profilers.erase(pos);
1952+
}
1953+
return true;
1954+
}
1955+
1956+
/* "start" sub-command */
1957+
if (strncasecmp(argv[1], "sta", 3) == 0) {
1958+
std::string grfids;
1959+
size_t started = 0;
1960+
for (NewGRFProfiler &pr : _newgrf_profilers) {
1961+
if (!pr.active) {
1962+
pr.Start();
1963+
started++;
1964+
1965+
if (!grfids.empty()) grfids += ", ";
1966+
char grfidstr[12]{ 0 };
1967+
seprintf(grfidstr, lastof(grfidstr), "[%08X]", BSWAP32(pr.grffile->grfid));
1968+
grfids += grfidstr;
1969+
}
1970+
}
1971+
if (started > 0) {
1972+
IConsolePrintF(CC_DEBUG, "Started profiling for GRFID%s %s", (started > 1) ? "s" : "", grfids.c_str());
1973+
if (argc >= 3) {
1974+
int days = max(atoi(argv[2]), 1);
1975+
_newgrf_profile_end_date = _date + days;
1976+
1977+
char datestrbuf[32]{ 0 };
1978+
SetDParam(0, _newgrf_profile_end_date);
1979+
GetString(datestrbuf, STR_JUST_DATE_ISO, lastof(datestrbuf));
1980+
IConsolePrintF(CC_DEBUG, "Profiling will automatically stop on game date %s", datestrbuf);
1981+
} else {
1982+
_newgrf_profile_end_date = MAX_DAY;
1983+
}
1984+
} else if (_newgrf_profilers.empty()) {
1985+
IConsolePrintF(CC_WARNING, "No GRFs selected for profiling, did not start.");
1986+
} else {
1987+
IConsolePrintF(CC_WARNING, "Did not start profiling for any GRFs, all selected GRFs are already profiling.");
1988+
}
1989+
return true;
1990+
}
1991+
1992+
/* "stop" sub-command */
1993+
if (strncasecmp(argv[1], "sto", 3) == 0) {
1994+
NewGRFProfiler::FinishAll();
1995+
return true;
1996+
}
1997+
1998+
/* "abort" sub-command */
1999+
if (strncasecmp(argv[1], "abo", 3) == 0) {
2000+
for (NewGRFProfiler &pr : _newgrf_profilers) {
2001+
pr.Abort();
2002+
}
2003+
_newgrf_profile_end_date = MAX_DAY;
2004+
return true;
2005+
}
2006+
2007+
return false;
2008+
}
2009+
18802010
#ifdef _DEBUG
18812011
/******************
18822012
* debug commands
@@ -2056,4 +2186,5 @@ void IConsoleStdLibRegister()
20562186

20572187
/* NewGRF development stuff */
20582188
IConsoleCmdRegister("reload_newgrfs", ConNewGRFReload, ConHookNewGRFDeveloperTool);
2189+
IConsoleCmdRegister("newgrf_profile", ConNewGRFProfile, ConHookNewGRFDeveloperTool);
20592190
}

src/date.cpp

+5
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
#include "rail_gui.h"
1919
#include "linkgraph/linkgraph.h"
2020
#include "saveload/saveload.h"
21+
#include "newgrf_profiling.h"
2122

2223
#include "safeguards.h"
2324

@@ -245,6 +246,10 @@ static void OnNewMonth()
245246
*/
246247
static void OnNewDay()
247248
{
249+
if (!_newgrf_profilers.empty() && _newgrf_profile_end_date <= _date) {
250+
NewGRFProfiler::FinishAll();
251+
}
252+
248253
if (_network_server) NetworkServerDailyLoop();
249254

250255
DisasterDailyLoop();

src/misc.cpp

+3
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929
#include "station_kdtree.h"
3030
#include "town_kdtree.h"
3131
#include "viewport_kdtree.h"
32+
#include "newgrf_profiling.h"
3233

3334
#include "safeguards.h"
3435

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

73+
_newgrf_profilers.clear();
74+
7275
if (reset_date) {
7376
SetDate(ConvertYMDToDate(_settings_game.game_creation.starting_year, 0, 1), 0);
7477
InitializeOldNames();

0 commit comments

Comments
 (0)