Operations performarce decreasing over time

Question

Operations performarce decreasing over time

emanondev opened this issue 4 years ago · 11 comments

emanondev commented 4 years ago

Description

The same operation require more time each time you repeat it

Reproduction steps

register a permission on plugin startup with bukkit (pluginmanager) api

long now = System.currentTimeMillis();
Bukkit.getPluginManager().removePermission(perm.getName());
Bukkit.getPluginManager().addPermission(perm);
Bukkit.getPluginManager().recalculatePermissionDefaults(perm);
logIssue("DEBUG: Permission: "+perm.getName()+" (children: "+perm.getChildren().size()+") time: "+(System.currentTimeMillis()-now));

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

[01:42:33] DEBUG: Permission: deepquests.editor.players (children: 3) time: 11
[01:44:33] DEBUG: Permission: deepquests.editor.players (children: 3) time: 8
[01:45:29] DEBUG: Permission: deepquests.editor.players (children: 3) time: 16
[01:45:40] DEBUG: Permission: deepquests.editor.players (children: 3) time: 13
[01:45:50] DEBUG: Permission: deepquests.editor.players (children: 3) time: 14
[01:46:03] DEBUG: Permission: deepquests.editor.players (children: 3) time: 17
[01:46:15] DEBUG: Permission: deepquests.editor.players (children: 3) time: 18
[01:46:30] DEBUG: Permission: deepquests.editor.players (children: 3) time: 20
[01:46:46] DEBUG: Permission: deepquests.editor.players (children: 3) time: 25
[01:47:03] DEBUG: Permission: deepquests.editor.players (children: 3) time: 27
[01:52:43] DEBUG: Permission: deepquests.editor.players (children: 3) time: 27
[01:53:00] DEBUG: Permission: deepquests.editor.players (children: 3) time: 29
[01:53:20] DEBUG: Permission: deepquests.editor.players (children: 3) time: 31
[01:53:43] DEBUG: Permission: deepquests.editor.players (children: 3) time: 46
[01:54:46] DEBUG: Permission: deepquests.editor.players (children: 3) time: 37
[01:55:07] DEBUG: Permission: deepquests.editor.players (children: 3) time: 36
[01:56:17] DEBUG: Permission: deepquests.editor.players (children: 3) time: 41
[01:57:01] DEBUG: Permission: deepquests.editor.players (children: 3) time: 45
[01:58:36] DEBUG: Permission: deepquests.editor.players (children: 3) time: 43
[01:59:25] DEBUG: Permission: deepquests.editor.players (children: 3) time: 46

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

benwoo1110 · Answer 1 · 2020-10-07T02:50:36.000Z

do not do /reload or plugman reload. https://matthewmiller.dev/blog/problem-with-reload/

emanondev · Answer 2 · 2020-10-07T11:27:31.000Z

do not do /reload or plugman reload. https://matthewmiller.dev/blog/problem-with-reload/

using reload is not a requirement to replicate this bug:

i added

long start = System.currentTimeMillis();
for (int i = 1;i<300;i++) {
Permission perm = new Permission("test."+i);
Bukkit.getPluginManager().removePermission(perm.getName());
Bukkit.getPluginManager().addPermission(perm);
Bukkit.getPluginManager().recalculatePermissionDefaults(perm);
}
System.out.println("Required time: "+(System.currentTimeMillis()-start));

to a command,
output:

deepquestsnew manager
[13:21:41 INFO]: Required time: 1333
deepquestsnew manager
[13:21:48 INFO]: Required time: 2542
deepquestsnew manager
[13:21:53 INFO]: Required time: 2699
deepquestsnew manager
[13:21:58 INFO]: Required time: 2689
deepquestsnew manager
[13:22:03 INFO]: Required time: 2944
deepquestsnew manager
[13:22:08 INFO]: Required time: 2837
deepquestsnew manager
[13:22:12 INFO]: Required time: 3020
deepquestsnew manager
[13:22:17 INFO]: Required time: 3034
deepquestsnew manager
[13:22:22 INFO]: Required time: 3212
deepquestsnew manager
[13:22:26 INFO]: Required time: 3213
deepquestsnew manager
[13:22:31 INFO]: Required time: 3265
deepquestsnew manager
[13:22:36 INFO]: Required time: 3463
deepquestsnew manager
[13:22:41 INFO]: Required time: 3451
deepquestsnew manager
[13:22:46 INFO]: Required time: 3407
deepquestsnew manager
[13:22:51 INFO]: Required time: 3562
deepquestsnew manager
[13:22:57 INFO]: Required time: 3539
deepquestsnew manager
[13:23:03 INFO]: Required time: 3831
deepquestsnew manager
[13:23:08 INFO]: Required time: 3702
deepquestsnew manager
[13:23:19 INFO]: Required time: 3873
deepquestsnew manager
[13:23:27 INFO]: Required time: 3960
deepquestsnew manager
[13:23:35 INFO]: Required time: 4413

