OpenTTD-patches/docs/logging_and_performance_metrics.md

Logging, frame rate and performance metrics

1.0) Logging of potentially dangerous actions

OpenTTD is a complex program, and together with NewGRF, it may show a buggy behaviour. But not only bugs in code can cause problems. There are several ways to affect game state possibly resulting in program crash or multiplayer desyncs.

Easier way would be to forbid all these unsafe actions, but that would affect game usability for many players. We certainly do not want that. However, we receive bug reports because of this. To reduce time spent with solving these problems, these potentially unsafe actions are logged in the savegame (including crash.sav). Log is stored in crash logs, too.

Information logged:

• Adding / removing / changing order of NewGRFs
• Changing NewGRF parameters, loading compatible NewGRF
• Changing game mode (scenario editor <-> normal game)
• Loading game saved in a different OpenTTD / TTDPatch / Transport Tycoon Deluxe / original Transport Tycoon version
• Running a modified OpenTTD build
• Changing settings affecting NewGRF behaviour (non-network-safe settings)
• Triggering NewGRF bugs

No personal information is stored.

You can show the game log by typing 'gamelog' in the console or by running OpenTTD in debug mode.

2.0) Frame rate and performance metrics

The Help menu in-game has a function to open the Frame rate window. This window shows various real-time performance statistics, measuring what parts of the game require the most processing power currently.

A summary of the statistics can also be retrieved from the console with the fps command. This is especially useful on dedicated servers, where the administrator might want to determine what's limiting performance in a slow game.

The frame rate is given as two figures, the simulation rate and the graphics frame rate. Usually these are identical, as the screen is rendered exactly once per simulated tick, but in the future there might be support for graphics and simulation running at different rates. When the game is paused, the simulation rate drops to zero.

In addition to the simulation rate, a game speed factor is also calculated. This is based on the target simulation speed, which is 30 milliseconds per game tick. At that speed, the expected frame rate is 33.33 frames/second, and the game speed factor is how close to that target the actual rate is. When the game is in fast forward mode, the game speed factor shows how much speed up is achieved.

The lower part of the window shows timing statistics for individual parts of the game. The times shown are short-term and long-term averages of how long it takes to process one tick of game time, all figures are in milliseconds.

Clicking a line in the lower part of the window opens a graph window, giving detailed readings on each tick simulated by the game.

The following is an explanation of the different statistics:

• Game loop - Total processing time used per simulated "tick" in the game. This includes all pathfinding, world updates, and economy handling.
• Cargo handling - Time spent loading/unloading cargo at stations, and industries and towns sending/retrieving cargo from stations.
• Train ticks, Road vehicle ticks, Ship ticks, Aircraft ticks - Time spent on pathfinding and other processing for each player vehicle type.
• World ticks - Time spent on other world/landscape processing. This includes towns growing, building animations, updates of farmland and trees, and station rating updates.
• GS/AI total, Game script, and AI players - Time spent running logic for game scripts and AI players. The total may show as less than the current sum of the individual scripts, this is because AI players at lower difficulty settings do not run every game tick, and hence contribute less to the average across all ticks. Keep in mind that the "Current" figure is also an average, just only over short term.
• Link graph delay - Time overruns of the cargo distribution link graph update thread. Usually the link graph is updated in a background thread, but these updates need to synchronise with the main game loop occasionally, if the time spent on link graph updates is longer than the time taken to otherwise simulate the game while it was updating, these delays are counted in this figure.
• Graphics rendering - Total time spent rendering all graphics, including both GUI and world viewports. This typically spikes when panning the view around, and when more things are happening on screen at once.
• World viewport rendering - Isolated time spent rendering just world viewports. If this figure is significantly lower than the total graphics rendering time, most time is spent rendering GUI than rendering world.
• Video output - Speed of copying the rendered graphics to the display adapter. Usually this should be very fast (in the range of 0-3 ms), large values for this can indicate a graphics driver problem.
• Sound mixing - Speed of mixing active audio samples together. Usually this should be very fast (in the range of 0-3 ms), if it is slow, consider switching to the NoSound set.

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.