1. Guest, as per the stickied thread, this forum has not been in use since 2014. All bugs and feature requests should be posted to JIRA.

Getting 2-10 second lag spikes all of a sudden

Discussion in 'Bugs & Feature Requests' started by Murderscene, Jun 19, 2013.

  1. Murderscene

    Murderscene

    I've been trying to figure this out all night and I cannot for the life of me!

    I have easily had 60+ players online on my server with no problem. However for the last few days even with 5 online I am getting huge lag spikes. I have checked the server hardware and internet connection and all seems fine.

    Everytime the lag happens. I see the following in console:
    Code (Text):
    CONSOLE: [INFO] /123.456.789.12:51688 lost connection
    The IP and PORT varies alot but without fail I see a lost connection message upon the lag spike.

    It also happens onPlayerJoin. At first I thought it was a bug in my onPlayerJoin code. But I made it output a message to the console when this event is run and noticed that it is NOT run during a lag spike where no player joins but i still get the 'lost connection' message.

    So now I am stumped.

    Would anyone have any ideas?
     
    #1 Murderscene, Jun 19, 2013
    Last edited: Jun 19, 2013
  3. Jigsaw

    Jigsaw
    Supporter

    That lost connection message is usually harmless. I've never seen it cause lag on my server with 40-80 online.

    Have you tried getting the timings for a few minutes while the lag spikes are frequent? If not, that would be my first recommendation.
     
    #2 Jigsaw, Jun 19, 2013
    • Agree Agree x 1
  5. YoFuzzy3

    YoFuzzy3
    Supporter

    Could you please provide a timings sample from when the lag spikes occur?
     
    #3 YoFuzzy3, Jun 19, 2013
  7. Murderscene

    Murderscene

    Yeah I am new to the whole timings thing.

    You can see in the timings that onPlayerJoin causes immense lag. But what I am stumped about is the lag when no players are joining. But seeing 'lost connection' in the console appears. I guess this could be that certain connections are dropping DUE to the lag? But it's still not because of the onPlayerJoin.

    Looking at it properly. I'm guessing it's the interval:20 causing my lag. I am really unsure what I'm looking at here. I paste it into http://aikar.co/timings.php

    Is the Violation Level the thing I should be concerned about? or the Pct Tick (Percentage of tick i presume).

    EDIT: It also happens when players LEAVE the game. :/ Not every time, but alot of the timer directly after a huge spike a player joins or leaves

    Code (Text):
    NoCheatPlus v3.9.3-RC-b539
        PlayerLoginEvent Time: 27188800 Count: 16 Avg: 1699300 Violations: 0
        PlayerLoginEvent Time: 33293128 Count: 16 Avg: 2080820 Violations: 0
        PlayerJoinEvent Time: 217883 Count: 15 Avg: 14525 Violations: 0
        PlayerJoinEvent Time: 354803 Count: 15 Avg: 23653 Violations: 0
        PlayerJoinEvent Time: 2934345 Count: 15 Avg: 195623 Violations: 0
        PlayerJoinEvent Time: 76935068 Count: 15 Avg: 5129004 Violations: 0
        PlayerQuitEvent Time: 381532 Count: 9 Avg: 42392 Violations: 0
        PlayerQuitEvent Time: 665239 Count: 9 Avg: 73915 Violations: 0
        PlayerQuitEvent Time: 153465 Count: 9 Avg: 17051 Violations: 0
        PlayerInteractEvent Time: 64618347 Count: 352 Avg: 183574 Violations: 0
        PlayerInteractEvent Time: 4237334 Count: 352 Avg: 12037 Violations: 0
        PlayerInteractEvent Time: 2574719 Count: 352 Avg: 7314 Violations: 0
        PlayerInteractEvent Time: 7426725 Count: 352 Avg: 21098 Violations: 0
        PlayerAnimationEvent Time: 10389383 Count: 864 Avg: 12024 Violations: 0
        PlayerAnimationEvent Time: 4488319 Count: 864 Avg: 5194 Violations: 0
        PlayerAnimationEvent Time: 4352230 Count: 864 Avg: 5037 Violations: 0
        BlockBreakEvent Time: 4399680 Count: 14 Avg: 314262 Violations: 0
        BlockDamageEvent Time: 3035512 Count: 205 Avg: 14807 Violations: 0
        PlayerCommandPreprocessEvent Time: 8726352 Count: 45 Avg: 193918 Violations: 0
        EntityDamageEvent (and others) Time: 19761147 Count: 1343 Avg: 14714 Violations: 0
        EntityDamageEvent (and others) Time: 11031518 Count: 1343 Avg: 8214 Violations: 0
        EntityDamageEvent (and others) Time: 54478052 Count: 1343 Avg: 40564 Violations: 0
        EntityDamageEvent (and others) Time: 5829908 Count: 1343 Avg: 4340 Violations: 0
        PlayerToggleSneakEvent Time: 2863607 Count: 140 Avg: 20454 Violations: 0
        PlayerToggleSneakEvent Time: 2273262 Count: 140 Avg: 16237 Violations: 0
        PlayerToggleSprintEvent Time: 18307095 Count: 1463 Avg: 12513 Violations: 0
        PlayerToggleSprintEvent Time: 15837590 Count: 1463 Avg: 10825 Violations: 0
        PlayerToggleSprintEvent Time: 7108605 Count: 1463 Avg: 4858 Violations: 0
        FoodLevelChangeEvent Time: 2563275 Count: 10 Avg: 256327 Violations: 0
        PlayerDropItemEvent Time: 484051 Count: 2 Avg: 242025 Violations: 0
        PlayerInteractEntityEvent Time: 2050283 Count: 37 Avg: 55413 Violations: 0
        InventoryClickEvent Time: 2014130 Count: 12 Avg: 167844 Violations: 0
        PlayerItemHeldEvent Time: 5292635 Count: 154 Avg: 34367 Violations: 0
        PlayerMoveEvent Time: 2689388226 Count: 57691 Avg: 46617 Violations: 0
        PlayerMoveEvent Time: 596534483 Count: 57691 Avg: 10340 Violations: 0
        PlayerTeleportEvent Time: 14287529 Count: 344 Avg: 41533 Violations: 0
        Total time 3706478260 (3s)
    PermissionsEx v1.19.6
        PlayerLoginEvent Time: 22745490 Count: 16 Avg: 1421593 Violations: 0
        PlayerLoginEvent Time: 1079562 Count: 16 Avg: 67472 Violations: 0
        PlayerQuitEvent Time: 229245 Count: 9 Avg: 25471 Violations: 0
        PluginEnableEvent Time: 12837524 Count: 5 Avg: 2567504 Violations: 0
        Total time 36891821 (0s)
    WorldEdit v5.5.6
        PlayerQuitEvent Time: 166114 Count: 9 Avg: 18457 Violations: 0
        PlayerInteractEvent Time: 82838748 Count: 352 Avg: 235337 Violations: 0
        PlayerCommandPreprocessEvent Time: 6874059 Count: 45 Avg: 152756 Violations: 0
        PluginEnableEvent Time: 63081 Count: 4 Avg: 15770 Violations: 0
        Total time 89942002 (0s)
    BukkitCompat vR22A
        PlayerCommandPreprocessEvent Time: 1985228 Count: 45 Avg: 44116 Violations: 0
        Total time 1985228 (0s)
    TagAPI v2.3
        PlayerJoinEvent Time: 162403 Count: 15 Avg: 10826 Violations: 0
        PlayerJoinEvent Time: 1236554 Count: 15 Avg: 82436 Violations: 0
        PlayerQuitEvent Time: 115007 Count: 9 Avg: 12778 Violations: 0
        Total time 1513964 (0s)
    BitCraft v1.0
        PlayerLoginEvent Time: 29837511 Count: 16 Avg: 1864844 Violations: 0
        PlayerJoinEvent Time: 69216214863 Count: 15 Avg: 4614414324 Violations: 1374
        PlayerQuitEvent Time: 84974815 Count: 9 Avg: 9441646 Violations: 0
        PlayerInteractEvent Time: 15356515889 Count: 352 Avg: 43626465 Violations: 283
        BlockBreakEvent Time: 4916079234 Count: 14 Avg: 351148516 Violations: 94
        PlayerCommandPreprocessEvent Time: 1845486 Count: 45 Avg: 41010 Violations: 0
        EntityDamageEvent (and others) Time: 2121422 Count: 1343 Avg: 1579 Violations: 0
        EntityDamageEvent (and others) Time: 10279087 Count: 1343 Avg: 7653 Violations: 0
        FoodLevelChangeEvent Time: 167330 Count: 10 Avg: 16733 Violations: 0
        PlayerDropItemEvent Time: 208618 Count: 2 Avg: 104309 Violations: 0
        PlayerInteractEntityEvent Time: 118664676 Count: 37 Avg: 3207153 Violations: 0
        InventoryClickEvent Time: 670173191 Count: 12 Avg: 55847765 Violations: 12
        PlayerMoveEvent Time: 9303799918 Count: 57691 Avg: 161269 Violations: 116
        InventoryOpenEvent Time: 1220669 Count: 20 Avg: 61033 Violations: 0
        PlayerReceiveNameTagEvent Time: 891306739 Count: 198 Avg: 4501549 Violations: 17
        BlockSpreadEvent Time: 13320553 Count: 1769 Avg: 7529 Violations: 0
        HangingBreakByEntityEvent Time: 1744267 Count: 36 Avg: 48451 Violations: 0
        HangingBreakByEntityEvent Time: 71917789 Count: 36 Avg: 1997716 Violations: 0
        CreatureSpawnEvent (and others) Time: 2420173 Count: 388 Avg: 6237 Violations: 0
        CreatureSpawnEvent (and others) Time: 3704098 Count: 388 Avg: 9546 Violations: 0
        BlockRedstoneEvent Time: 4500276 Count: 231 Avg: 19481 Violations: 0
        BlockBurnEvent Time: 2612904 Count: 162 Avg: 16129 Violations: 0
        PlayerPickupItemEvent Time: 13246987 Count: 226 Avg: 58614 Violations: 0
        InventoryCloseEvent Time: 19780213 Count: 37 Avg: 534600 Violations: 0
        BlockFadeEvent Time: 18952497 Count: 2441 Avg: 7764 Violations: 0
        Total time 100755609205 (100s)
    Minecraft
        ** tickTileEntity - TileEntityChest Time: 481338240 Count: 2127733 Avg: 226 Violations: 0
        Task: BitCraft v1.0 Id:(interval:60) Time: 350090365 Count: 1360 Avg: 257419 Violations: 0
        newworldedit - entityTick Time: 129704560227 Count: 46215 Avg: 2806546 Violations: 1
        ** tickEntity - EntityPainting Time: 2359512775 Count: 6573047 Avg: 358 Violations: 0
        ** livingEntityAICollision Time: 1072660468 Count: 1948682 Avg: 550 Violations: 0
        newworldedit - tracker Time: 46965146376 Count: 46215 Avg: 1016231 Violations: 667
        ** tickTileEntity Time: 8227989726 Count: 22151634 Avg: 371 Violations: 0
        Task: TagAPI v2.3 Id:(Single) Time: 10584025 Count: 28 Avg: 378000 Violations: 0
        ** tickTileEntity - TileEntityDispenser Time: 382918083 Count: 2197798 Avg: 174 Violations: 0
        newworldedit - tileEntityPending Time: 8708374 Count: 46215 Avg: 188 Violations: 0
        entityActivationCheck Time: 9524336062 Count: 46215 Avg: 206087 Violations: 0
        ** playerCommand Time: 10309964071 Count: 44 Avg: 234317365 Violations: 200
        ** checkIfActive Time: 56564464082 Count: 32302010 Avg: 1751 Violations: 0
        ** tickTileEntity - TileEntitySkull Time: 214405634 Count: 1285365 Avg: 166 Violations: 0
        ** tickTileEntity - TileEntityHopper Time: 1133081457 Count: 958987 Avg: 1181 Violations: 0
        Player Tick Time: 152107800050 Count: 46214 Avg: 3291379 Violations: 2602
        Task: BitCraft v1.0 Id:(interval:3960) Time: 108203 Count: 2 Avg: 54101 Violations: 0
        newworldedit - doTickPending Time: 1924475171 Count: 46215 Avg: 41641 Violations: 0
        newworldedit - doTickTiles Time: 13999316936 Count: 46215 Avg: 302917 Violations: 0
        ** tickTileEntity - TileEntityBeacon Time: 195116313 Count: 502747 Avg: 388 Violations: 0
        ** tickEntity - CustomVillager Time: 12607290688 Count: 509659 Avg: 24736 Violations: 1
        Task: NoCheatPlus v3.9.3-RC-b539 Id:(Single) Time: 310475100 Count: 3 Avg: 103491700 Violations: 6
        Task: BitCraft v1.0 Id:(Single) Time: 111152790 Count: 138 Avg: 805455 Violations: 0
        Task: NoCheatPlus v3.9.3-RC-b539 Id:(interval:1207) Time: 161837 Count: 38 Avg: 4258 Violations: 0
        Task: NoCheatPlus v3.9.3-RC-b539 Id:(interval:1) Time: 930865898 Count: 46215 Avg: 20142 Violations: 0
        ** tickTileEntity - TileEntityRecordPlayer Time: 180743522 Count: 1079274 Avg: 167 Violations: 0
        Task: BitCraft v1.0 Id:(interval:1) Time: 178122005 Count: 46215 Avg: 3854 Violations: 0
        newworldedit - tileEntityTick Time: 20024240070 Count: 46215 Avg: 433284 Violations: 0
        newworldedit - doChunkUnload Time: 816159387 Count: 46215 Avg: 17660 Violations: 0
        Task: BitCraft v1.0 Id:(interval:6000) Time: 9085351 Count: 7 Avg: 1297907 Violations: 0
        newworldedit - doChunkGC Time: 172690116 Count: 46215 Avg: 3736 Violations: 0
        ** livingEntityTickRest Time: 1012793335 Count: 1948682 Avg: 519 Violations: 0
        Tickables Time: 13437913 Count: 46214 Avg: 290 Violations: 0
        ** tickEntity - EntityItemFrame Time: 6787526951 Count: 20337958 Avg: 333 Violations: 0
        ** livingEntityBaseTick Time: 10428673402 Count: 1948682 Avg: 5351 Violations: 1
        ** tickEntity - CustomOcelot Time: 774931712 Count: 13603 Avg: 56967 Violations: 1
        syncChunkLoad Time: 925470382 Count: 625 Avg: 1480752 Violations: 18
        ** tickEntity - CustomPig Time: 1219738861 Count: 43595 Avg: 27978 Violations: 0
        ** tickEntity Time: 115325273599 Count: 32270629 Avg: 3573 Violations: 1
        newworldedit - doSounds Time: 79938866 Count: 46215 Avg: 1729 Violations: 0
        Task: WorldEdit v5.5.6 Id:(Single) Time: 421011 Count: 143 Avg: 2944 Violations: 0
        ** livingEntityAI Time: 6599698865 Count: 1948682 Avg: 3386 Violations: 0
        ** tickTileEntity - TileEntityLightDetector Time: 167941869 Count: 369720 Avg: 454 Violations: 0
        ChunkIOTick Time: 72685758 Count: 46215 Avg: 1572 Violations: 0
        Task: BitCraft v1.0 Id:(interval:36000) Time: 1169196 Count: 1 Avg: 1169196 Violations: 0
        Task: BitCraft v1.0 Id:(interval:3680) Time: 1224583 Count: 19 Avg: 64451 Violations: 0
        newworldedit - doVillages Time: 1797909125 Count: 46215 Avg: 38903 Violations: 0
        Task: NoCheatPlus v3.9.3-RC-b539 Id:(interval:200) Time: 28306113 Count: 231 Avg: 122537 Violations: 0
        ** tickEntity - EntityPlayer Time: 5252011626 Count: 250604 Avg: 20957 Violations: 0
        Task: BitCraft v1.0 Id:(interval:4840) Time: 120658 Count: 1 Avg: 120658 Violations: 0
        ** tickEntity - EntityItem Time: 138176705 Count: 5227 Avg: 26435 Violations: 0
        Task: BitCraft v1.0 Id:(interval:4140) Time: 160399 Count: 3 Avg: 53466 Violations: 0
        Scheduler Time: 484012882396 Count: 46215 Avg: 10473068 Violations: 9505
        ** entityMove Time: 6039522488 Count: 905086 Avg: 6672 Violations: 0
        Task: BitCraft v1.0 Id:(interval:100) Time: 44021562 Count: 6930 Avg: 6352 Violations: 0
        ** Full Server Tick Time: 868373495955 Count: 46214 Avg: 18790269 Violations: 12820
        ** tickTileEntity - TileEntitySign Time: 2090711595 Count: 12415023 Avg: 168 Violations: 0
        ** tickEntity - CustomCreeper Time: 11206790430 Count: 1107141 Avg: 10122 Violations: 0
        ** tickTileEntity - TileEntityBrewingStand Time: 304541648 Count: 1214987 Avg: 250 Violations: 0
        Player List Time: 91029845 Count: 46214 Avg: 1969 Violations: 0
        newworldedit - mobSpawn Time: 3381268504 Count: 46102 Avg: 73343 Violations: 0
        ** activatedTickEntity Time: 44176932808 Count: 28827231 Avg: 1532 Violations: 2
        ** livingEntityAIMove Time: 7993092998 Count: 1948682 Avg: 4101 Violations: 0
        newworldedit - doPortalForcer Time: 100522116 Count: 46215 Avg: 2175 Violations: 0
        Task: BitCraft v1.0 Id:(interval:20) Time: 481508721908 Count: 53169 Avg: 9056192 Violations: 9496
        newworldedit - doChunkMap Time: 533252768 Count: 46215 Avg: 11538 Violations: 0
    # Version git-Spigot-937 (MC: 1.5.2)
    # Entities 741
    # LivingEntities 93
    Sample time 2863983462929 (2863.983462929s)
     
     
    #4 Murderscene, Jun 19, 2013
    Last edited: Jun 19, 2013
  9. YoFuzzy3

    YoFuzzy3
    Supporter

    Wow, that BitCraft plugin doesn't look well coded...

    9ms pause every 1 second
    4.6s pause on every player join
    43ms pause on every interact
    351ms pause on every block break
    55ms pause on every inventory click
    And that huge playerCommand tick is probably also caused by a command from it.

    What on earth does the plugin do?

    Also the lost connections are caused when someone tries to join the server while it's frozen and then hits cancel or the connection times out.
     
    #5 YoFuzzy3, Jun 19, 2013
  11. Murderscene

    Murderscene

    It's a plugin I coded myself. It's worked perfectly with 60+ players online up until recently with no changes :(.

    I guess it's time to review my code.

    EDIT:
    The only thing I can think of is the mySQL calls it is doing on certain events.

    the mySQL server is located on the same machine and its only simple select, insert, and update calls that have never given me grief before
     
    #6 Murderscene, Jun 19, 2013
  13. YoFuzzy3

    YoFuzzy3
    Supporter

    Does it access some sort of database?
     
    #7 YoFuzzy3, Jun 19, 2013
  15. Murderscene

    Murderscene


    Yes a mySQL server. I edited my post with some info. Any ideas why a local mySQL server would start slowing down?

    The calls seem to still execute quite fast via phpmyadmin (under 0.01 seconds)
     
    #8 Murderscene, Jun 19, 2013
  17. YoFuzzy3

    YoFuzzy3
    Supporter

    Then maybe there's some odd delay when accessing the database from the MySQL server? I have a LogBlock database which is 6GB and doesn't cause any lag. Have you tried running queries Async? Or even before that, put debug messages in your plugin before and after a query?
     
    #9 YoFuzzy3, Jun 19, 2013
  19. Murderscene

    Murderscene

    I think I have found the problem.

    My 'INSERT' queries i do in phpmyadmin (some i forgot to test) are taking sometimes up to 2 seconds to work.

    I never knew that a large database will slow down insert queries. So now I'll have to find a way around this. My server should be able to hand these no problem. So maybe an error in my mySQL setup.

    The table only has around 100k rows
     
    #10 Murderscene, Jun 19, 2013
  21. YoFuzzy3

    YoFuzzy3
    Supporter

    Then try run the 'INSERT' queries in an Async thread? That way they won't hang the main server thread.
     
    #11 YoFuzzy3, Jun 19, 2013
  23. Murderscene

    Murderscene


    It's a good idea. Although with my server I have to be certain that no code is run before the insert query is completed.
     
    #12 Murderscene, Jun 19, 2013
  25. YoFuzzy3

    YoFuzzy3
    Supporter

    Well, good luck with your plugin then.
     
    #13 YoFuzzy3, Jun 19, 2013
  27. Murderscene

    Murderscene

    Thanks for all your help!
     
    #14 Murderscene, Jun 19, 2013
(You must log in or sign up to post here.)