emilyy-dev · Answer 3 · 2020-10-07T16:44:02.000Z

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:

The test is run by running a command as a player, so a player has to be online and thus permissions have to take effect on a Permissible object.
I ran six tests in total, with every possible combination of the following two-state variables:
- Using LuckPerms or Bukkit's default permission system (basically: Is LuckPerms installed?)
- Reporting the progress in real time to the player, to console, or none. This I did because both reporting progress and even the simple fact of measuring the time takes time by itself, and it's not precisely little processing power.
I removed the PluginManager#recalculatePermissionDefaults(Permission) statement because PluginManager#addPermission(Permission) and PluginManager#removePermission(Permission) already do that.
This is the permission tested:

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));

This is the performed code when the command runs:

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;
}

Results	Logging to player:	Logging to console:	No logging:
LuckPerms loaded	Total time: 4222ms	Total time: 9107ms	Total time: 1625ms
LuckPerms not loaded	Total time: 2807ms	Total time: 8906ms	Total time: 685ms
	Difference: 1415ms	Difference: 201ms	Difference: 940ms

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 PluginManager#recalculatePermissionDefaults(Permission) each individual test)).
And in any case, the results as a whole vary by almost 10x (min diff 201ms, max diff 1415ms), but again, that is the total time, not the individual operations, which again, in all cases where reporting in real time was enabled, it printed a time of 0ms, regardless of the reporter target, and by the time I got to test without logging, the permission was added and removed 20k times each (so 80k PluginManager#recalculatePermissionDefaults(Permission) by the end of the 3 consecutive tests).

lp info

[LP] Running LuckPerms v5.1.107 by Luck.
[LP] -  Platform: Bukkit
[LP] -  Server Brand: Paper
[LP] -  Server Version:
[LP]      git-Paper-216 (MC: 1.16.3) - 1.16.3-R0.1-SNAPSHOT
[LP] -  Storage:
[LP]      Type: H2
[LP]      File Size: 0.03MB
[LP] -  Messaging: None
[LP] -  Instance:
[LP]      Static contexts: None
[LP]      Online Players: 0 (0 unique)
[LP]      Uptime: 5m 10s
[LP]      Local Data: 0 users, 2 groups, 0 tracks

System Info: Java 11 (OpenJDK 64-Bit Server VM 11.0.8+10-post-Ubuntu-0ubuntu120.04) Host: Linux 4.4.0-18362-Microsoft (amd64)

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.

emanondev · Answer 4 · 2020-10-09T02:35:40.000Z

I did some more tests

each test runs 20 times in a timed task
each test print the final result at the end of each time it runs

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

my first 2 tests aimed to understand which part of my previus test required growing time so i splitted them to check permission creation time and permission registering time, surprisingly them were both with costant time
on the third the i putted them back together just to confim to myself i not being crazy, luckly (or unluckly?) the test confirmed i'm not crazy growing from 746ms on time#1 to 3056ms on time#20
on fourth test i tried to use different permission names for each test, just to see if it was related to removePermission working on some strange ways, the test didn't bring relevant conclusions since the time still grows from 1336ms on time#1 2635 on time#20 (still it's interesting that time range from first to last time is less than the range of third test)
on my fifth and last test i choosed to split time counters for permission creation time and permission registering time, the test finally proved that time required for registering permissions is growing while the time required for permission creation is a almost a costant, however test one showed how time required for registering a permission can be a costant too

i'm actually confused by those results and i'm missing something, i can confirm the bug but i can't say it's luckperms fault or if luckperms may fix it

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);

[02:48:09 INFO]: Required time for test #1: 660
[02:48:17 INFO]: Required time for test #2: 692
[02:48:24 INFO]: Required time for test #3: 651
[02:48:32 INFO]: Required time for test #4: 681
[02:48:39 INFO]: Required time for test #5: 654
[02:48:47 INFO]: Required time for test #6: 730
[02:48:54 INFO]: Required time for test #7: 668
[02:49:02 INFO]: Required time for test #8: 682
[02:49:09 INFO]: Required time for test #9: 655
[02:49:17 INFO]: Required time for test #10: 697
[02:49:24 INFO]: Required time for test #11: 639
[02:49:32 INFO]: Required time for test #12: 681
[02:49:39 INFO]: Required time for test #13: 653
[02:49:47 INFO]: Required time for test #14: 702
[02:49:54 INFO]: Required time for test #15: 654
[02:50:02 INFO]: Required time for test #16: 672
[02:50:09 INFO]: Required time for test #17: 642
[02:50:17 INFO]: Required time for test #18: 707
[02:50:24 INFO]: Required time for test #19: 651
[02:50:32 INFO]: Required time for test #20: 681

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);

