How to actually use Paper/Spigot Timings and understand the limitations
Posted on November 30, 2019 in minecraft
The most common tool for determining the cause of lag and slowdowns for Minecraft servers at the moment is Timings, built into both Paper and Spigot. However, there is more than meets the eye when it comes to reading a Timings report, and they're not always able to tell you what is causing lag.
Many people look at a Timings report and blindly blame it on whichever shows up first. This is very incorrect for multiple reasons. Firstly, Timings is unable to accurately determine which plugin causes slowdowns (a point I'll come back to later), and secondly that a plugin may be slow in response to another problem with the server. If you're experiencing multiple plugins being listed as a cause of lag in Timings, you likely have another issue with the server that is then causing plugins to perform slowly.
This Timings report is a perfect example of another issue with the server showing up as a plugin problem. At first glance, many would assume that WorldGuard is causing the server to behave slowly here. This is not the case at all. If you look closely, you'll notice that a ridiculously large number of physics events are being passed to WorldGuard per tick. This indicates that the server is being held back by block updates, generally caused by massive redstone contraptions or malicious lag machines created by players.
Removing WorldGuard here is not the solution, as it will not fix the problem and will show up in Timings for any plugin that listens to physics events. The real answer is to find and remove the lag machine.
To talk about the next common issue people encounter when using Timings, I need to briefly explain how Timings works.
Timings is what is known as a sampler. This means throughout the server code, multiple "sample" points have been added. Timings can then extrapolate that everything occurring inside a specific sample section is caused by a particular task. This means everything that occurs in the code section where chunk loading occurs is marked as chunk loading, and everything that happens in the event handler for CraftBook's redstone event is marked as CraftBook.
This sounds fine at first glance, however, what if a plugin triggers a large redstone contraption? This is where inaccuracies start to occur within Timings. Due to plugins being a complex system, and Minecraft having so many "side effects" in every system, it would be impossible for something that works like Timings to provide perfect accuracy. In some cases, Timings can blame a vast majority of the servers tick processing on a single plugin. For example, if a CraftBook Integrated Circuit triggers a large redstone contraption that loads chunks and moves around items in hoppers, CraftBook is blamed for all of that time.
So you're now aware of what the issues are, now I'm sure you want to know the solution. Like most things, there isn't one single perfect solution. Having an understanding about what is happening on your server, and knowledge of the available tools will always be the best way to fix performance problems.
A tool similar to Timings that provides significantly higher accuracy is WarmRoast. This is a CPU Sampler explicitly built for Minecraft, by the original creator of WorldEdit, WorldGuard, and CraftBook. Running WarmRoast itself can appear to be significantly more complex than running Timings, so WorldGuard bundles it in an easy command. Another developer, Luck, has also made a standalone WarmRoast plugin called Spark. This does work the same way as WorldGuard's bundled WarmRoast so will not obtain different results, either can be used the same way.
To use WorldGuard's bundled WarmRoast, run
/wg profile -p when you're noticing the lag. Unlike Timings, this runs for a short period (5 minutes by default). You can pass the command the number of minutes to run for if you want to change this, by running
/wg profile -p 10 for 10 minutes.
This produces an output similar to Timings, but with much finer granularity. From here you can determine exactly what function in the code running on your server is causing slowdowns. This profile is more complicated to read than Timings but provides significantly further detail and accuracy. You can also use this to find other issues easier as well, such as finding out that lag is being caused by zombies targetting villagers. This probably means a mob farm of some description is the issue.
Overall, the correct way to solve performance problems is to understand what a Minecraft server is doing and the tools available to you to solve the problem.
If you're encountering lag, a good first step is to generate a Timings report. As Timings is always running, this is a natural step to rule out the "low hanging fruit". If Timings is showing that there are a considerable number of certain events, or that chunk generation is the cause, you probably don't need to investigate further. You can find the problem contraption or pre-generate your world. If however, it's inconclusive, WarmRoast can provide further information to identify precisely what the problem is.
It's good to make a well-informed judgement when it comes to performance, rather than just deleting plugins that Timings points to. Removing plugins is almost always a red herring, and in some cases only masks the issue for it to come back worse in the future.
If all else fails, plugin developers will be able to do a lot more with a WarmRoast profile than they will with a Timings report. This means if it is a plugin issue, the developer will have a better idea of what the exact problem is, allowing for a much simpler fix.
Posted on July 26, 2018
Over the past few months, I've taken on the task of updating WorldEdit, WorldGuard, and CraftBook to Minecraft 1.13.
Posted on August 10, 2018
Updating WorldGuard to 1.13 has been a complicated process, however not as time-consuming as WorldEdit.
Posted on January 24, 2020
With over half a year since the last big WorldEdit update, we're now releasing WorldEdit 7.1, with many new features and improvements!