[1.16.1] Console spams heavily nested feedback which includes chunk related things such as "Chunk Status - minecraft:full". It then ends in a stack.

[Numpty-Clodpole]

Link/paste of stack trace

Link to the beginning, and end of the whole thing here: https://paste.ubuntu.com/p/QqPwWrrk7d/

The stack is at the bottom of that paste, but I'll include it here as well:

 Current Thread: Server thread
 	PID: 34 | Suspended: false | Native: false | State: TIMED_WAITING
 	Stack:
 		sun.misc.Unsafe.park(Native Method)
 		java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 		net.minecraft.server.v1_16_R1.IAsyncTaskHandler.bk(IAsyncTaskHandler.java:131)
 		net.minecraft.server.v1_16_R1.IAsyncTaskHandler.awaitTasks(IAsyncTaskHandler.java:120)
 		net.minecraft.server.v1_16_R1.ChunkProviderServer.getChunkAt(ChunkProviderServer.java:511)
 		net.minecraft.server.v1_16_R1.World.getChunkAt(World.java:391)
 		net.minecraft.server.v1_16_R1.IWorldReader.getChunkAt(IWorldReader.java:100)
 		net.minecraft.server.v1_16_R1.World.getChunkAt(World.java:332)
 		net.minecraft.server.v1_16_R1.World.getType(World.java:718)
 		net.minecraft.server.v1_16_R1.BlockPortal$Shape.<init>(BlockPortal.java:204)
 		net.minecraft.server.v1_16_R1.BlockPortal.c(BlockPortal.java:129)
 		net.minecraft.server.v1_16_R1.PortalTravelAgent.lambda$findPortal$3(PortalTravelAgent.java:70)
 		net.minecraft.server.v1_16_R1.PortalTravelAgent$$Lambda$5736/443596303.apply(Unknown Source)
 		java.util.Optional.map(Optional.java:215)
 		net.minecraft.server.v1_16_R1.PortalTravelAgent.findPortal(PortalTravelAgent.java:66)
 		net.minecraft.server.v1_16_R1.Entity.teleportTo(Entity.java:2658)
 		net.minecraft.server.v1_16_R1.Entity.a(Entity.java:2575)
 		net.minecraft.server.v1_16_R1.Entity.doPortalTick(Entity.java:2201)
 		net.minecraft.server.v1_16_R1.Entity.postTick(Entity.java:454)
 		net.minecraft.server.v1_16_R1.WorldServer.entityJoinedWorld(WorldServer.java:833)
 		net.minecraft.server.v1_16_R1.WorldServer$$Lambda$4777/705438123.accept(Unknown Source)
 		net.minecraft.server.v1_16_R1.World.a(World.java:932)
 		net.minecraft.server.v1_16_R1.WorldServer.doTick(WorldServer.java:526)
 		net.minecraft.server.v1_16_R1.MinecraftServer.b(MinecraftServer.java:1353)
 		net.minecraft.server.v1_16_R1.DedicatedServer.b(DedicatedServer.java:377)
 		net.minecraft.server.v1_16_R1.MinecraftServer.a(MinecraftServer.java:1212)
 		net.minecraft.server.v1_16_R1.MinecraftServer.v(MinecraftServer.java:1000)
 		net.minecraft.server.v1_16_R1.MinecraftServer.lambda$a$0(MinecraftServer.java:177)
 		net.minecraft.server.v1_16_R1.MinecraftServer$$Lambda$2978/962890623.run(Unknown Source)
 		java.lang.Thread.run(Thread.java:748)

Please do not make reports when the report says "DO NOT REPORT THIS TO PAPER". These are simply messages informing you of lag, to find what is causing it. Ask for tips on Discord or IRC instead.

^ Regarding this 'do not report' policy, whilst I was helping another user in the Spigot discord server with the same issue, electroniccat told me to report it here after looking at it himself. Initially I wasn't going to report it due to the log telling me that. Proof:

Plugin list:

• LuckPerms: https://www.spigotmc.org/resources/luckperms-an-advanced-permissions-plugin.28140/
• FoundDiamonds: https://github.com/WeNeedCoffee/FoundDiamonds/
• BetterBanner: https://www.spigotmc.org/resources/betterbanner.63993/
• VillagerOptimiser: https://www.spigotmc.org/resources/villager-optimiser-1-14-2-1-15-2.68517/
• Spark: https://www.spigotmc.org/resources/spark.57242/
• EnderSurfer: https://dev.bukkit.org/projects/endersurfer/
• NuVotifier: https://www.spigotmc.org/resources/nuvotifier.13449/
• Multiverse-Core: https://www.spigotmc.org/resources/multiverse-core.390/
• ProtocolLib: https://www.spigotmc.org/resources/protocollib.1997/
• AutomaticInventory: https://dev.bukkit.org/projects/automatic-inventory
• CommandHook: https://www.spigotmc.org/resources/commandhook.61415/
• KixsChatAnnouncer: https://www.spigotmc.org/resources/%E2%99%A6-kixs-auto-announcer-%E2%99%A6-announcements-that-stand-out-1-12-1-15-x.50320/
• LimitPillagers: https://www.spigotmc.org/resources/limitpillagers-fix-outpost-spawns-and-more.69733/
• TrollBoss: https://www.spigotmc.org/resources/trollboss.47423/
• Whitelist: https://dev.bukkit.org/projects/whitelistplugin/
• Despawner: (Custom made, by one of the mcMMO moderators - Vicarious/Kraken - no plugin page. Despawns a specified list of hostile mobs on a 10min loop.)
• Vault: https://www.spigotmc.org/resources/vault.34315/
• MobHeads: https://www.spigotmc.org/resources/ultimate-mob-heads.54946/
• Dynmap: https://www.spigotmc.org/resources/dynmap.274/
• WorldEdit: https://dev.bukkit.org/projects/worldedit/
• Essentials: https://www.spigotmc.org/resources/essentialsx.9089/
• StackableItems: https://dev.bukkit.org/projects/stackableitems
• PerWorldInventory: https://www.spigotmc.org/resources/per-world-inventory.4482/
• WorldGuard: https://dev.bukkit.org/projects/worldguard/
• VotingPlugin: https://www.spigotmc.org/resources/votingplugin.15358/
• mcMMO: https://www.spigotmc.org/resources/official-mcmmo-overhaul.64348/
• CoreProtect: https://www.spigotmc.org/resources/coreprotect.8631/
• PluginLibrary: https://www.spigotmc.org/resources/plugin-library.17645/
• Harbor: https://www.spigotmc.org/resources/harbor-a-sleep-enhancement-plugin.60088/
• DiscordSRV: https://www.spigotmc.org/resources/discordsrv.18494/

Actions to reproduce (if known):

Honestly, I am unable to consistently reproduce it. This seems to occur randomly whilst loading chunks. From the above stack though, and what Cat said, I want to assume it has to do with a portal being loaded.

Paper build number:

> version
[02:00:05 INFO]: This server is running Paper version git-Paper-26 (MC: 1.16.1) (Implementing API version 1.16.1-R0.1-SNAPSHOT)
[02:00:05 INFO]: Checking version, please wait...
[02:00:06 INFO]: You are running the latest version

Other notes:

It might be worth noting that this does not happen on Spigot at all, which is rather unfortunate. I wish to use Paper, but this is the only thing stopping me. I'm not sure if this is a helpful note.

One last note, is this issue appears to be similar to #2699. Cat was a tad befuddled by it as well.

[aikar]

I don't see a bug here, just the crappiness of portals.

It loads a lot of chunks and i think it can be improved to not need to load as many once it finds the candidate.

In this case, all of the chunks are blocked on the light queue.

full logs to see if light was doing work would of been more ideal

[Numpty-Clodpole]

Well, I didn't include the full log before, because it is a 865KB text file. Pastebin won't let me paste over 512KB, Ubuntu's website hangs after more than a few thousand lines of text, and even Hastebin won't accept it.