[02:35:28 INFO]: Required time for test #1: 1
[02:35:35 INFO]: Required time for test #2: 0
[02:35:43 INFO]: Required time for test #3: 1
[02:35:50 INFO]: Required time for test #4: 1
[02:35:58 INFO]: Required time for test #5: 0
[02:36:05 INFO]: Required time for test #6: 0
[02:36:13 INFO]: Required time for test #7: 0
[02:36:20 INFO]: Required time for test #8: 1
[02:36:28 INFO]: Required time for test #9: 1
[02:36:35 INFO]: Required time for test #10: 0
[02:36:43 INFO]: Required time for test #11: 1
[02:36:50 INFO]: Required time for test #12: 1
[02:36:58 INFO]: Required time for test #13: 0
[02:37:05 INFO]: Required time for test #14: 0
[02:37:13 INFO]: Required time for test #15: 1
[02:37:20 INFO]: Required time for test #16: 0
[02:37:28 INFO]: Required time for test #17: 0
[02:37:35 INFO]: Required time for test #18: 0
[02:37:43 INFO]: Required time for test #19: 1
[02:37:50 INFO]: Required time for test #20: 0

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);

[03:11:04 INFO]: Required time for test #1: 746
[03:11:13 INFO]: Required time for test #2: 2064
[03:11:21 INFO]: Required time for test #3: 2132
[03:11:28 INFO]: Required time for test #4: 2148
[03:11:36 INFO]: Required time for test #5: 2233
[03:11:43 INFO]: Required time for test #6: 2261
[03:11:51 INFO]: Required time for test #7: 2344
[03:11:58 INFO]: Required time for test #8: 2462
[03:12:06 INFO]: Required time for test #9: 2473
[03:12:14 INFO]: Required time for test #10: 2520
[03:12:21 INFO]: Required time for test #11: 2537
[03:12:29 INFO]: Required time for test #12: 2694
[03:12:36 INFO]: Required time for test #13: 2726
[03:12:44 INFO]: Required time for test #14: 2700
[03:12:51 INFO]: Required time for test #15: 2786
[03:12:59 INFO]: Required time for test #16: 2885
[03:13:06 INFO]: Required time for test #17: 2913
[03:13:14 INFO]: Required time for test #18: 2977
[03:13:22 INFO]: Required time for test #19: 3010
[03:13:29 INFO]: Required time for test #20: 3056

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);

[03:21:34 INFO]: Required time for test #1: 1336
[03:21:42 INFO]: Required time for test #2: 1327
[03:21:49 INFO]: Required time for test #3: 1399
[03:21:57 INFO]: Required time for test #4: 1430
[03:22:05 INFO]: Required time for test #5: 1595
[03:22:12 INFO]: Required time for test #6: 1540
[03:22:20 INFO]: Required time for test #7: 1615
[03:22:27 INFO]: Required time for test #8: 1719
[03:22:35 INFO]: Required time for test #9: 1963
[03:22:42 INFO]: Required time for test #10: 1817
[03:22:50 INFO]: Required time for test #11: 1930
[03:22:57 INFO]: Required time for test #12: 1913
[03:23:05 INFO]: Required time for test #13: 2219
[03:23:13 INFO]: Required time for test #14: 2087
[03:23:20 INFO]: Required time for test #15: 2188
[03:23:28 INFO]: Required time for test #16: 2221
[03:23:36 INFO]: Required time for test #17: 2637
[03:23:43 INFO]: Required time for test #18: 2393
[03:23:50 INFO]: Required time for test #19: 2428
[03:23:58 INFO]: Required time for test #20: 2635

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);

[03:30:23 INFO]: Required time for test #1: 1269 (create: 2) (register: 1267)
[03:30:30 INFO]: Required time for test #2: 1354 (create: 2) (register: 1352)
[03:30:38 INFO]: Required time for test #3: 1424 (create: 3) (register: 1421)
[03:30:46 INFO]: Required time for test #4: 1538 (create: 0) (register: 1538)
[03:30:53 INFO]: Required time for test #5: 1490 (create: 2) (register: 1488)
[03:31:01 INFO]: Required time for test #6: 1565 (create: 4) (register: 1561)
[03:31:08 INFO]: Required time for test #7: 1644 (create: 2) (register: 1642)
[03:31:16 INFO]: Required time for test #8: 1802 (create: 1) (register: 1801)
[03:31:23 INFO]: Required time for test #9: 1741 (create: 4) (register: 1737)
[03:31:31 INFO]: Required time for test #10: 2200 (create: 2) (register: 2198)
[03:31:38 INFO]: Required time for test #11: 1942 (create: 4) (register: 1938)
[03:31:46 INFO]: Required time for test #12: 2065 (create: 3) (register: 2062)
[03:31:54 INFO]: Required time for test #13: 2081 (create: 2) (register: 2079)
[03:32:01 INFO]: Required time for test #14: 2113 (create: 2) (register: 2111)
[03:32:09 INFO]: Required time for test #15: 2604 (create: 2) (register: 2602)
[03:32:18 INFO]: Required time for test #16: 3877 (create: 4) (register: 3873)
[03:32:24 INFO]: Required time for test #17: 2830 (create: 1) (register: 2829)
[03:32:31 INFO]: Required time for test #18: 2432 (create: 4) (register: 2428)
[03:32:39 INFO]: Required time for test #19: 2549 (create: 0) (register: 2549)
[03:32:47 INFO]: Required time for test #20: 2721 (create: 2) (register: 2719)

