Operations performarce decreasing over time #2655
Comments
emanondev
added
the
type: issue
|
do not do |
using reload is not a requirement to replicate this bug: i added
to a command,
|
|
I ran a test myself to see how much of a role LuckPerms really plays on this. Here I list the method and variables taken into account:
private final Permission permission = new Permission("plugintest.permission.test", PermissionDefault.OP,
Map.of("plugintest.permission.test.1", true,
"plugintest.permission.test.2", false,
"plugintest.permission.test.3", true,
"plugintest.permission.test.4", false));
public int run(final CommandContext<S> context) {
final S player = context.getSource();
final boolean reportProgress = getBool(context, "report progress");
final Consumer<String> reporter;
if (reportProgress) {
reporter = getBool(context, "report console") ? logger::info : player::sendMessage;
// plugin logger
} else {
reporter = null;
}
player.sendMessage("Test started");
final Instant start = Instant.now();
if (reportProgress) {
for (int i = 0; i < 10000; ++i) {
final Instant first = Instant.now();
pluginManager.addPermission(permission);
final Instant second = Instant.now();
pluginManager.removePermission(permission);
final Instant third = Instant.now();
reporter.accept("--------------------------------");
reporter.accept("Run: " + i);
reporter.accept("Adding permission: " + Duration.between(first, second).toMillis() + "ms");
reporter.accept("Removing permission: " + Duration.between(second, third).toMillis() + "ms");
reporter.accept("Total permission: " + Duration.between(first, third).toMillis() + "ms");
}
} else {
for (int i = 0; i < 10000; ++i) {
pluginManager.addPermission(permission);
pluginManager.removePermission(permission);
}
}
final Instant finish = Instant.now();
player.sendMessage("");
player.sendMessage("--------------------------------");
player.sendMessage("Test finished");
player.sendMessage("Total time: " + Duration.between(start, finish).toMillis() + "ms");
player.sendMessage("Report progress? " + reportProgress);
if (reportProgress) {
player.sendMessage("Report to plugin logger: " + getBool(context, "report console"));
}
player.sendMessage("LuckPerms present? " + luckpermsInstalled);
player.sendMessage("--------------------------------");
player.sendMessage("");
return SINGLE_SUCCESS;
}
In all cases where reporting in real time was enabled, it printed a time of 0ms, regardless of the reporter target. While yes, it is clear that LP does add a bit of overhead on large operations, realistically no plugin is going to add/remove permissions dynamically in such quantities (a little reminder that on this test the permission is being added and removed 10000 times in a single game tick (that is 20k I don't know what you think but to me it doesn't seem like performance degrades as the number of additions/deletions increases. I would love to see more tests on different platforms or with different methods, this is what I came up with. |
|
I did some more tests
the interesting value is not which code require more time as absolute value but how this changes between time#1 and time#20 of the same code
i'm actually confused by those results and i'm missing something, Test 1 Permission[] perms = new Permission[300];
for (int i = 0; i < 300; i++)
perms[i] = new Permission("test." + i);
new BukkitRunnable() {
private int testCounter = 0;
public void run() {
if (testCounter >= 20){
this.cancel();
return;
}
testCounter++;
long start = System.currentTimeMillis();
for (int i = 0; i < 300; i++) {
Bukkit.getPluginManager().removePermission(perms[i].getName());
Bukkit.getPluginManager().addPermission(perms[i]);
}
System.out.println(
"Required time for test #" + testCounter + ": " + (System.currentTimeMillis() - start));
}
}.runTaskTimer(Quests.get(), 10, 150);Test 2 Permission[] perms = new Permission[300];
new BukkitRunnable() {
private int testCounter = 0;
public void run() {
if (testCounter >= 20){
this.cancel();
return;
}
testCounter++;
long start = System.currentTimeMillis();
for (int i = 0; i < 300; i++)
perms[i] = new Permission("test." + i+1);
System.out.println(
"Required time for test #" + testCounter + ": " + (System.currentTimeMillis() - start));
}
}.runTaskTimer(Quests.get(), 10, 150);Test 3 new BukkitRunnable() {
private int testCounter = 0;
public void run() {
if (testCounter >= 20){
this.cancel();
return;
}
testCounter++;
long start = System.currentTimeMillis();
for (int i = 0; i < 300; i++) {
Permission perm = new Permission("test." + i);
Bukkit.getPluginManager().removePermission(perm.getName());
Bukkit.getPluginManager().addPermission(perm);
}
System.out.println(
"Required time for test #" + testCounter + ": " + (System.currentTimeMillis() - start));
}
}.runTaskTimer(Quests.get(), 10, 150);Test 4 new BukkitRunnable() {
private int testCounter = 0;
public void run() {
if (testCounter >= 20){
this.cancel();
return;
}
testCounter++;
long start = System.currentTimeMillis();
for (int i = 0; i < 300; i++) {
Permission perm = new Permission("test." + (testCounter*1000+i));
Bukkit.getPluginManager().removePermission(perm.getName());
Bukkit.getPluginManager().addPermission(perm);
}
System.out.println(
"Required time for test #" + testCounter + ": " + (System.currentTimeMillis() - start));
}
}.runTaskTimer(Quests.get(), 10, 150);Test 5 new BukkitRunnable() {
private int testCounter = 0;
public void run() {
if (testCounter >= 20){
this.cancel();
return;
}
testCounter++;
long registerSum = 0;
long createSum = 0;
long start;
for (int i = 0; i < 300; i++) {
start = System.currentTimeMillis();
Permission perm = new Permission("test." + (testCounter*1000+i));
createSum+=(System.currentTimeMillis()-start);
start = System.currentTimeMillis();
Bukkit.getPluginManager().removePermission(perm.getName());
Bukkit.getPluginManager().addPermission(perm);
registerSum+=(System.currentTimeMillis()-start);
}
System.out.println(
"Required time for test #" + testCounter + ": " + (createSum+registerSum)+" (create: "+createSum+") (register: "+registerSum+")");
}
}.runTaskTimer(Quests.get(), 10, 150); |
|
Did you run this test with Bukkit's default permission system (LuckPerms not installed at all)? |
|
It was on LuckPerms, i tested now with default and it gave similar results i also added another timer for removePermission operation it also give almost 0 ms time required on each test so i tried to decompile and i noticed that Permission constructor also calls for decompiling i looked to relevant operations: private void dirtyPermissibles(boolean op) {
Set<Permissible> permissibles = getDefaultPermSubscriptions(op);
for (Permissible p : permissibles)
p.recalculatePermissions();
}is called twice for TRUE permissions, once for OP or NOT_OP, never for FALSE after public void recalculatePermissions() {
clearPermissions();
Set<Permission> defaults = Bukkit.getServer().getPluginManager().getDefaultPermissions(isOp());
Bukkit.getServer().getPluginManager().subscribeToDefaultPerms(isOp(), this.parent);
for (Permission perm : defaults) {
String name = perm.getName().toLowerCase(Locale.ENGLISH);
this.permissions.put(name, new PermissionAttachmentInfo(this.parent, name, null, true));
Bukkit.getServer().getPluginManager().subscribeToPermission(name, this.parent);
calculateChildPermissions(perm.getChildren(), false, null);
}
for (PermissionAttachment attachment : this.attachments)
calculateChildPermissions(attachment.getPermissions(), false, attachment);
}calls for i can't test timings of those but all my crash test cointains |
|
Hi, thanks for the detailed report. re: your observations that
|
Indeed, I have observed performances issues even when LuckPerms is not involved. The Spigot permission fundamentally scales very poorly and seems to have worsened in recent versions. I've raised SPIGOT-6433 to flag this up. |
|
I read your Spigot bug report. The reason it is so slow is because each time a new permission is added, the server calls That's not actually the problem: the actual issue is that the behaviour of It:
This is really, really slow, especially when you have thousands of permissions. LuckPerms overrides this for players, but it doesn't / can't do it for every object on the server (like the console, NPCs etc), which is why you are still experiencing the slowdown. It's fundamentally an issue with the Bukkit permissions API. I've tried my best to speed things up where I can, but without being able to modify the server behaviour, there's only so much I can do. From your end, there is one very easy change you can make to resolve the problem: define your permissions so they are not automatically granted by default. Permission achievementParent = new Permission("achievement.*", PermissionDefault.FALSE);
for (int i = 0; i < 9999; ++i) {
String permissionNode = "achievement." + i;
if (Bukkit.getPluginManager().getPermission(permissionNode) == null) {
Permission perm = new Permission(permissionNode, PermissionDefault.FALSE);
perm.addParent(achievementParent, true);
Bukkit.getPluginManager().addPermission(perm);
}
}By using |
|
Profiling on a Spigot 1.16.5 server without LuckPerms installed: https://spark.lucko.me/4f59qsQaMx?hl=18,32,40,47 Those same hotspots will unfortunately occur when LP is installed too, note that the only permissible there is the server console (org.bukkit.craftbukkit.v1_16_R3.command.ServerCommandSender) - the problem will get linearly worse with each extra player (unless you have LP installed) / permissible / NPC / whatever. |
|
Thanks for the additional information. The behaviour you're describing with
Won't this mean a change in default behaviours for users which have overridden the parent permission node and set it to false, at least with some permissions plugins? Admittedly, permissions are not my area of expertise. :) |
Description
The same operation require more time each time you repeat it
Reproduction steps
register a permission on plugin startup with bukkit (pluginmanager) api
then reload the plugin with plugman or just repeat the registering of that permission with bukkitapi
time required for registering the permission is increasing
Logs:
i used plugman reload on a plugin, for readability i'll put logs abouth a specific permission on each plugman reload, but the plugin itself register the same 242 permissions each time it is reloaded
since loading 242 of 40-50ms each gets the server stuck for a bit an error is also printed on console cause the server stopped responding
[01:59:44 ERROR]: --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH - git-Paper-101 (MC: 1.16.1) ---
[01:59:44 ERROR]: The server has not responded for 20 seconds! Creating thread dump
[01:59:44 ERROR]: ------------------------------
[01:59:44 ERROR]: Server thread dump (Look for plugins here before reporting to Paper!):
[01:59:44 ERROR]: ------------------------------
[01:59:44 ERROR]: Current Thread: Server thread
[01:59:44 ERROR]: PID: 16 | Suspended: false | Native: false | State: RUNNABLE
[01:59:44 ERROR]: Stack:
[01:59:44 ERROR]: java.lang.Object.hashCode(Native Method)
[01:59:44 ERROR]: java.util.WeakHashMap.hash(WeakHashMap.java:298)
[01:59:44 ERROR]: java.util.WeakHashMap.put(WeakHashMap.java:449)
[01:59:44 ERROR]: java.util.Collections$SynchronizedMap.put(Collections.java:2590)
[01:59:44 ERROR]: me.lucko.luckperms.bukkit.inject.server.LuckPermsSubscriptionMap$LPSubscriptionValueMap.put(LuckPermsSubscriptionMap.java:218)
[01:59:44 ERROR]: me.lucko.luckperms.bukkit.inject.server.LuckPermsSubscriptionMap$LPSubscriptionValueMap.put(LuckPermsSubscriptionMap.java:160)
[01:59:44 ERROR]: org.bukkit.plugin.SimplePluginManager.subscribeToPermission(SimplePluginManager.java:796)
[01:59:44 ERROR]: org.bukkit.permissions.PermissibleBase.calculateChildPermissions(PermissibleBase.java:207)
[01:59:44 ERROR]: org.bukkit.permissions.PermissibleBase.recalculatePermissions(PermissibleBase.java:177)
[01:59:44 ERROR]: org.bukkit.permissions.Permission.recalculatePermissibles(Permission.java:174)
[...]
Expected behaviour
Time required should be costant, since the same permission is registered the old one should be deleted/replaced
Environment details
[LP] Running LuckPerms v5.1.107 by Luck.
[LP] - Platform: Bukkit
[LP] - Server Brand: Paper
[LP] - Server Version:
[LP] git-Paper-101 (MC: 1.16.1) - 1.16.1-R0.1-SNAPSHOT
[LP] - Storage:
[LP] Type: H2
[LP] File Size: 0.05MB
[LP] - Messaging: None
[LP] - Instance:
[LP] Static contexts: None
[LP] Online Players: 0 (0 unique)
[LP] Uptime: 1m 42s
[LP] Local Data: 0 users, 3 groups, 0 tracks
Any other relevant details
The text was updated successfully, but these errors were encountered: