docs/logging_and_performance_metrics.md

   1 # Logging, frame rate and performance metrics
   2
   3 ## 1.0) Logging of potentially dangerous actions
   4
   5 OpenTTD is a complex program, and together with NewGRF, it may show a buggy
   6 behaviour. But not only bugs in code can cause problems. There are several
   7 ways to affect game state possibly resulting in program crash or multiplayer
   8 desyncs.
   9
  10 Easier way would be to forbid all these unsafe actions, but that would affect
  11 game usability for many players. We certainly do not want that.
  12 However, we receive bug reports because of this. To reduce time spent with
  13 solving these problems, these potentially unsafe actions are logged in
  14 the savegame (including crash.sav). Log is stored in crash logs, too.
  15
  16 Information logged:
  17
  18 - Adding / removing / changing order of NewGRFs
  19 - Changing NewGRF parameters, loading compatible NewGRF
  20 - Changing game mode (scenario editor <-> normal game)
  21 - Loading game saved in a different OpenTTD / TTDPatch / Transport Tycoon Deluxe /
  22    original Transport Tycoon version
  23 - Running a modified OpenTTD build
  24 - Changing settings affecting NewGRF behaviour (non-network-safe settings)
  25 - Triggering NewGRF bugs
  26
  27 No personal information is stored.
  28
  29 You can show the game log by typing 'gamelog' in the console or by running
  30 OpenTTD in debug mode.
  31
  32 ## 2.0) Frame rate and performance metrics
  33
  34 The Help menu in-game has a function to open the Frame rate window. This
  35 window shows various real-time performance statistics, measuring what parts
  36 of the game require the most processing power currently.
  37
  38 A summary of the statistics can also be retrieved from the console with the
  39 `fps` command. This is especially useful on dedicated servers, where the
  40 administrator might want to determine what's limiting performance in a slow
  41 game.
  42
  43 The frame rate is given as two figures, the simulation rate and the graphics
  44 frame rate. Usually these are identical, as the screen is rendered exactly
  45 once per simulated tick, but in the future there might be support for graphics
  46 and simulation running at different rates. When the game is paused, the
  47 simulation rate drops to zero.
  48
  49 In addition to the simulation rate, a game speed factor is also calculated.
  50 This is based on the target simulation speed, which is 30 milliseconds per
  51 game tick. At that speed, the expected frame rate is 33.33 frames/second, and
  52 the game speed factor is how close to that target the actual rate is. When
  53 the game is in fast forward mode, the game speed factor shows how much
  54 speed up is achieved.
  55
  56 The lower part of the window shows timing statistics for individual parts of
  57 the game. The times shown are short-term and long-term averages of how long
  58 it takes to process one tick of game time, all figures are in milliseconds.
  59
  60 Clicking a line in the lower part of the window opens a graph window, giving
  61 detailed readings on each tick simulated by the game.
  62
  63 The following is an explanation of the different statistics:
  64
  65 - *Game loop* - Total processing time used per simulated "tick" in the game.
  66   This includes all pathfinding, world updates, and economy handling.
  67 - *Cargo handling* - Time spent loading/unloading cargo at stations, and
  68   industries and towns sending/retrieving cargo from stations.
  69 - *Train ticks*, *Road vehicle ticks*, *Ship ticks*, *Aircraft ticks* -
  70   Time spent on pathfinding and other processing for each player vehicle type.
  71 - *World ticks* - Time spent on other world/landscape processing. This
  72   includes towns growing, building animations, updates of farmland and trees,
  73   and station rating updates.
  74 - *GS/AI total*, *Game script*, and *AI players* - Time spent running logic
  75   for game scripts and AI players. The total may show as less than the current
  76   sum of the individual scripts, this is because AI players at lower
  77   difficulty settings do not run every game tick, and hence contribute less
  78   to the average across all ticks. Keep in mind that the "Current" figure is
  79   also an average, just only over short term.
  80 - *Link graph delay* - Time overruns of the cargo distribution link graph
  81   update thread. Usually the link graph is updated in a background thread,
  82   but these updates need to synchronise with the main game loop occasionally,
  83   if the time spent on link graph updates is longer than the time taken to
  84   otherwise simulate the game while it was updating, these delays are counted
  85   in this figure.
  86 - *Graphics rendering* - Total time spent rendering all graphics, including
  87   both GUI and world viewports. This typically spikes when panning the view
  88   around, and when more things are happening on screen at once.
  89 - *World viewport rendering* - Isolated time spent rendering just world
  90   viewports. If this figure is significantly lower than the total graphics
  91   rendering time, most time is spent rendering GUI than rendering world.
  92 - *Video output* - Speed of copying the rendered graphics to the display
  93   adapter. Usually this should be very fast (in the range of 0-3 ms), large
  94   values for this can indicate a graphics driver problem.
  95 - *Sound mixing* - Speed of mixing active audio samples together. Usually
  96   this should be very fast (in the range of 0-3 ms), if it is slow, consider
  97   switching to the NoSound set.
  98
  99 If the frame rate window is shaded, the title bar will instead show just the
 100 current simulation rate and the game speed factor.
 101
 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.