emilyy-dev · Answer 5 · 2020-10-09T02:41:01.000Z

Did you run this test with Bukkit's default permission system (LuckPerms not installed at all)?

emanondev · Answer 6 · 2020-10-09T10:59:35.000Z

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
ex: (newpwermission: 1) (addpermission: 672) (removepermission: 2)

so i tried to decompile and i noticed that Permission constructor also calls for recalculatePermission, which do nothing if the permission was never added to the PluginManager, so the first time you create a Permission required time is almost 0 the second time (if added to PluginManager) will do more operations
ex: (newpwermission: 2726) (addpermission: 1375) (removepermission: 0)
that explains why test 3 had such different timings from time 1 to time 2

[03:11:04 INFO]: Required time for test #1: 746
[03:11:13 INFO]: Required time for test #2: 2064

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 recalculatePermission is invoked
p.recalculatePermissions() is

  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 PluginManager.subscribeToPermission() calls LuckPerms/Bukkit Default Permissions

i can't test timings of those but all my crash test cointains .subscribeToPermission(SimplePluginManager.java:796) in the stack trace

[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)
[...]

lucko · Answer 7 · 2020-10-20T12:34:06.000Z

Hi, thanks for the detailed report.

re: your observations that `PluginManager#addPermission` takes longer when using LuckPerms

This is normal and to be expected. LuckPerms changes the way Permission registration works, and stores the information in a slightly different way. The reason for doing this is to make permission checks and calls to Permissible#recalculatePermissions much faster.

I believe the trade off is worth it. Registration of permissions is something that (should usually) happen on plugin enable - permission checks on the other hand happen continuously while the server is running. It makes sense to do a little bit more "work" when registering to make the checks run faster.

You can see the modified permissions map here: https://github.com/lucko/LuckPerms/blob/master/bukkit/src/main/java/me/lucko/luckperms/bukkit/inject/server/LuckPermsPermissionMap.java

re: the benchmarks in general

Benchmarks are tricky to get right - you need to be careful to make sure they are written in such a way to account for JVM warmup etc. There's a good stack overflow answer I found here which sums up what I mean: https://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java

Rudimentary stopwatch type tests are ok, but you can't trust them entirely!

re: where to go from here

Just knowing that the time taken is higher isn't really enough. I'd need some sort of profiler output to be able to make further optimisations.

If you have access to YourKit or jProfiler or something like that - then method instrumentation profiling output would be great. If not, using a sampler plugin such as spark will probably suffice, so long as your tests have enough iterations to be picked up. See: https://github.com/lucko/spark (you can also use --interval 1 for greater accuracy)

If you'd like to dig deeper and find some specific areas that could be optimised, then I would be more than happy to assist with that. However, if not, I think the current timings are probably acceptable.

PyvesB · Answer 8 · 2021-04-24T09:25:49.000Z

It was on LuckPerms, i tested now with default and it gave similar results

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.

lucko · Answer 9 · 2021-04-24T17:58:41.000Z

I read your Spigot bug report.

The reason it is so slow is because each time a new permission is added, the server calls recalculatePermissions on all registered permissibles (via here, then here - this could be anything, players, command blocks, NPCs, any "permission" holding object on the server.

That's not actually the problem: the actual issue is that the behaviour of recalculatePermissions is pretty terrible.

It:

clears all permissions, one at a time, and "unsubscribes" from them - this is a non-simple operation.
then resubscribes, individually, to each permission granted by default or directly to the permissible

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 PermissionDefault.FALSE, the permissions will not be automatically added to all permissibles, which immediately fixes the problem.

lucko · Answer 10 · 2021-04-24T18:06:13.000Z

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.

PyvesB · Answer 11 · 2021-05-01T10:44:17.000Z

Thanks for the additional information. The behaviour you're describing with recalculatePermissions is indeed what I observed when stepping through the Bukkit implementation with a debugger last weekend.

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.

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. :)

Share to