Getting timings data
- To take timings, run /timings on
- Then, leave it for a few minutes, then run /timings paste
- Use the page given by /timings paste to display the output in a graphical format
Minecraft's game loop runs on ticks. There are 20 ticks in 1 second, meaning that one tick should happen every 50 milliseconds. During one of these ticks, various events are processed (from game ticks such as chunks loading and players interacting with blocks), and each plugin installed on a server will handle these events a different way (for example, a plugin like WorldGuard uses a PlayerMoveEvent to make sure a player isn't where he shouldn't be).
This is where timings data becomes useful. They allow you to monitor how long it takes the plugins installed on your server to process an event. This allows you to see where lag issues arise, as a misbehaving plugin which takes a long amount to handle an event can lead to delays in the tick loop, and thus a server tick rate below 20.
Using Aikar's timing parser
Aikar's timings parser makes it easier to read timings data collected on your server. The timings report is separated into sections for each plugin. The first two sections are Minecraft's own tick events (dealing with loading/unloading entities, chunks, etc.), and the rest are divided by plugin (sorted by total time spent by plugin).
At the top of the report, there are a few general data points:
- Total: The total time spent handling events.
- Sample Time: The total time the server has been collecting timings data for the report.
- Average Entities: The average number of activated entities, followed by the average number of total entities.
- Average Players: The average amount of players logged in during the sample time.
- Average TPS: The average server tick rate during the sample time.
In the headers of sections for plugins, there are two data points following the name and version:
- Total: The total time spent by the plugin processing events during the sample time.
- Pct: The percentage of the sample time this represents.
Each section has several columns of data per event a plugin handles:
- Pct Total: The percentage of the total sample time spent processing the event.
- Calculation: Total / Sample Time
- Pct Tick: The percentage of a single tick (50 ms) spent processing the event.
- Calculation: Avg / 50
- Total: The total time spent during the sample time.
- Avg: The average amount of time spent per tick.
- Count: The amount of times the event was fired and handled by the plugin.
- Vio: The percentage of the total violation count this plugin was responsible for.
- The violation count is the number of times a timer has caused TPS loss.
- Event: The name of the event.
The Pct Total column is a good indicator of overall server tick rate (TPS). If a certain event takes up a large amount of time to process, it could mean that it is responsible for a sluggish server because a good amount of the game loop is spent on that one event.
The Pct Tick column is useful for identifying server lag spikes. For example, if your players complain about experiencing a large lag spike only during logon, it would be wise to examine PlayerJoinEvent timings. Seeing a large number in the Pct Tick column and a low number in the Count column could indicate that the plugin is spending a lot of a single tick processing the event, and thus causing a lag spike. Coupled with a high violations count, this would mean that the plugin is an almost definitive cause of steady, repeated lag spikes.
Examining a timings report is therefore useful to find the root cause of lag on your server. If you see a specific plugin is taking up a lot of time processing a certain event, it is a good indication that the plugin is causing your server lag. Of course, it would not be wise to immediately hassle the developer, as many other factors come into play when dealing with lag issues, such as server hardware, latency when using an external database, etc.