CitizensDev/Citizens — Issue #455: On Login lag.
Author: Asphodan
Created: 2011-12-10 20:49:55+00:00
State: open

2011-12-10 14:38:21 [INFO] adding player crazziecanuck
2011-12-10 14:38:22 [INFO] Logging in player: crazziecanuck
2011-12-10 14:38:22 [INFO] Loaded player file, took 0.215327 ms
2011-12-10 14:38:22 [INFO] Updated World Variables, took 0.00108 ms
2011-12-10 14:38:22 [INFO] crazziecanuck [/142.46.193.2:60998] logged in with entity id 3631 at ([world] 2582.300000011921, 58.0, -1490.4035888202375)
2011-12-10 14:38:22 [INFO] Updated gamemode and spawn, took 0.096461 ms
2011-12-10 14:38:22 [INFO] Sent players online list, took 0.005043 ms
2011-12-10 14:38:22 [INFO] Sent spawn position, took 0.003082 ms
2011-12-10 14:38:22 [INFO] Set player bed and world time, took 0.004357 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with Spout was 2.015977 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKChat was 1.047162 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with WorldEdit was 0.005513 ms
2011-12-10 14:38:22 [INFO] [PermissionsEx] Permissions handler for crazziecanuck successfuly injected
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with PermissionsEx was 0.55982 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKModTickets was 0.571719 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKB3 was 0.0775 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with commissionone was 0.060234 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKModPowers was 0.152384 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with VoxelSniper was 0.003318 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with Multiverse-Core was 0.003543 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with iConomy was 2.770888 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with AfkKick was 0.005619 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with VotifierReminder was 0.031704 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with WorldGuard was 0.168173 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with mcMMO was 0.060611 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with Citizens was 0.04896 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with HeroSpawn was 0.002758 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with NoCheat was 0.003779 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKCreditsShop was 3.109031 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKBetterActivity was 2.636932 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKNames was 40.73284 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with OKMotds was 0.076139 ms
2011-12-10 14:38:22 [INFO] connect from ip 142.46.193.2
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with KiwiAdmin was 0.097832 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with BetterCapes was 0.34482 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with LogBlock was 0.020573 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with NoLagg was 0.005806 ms
2011-12-10 14:38:22 [INFO] Execution time for PLAYER JOIN event with MagicSpells was 1.820984 ms
2011-12-10 14:38:22 [INFO] [OKB3] [SYNC] crazziecanuck's ranks successfully updated.
2011-12-10 14:38:22 [INFO] [0m
2011-12-10 14:38:22 [INFO] Called Player Join Event, took 121.917482 ms

------------------
------------------

2011-12-10 14:38:23 [INFO] Updated World Variables, took 0.001082 ms
2011-12-10 14:38:23 [INFO] Asphodan [/173.202.36.212:52056] logged in with entity id 3713 at ([tutorial] 57.28125, 88.0, 348.65625)
2011-12-10 14:38:23 [INFO] Updated gamemode and spawn, took 0.079808 ms
2011-12-10 14:38:23 [INFO] Sent players online list, took 0.004948 ms
2011-12-10 14:38:23 [INFO] Sent spawn position, took 0.003117 ms
2011-12-10 14:38:23 [INFO] Set player bed and world time, took 0.004149 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with Spout was 3.075478 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with OKChat was 1.033942 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with WorldEdit was 0.005499 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with PermissionsEx was 0.018977 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with OKModTickets was 0.525639 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with OKB3 was 0.083176 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with commissionone was 0.032536 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with OKModPowers was 4.139397 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with VoxelSniper was 43.814522 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with Multiverse-Core was 0.003441 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with iConomy was 2.675449 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with AfkKick was 0.006264 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with VotifierReminder was 0.06632 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with WorldGuard was 0.038813 ms
2011-12-10 14:38:23 [INFO] Execution time for PLAYER JOIN event with mcMMO was 0.020463 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with Citizens was 20978.986653 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with HeroSpawn was 0.003185 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with NoCheat was 0.003674 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with OKCreditsShop was 3.194933 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with OKBetterActivity was 2.686405 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with OKNames was 20.357283 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with OKMotds was 0.081376 ms
2011-12-10 14:38:44 [INFO] connect from ip 173.202.36.212
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with KiwiAdmin was 0.079236 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with BetterCapes was 0.527141 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with LogBlock was 0.018292 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with NoLagg was 0.004759 ms
2011-12-10 14:38:44 [INFO] Execution time for PLAYER JOIN event with MagicSpells was 0.506992 ms
2011-12-10 14:38:44 [INFO] [OKB3] [SYNC] Asphodan's ranks successfully updated.
2011-12-10 14:38:44 [INFO] Called Player Join Event, took 21065.797174 ms

Using a modified Craftbukkit, we broke down the player-join event on a per-plugin basis. The top is the trace for a regular player, and the bottom is the trace for an admin - simply has the Wildcard node, and that is all.

I am using PermissionsEx as the permissions manager. Switching to something else is not an option, as many of our custom things have been built with PEX in mind.

I'd like to also note that while Citizens is figuring out what to do with the player with the * node, absolutely nothing else can happen on the server as it figures it out.