So I guess I'll just attach it as a file, if that's okay?
Here: 2020-06-28-6.log
It seems I didn't mention it before, and should have - this resulted in a crash. It's all there in the huge log file.

Edit: It looks like md_5's paste site accepted it: https://paste.md-5.net/idadaguqab.sql
I should mention that this log is from when build 13 was the latest, but it still occurs on build 26 as stated in the opening post.

[aikar]

[21:21:06] [Paper Watchdog Thread/ERROR]: Current Thread: Server-Worker-16
[21:21:06] [Paper Watchdog Thread/ERROR]: 	PID: 33 | Suspended: false | Native: false | State: RUNNABLE
[21:21:06] [Paper Watchdog Thread/ERROR]: 	Stack:
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngineStorage.a(LightEngineStorage.java:289)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngineLayer.a(LightEngineLayer.java:184)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngine.a(SourceFile:59)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngineThreaded.b(LightEngineThreaded.java:293)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngineThreaded.lambda$a$14(LightEngineThreaded.java:209)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.LightEngineThreaded$$Lambda$4635/1624813331.run(Unknown Source)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.ChunkTaskQueueSorter.b(SourceFile:58)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.ChunkTaskQueueSorter$$Lambda$4657/1040980989.run(Unknown Source)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.ThreadedMailbox.e(ThreadedMailbox.java:90)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.ThreadedMailbox.a(ThreadedMailbox.java:137)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		net.minecraft.server.v1_16_R1.ThreadedMailbox.run(ThreadedMailbox.java:102)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[21:21:06] [Paper Watchdog Thread/ERROR]: 		java.lang.Thread.run(Thread.java:748)

well it wasn't stuck. something queued up a lot of work. how many players had going on and assuming chunk generation too?

can you provide timings report so can see config? ultimately tons of chunks all were requested all needing light generated, and light queue seems to of taken too long to get it all done.

if you increased portal search radius, this is absolutely source of it.

ultimately, we do need to improve portals.

[Numpty-Clodpole]

From that log on the 28th, we probably only had around 6 players online. We were all generating new chunks, either searching for Netherite (ancient debris) in the Nether, or trying to find some of the other new things. Most of the players utilise an elytra with firework rockets, so I would imagine that's what caused so many requests all at once.

I do not have a timings report from that day, nor the two days after. I ended up switching back to Spigot after that, due to it tolerating the high chunk loading frequency. However, I just rebooted and switched to Paper right now since no players were online, and created a timings report for you: https://timings.aikar.co/?id=d2f294e0cf5a4692a99e4344c0509c54

The portal search radius setting has not been touched from default, as far as I'm aware - portal-search-radius: 128. If it is meant to be lower, I could certainly set it lower.

[aikar]

6 players using elytras generating chunks is yeah going to suck really hard core on queueing up data....

theres nothing we can do about that. your going to have to solve that one politically. id suggest reducing your view distance significantly for a while to improve things.

maybe cap at 6 no tick view distance.

[aikar]

note that even with portal optimizations, it wouldn't of helped you here. if light is flooded, then light is flooded, can't avoid that.

we could maybe try to cancel generating light once a chunk is unloaded, but still iffy.

[Numpty-Clodpole]

Would you be willing to help me understand why despite what you said, in this same context on Paper in 1.15.2, and on all of the 1.16.1 Spigot builds, I haven't encountered this issue?

Same context, meaning 6+ players online generating chunks with elytras and firework rockets at 16 chunk render distance. It was
my understanding that Paper is better overall for performance, which is why I'd really like to be able to use it.

Prior to submitting this comment, I also asked elsewhere to be sure, and one person suggested that perhaps the reason why I'm experiencing issues now, is due to the new Nether chunks being more complex to load than the chunk loading I had going on in 1.15.2. However, this would not explain why I'm able to run Spigot without this issue.

... and again, I know I've said this repeatedly now, but I cannot stress enough that I much prefer Paper. Not being able to use it and being forced to use Spigot instead is disappointing.

[Numpty-Clodpole]

This has been fixed in 7672852. Thank you for that, Aikar.