Closed SlimeDog closed 4 years ago
Ugleh
commented
4 years ago I don't get notifications for some reason on github, I will need to fix that. Sorry for the inconvenience of now seeing this. I take some long breaks from doing minecraft coding. At some point I will have to remove myself totally from the project. I will look into this issue, thanks.
SlimeDog
commented
4 years ago Thanks for looking at it. I imagine it has something to do with how Shopkeeper NPCs are identified to MC/Spigot.
How would you prefer to be notified in future?
Ugleh
commented
4 years ago Here is fine. I am going to change my notification settings.
As for the NPC, they are created as a fake player entity. I will have to I guess verify players are actually players somehow. I think I can do this via UUID, I will test it out.
Ugleh
commented
4 years ago @SlimeDog Can you walk me through how your Shopkeepers NPC is set up? Is it this Shopkeepers plugin, the one that spawns villagers? https://github.com/Shopkeepers
I'm not running into an issue with it, however based off the error above the breadcrumbs end at
me.ford.periodicholographicdisplays
I see thats your plugin. Is this what might be causing the bug instead?
SlimeDog
commented
4 years ago It's possible, but we're not doing anything untoward with NPCs. pHD is still unpublished, in final testing. I'll investigate.
Ugleh
commented
4 years ago I really have no clue what would be the relation with Shopkeeper NPC. Is your Shopkeeper NPC a Villager or is it look like an avatar? There is also the possibility that it has nothing to do with Shopkeepr NPC and was just a coincidence? One theory I have is that it could have to do with how Minecraft handles chunk loading differently in 1.15.2. The error in question starts here
at org.bukkit.Location.getChunk(Location.java:113)
at com.ugleh.redstoneproximitysensor.util.RPS.getNearbyEntities(RPS.java:63)Does your code mess with chunks as well? Maybe it unloads chunks while my code is searching for entities, could also happen on a chunk border, one of the last chunks loaded in the distance. I will have to keep running test my self.
Ugleh
commented
4 years ago I just checked chunk loading/unloading. The chunks load/unload is if RPS wasn't there. I tried with nothing catching the sensor and I tried with an item entity 20 blocks away that was catching the sensor. So I don't believe it is chunk loading/unloading related.
Ugleh
commented
4 years ago I found the culprit. The IllegalStateExeception was issued by your code. I looked at your repo at line 44 of PerChunkListener and it didn't comprehend so I looked at the history of the file.
You have it that if your settings are onDebug to print a stack trace error.
SlimeDog
commented
4 years ago Thanks. We'll review.
SlimeDog
commented
4 years ago I forgot: that debug statement was put in the pHD code temporarily, specifically to identify the source of the IllegalStateException.
mart-r
commented
4 years ago I found the culprit. The IllegalStateExeception was issued by your code. I looked at your repo at line 44 of PerChunkListener and it didn't comprehend so I looked at the history of the file.
SlimeDog/pHD@78813cd#diff-19b30c1b7ce29f7ccc0449243defeaf4L44
You have it that if your settings are onDebug to print a stack trace error.
That's right. It was printing the stacktrace as a debug measure. The idea was to see what's causing the ChunkLoadEvent to be called. And turned out there were thousands of these that were called by the runnable in RPS.
SlimeDog
commented
4 years ago I retested this issue with current RPS 2.4.9.2 and RPS 2.4.5. I was unable to reproduce the TPS degradation.
Ugleh
commented
4 years ago @SlimeDog are you saying that you can't reproduce with either? Why did you reopen just to close, mistake? @mart-r chunks may be loaded if the rps is on the edge of the chunk limit and it's range requires looking at an unloaded chunk. I'm not seeing this issue in 1.15.2, I've tried the scenario and the chunk unloads fine. I'll have to keep testing.
Ugleh
commented
4 years ago @mart-r @SlimeDog So I just did some extensive tests. The RPS will not loads its own chunk or chunks around it if its own chunk is not loaded however if the RPS chunk is loaded then it will load chunks that are within its range to check for entities and then those chunk will unload, causing it to load/unload constantly.
I have always figured that the chunk within the range of an RPS was reasonable to stay loaded as long as the RPS chunk is loaded but I didn't think it would unload almost instantly. and cause constant loading/unloading.
I will make it so the plugin never loads chunks. But I also have some ideas for caching chunk entities within a given loop. so that sensors within the same chunk will not have to do chunk#getentities every time, it will just look at the cache.
SlimeDog
commented
4 years ago I reopened to say that I would test again. I closed when I was unable to reproduce the issue. Spigot 1.15.2 pHD 1.0.0-RC-15 (current) RPS 2.4.5 and 2.4.9.2 Shopkeepers 2.9.1 or 2.9.2
So many things have changed on my servers in the intervening months -- I would have to revert over 150 development versions of plugins -- that I am unable to guarantee the same environment. We were able to reproduce the the issue repeatedly over the course of a week.
mart-r
commented
4 years ago @mart-r @SlimeDog So I just did some extensive tests. The RPS will not loads its own chunk or chunks around it if its own chunk is not loaded however if the RPS chunk is loaded then it will load chunks that are within its range to check for entities and then those chunk will unload, causing it to load/unload constantly.
I have always figured that the chunk within the range of an RPS was reasonable to stay loaded as long as the RPS chunk is loaded but I didn't think it would unload almost instantly. and cause constant loading/unloading.
I will make it so the plugin never loads chunks. But I also have some ideas for caching chunk entities within a given loop. so that sensors within the same chunk will not have to do chunk#getentities every time, it will just look at the cache.
So it sounds like this load-unload-load pattern could be caused by something else loading the chunk (once) and then RPS keeps loading it again and again? If that is the case, then the first chunk load event before any RPS caused chunk load event would be the underlying cause.
SlimeDog, You wouldn't have the (full) logs from that time, would you?
SlimeDog
commented
4 years ago I do not. My log retention is 7 days. :(
But let me take another stab at reproducing it. Give me an hour, say.
Ugleh
commented
4 years ago @mart-r The situation could also happen if a player is within the range of the sensor to be loaded but not in range for its neighboring chunks to be loaded. But like I said my next release will not load chunks anymore.
SlimeDog
commented
4 years ago But let me take another stab at reproducing it. Give me an hour, say.
No error reproduction with versions of pHD, RPS, and Shopkeepers from March 14. Obviously, I cannot replicate the exact environment and scenario. Sorry.
SlimeDog
commented
4 years ago OK! I have a reproduction environment. The key was to be patient. It takes 20+ minutes to get past the threshold. No players were connected during these tests. Interestingly, pHD was not managing any holograms, so it had nothing to do with the issue.
RedstoneProximitySensor-2.4.5. Shopkeepers-2.9.1
I found the issue again with pHD 1.0.0-RC-15, then reproduced it with pHD-0.0.28 and pHD-0.0.29, thinking they might have the relevant DEBUG message; they don't. If we need it, Mart please give me the last version of pHD that does.
If I connect a player at anytime during the test, TPS recovers. When I disconnect the player, then wait patiently, chaos returns.
Ugleh, how do you want to proceed?
SlimeDog
commented
4 years ago Relevant data
plugins/RedstoneProximitySensor/sensors.yml (partial)
sensors:
0b119a61-c9f2-4f59-b4d1-0247c98496db:
location:
world: world_luckyblock
x: -1.0
y: 4.0
z: 0.0
inverted: false
range: 5
acceptedEntities:
- OWNER
- PLAYER
owner: 3cf9b867-2577-49d1-affb-7ba8196a0d39
ownerOnlyEdit: trueImmediately above the RPS sensor @ world_luckyblock -1,5,0 is a command block that executes "say hello". That does not appear to be a relevant component, but it was in the original configuration, so I put it in. EDIT: I removed the command block; no change in the result, so not needed.
plugins/Shopkeepers/save.yml
data-version: 1
'1':
uniqueId: eecb4078-a83e-454a-a39b-bc67fcaa0cb5
name: I sell zappers
world: world_luckyblock
x: 0
y: 9
z: -4
type: admin
object:
type: villager
baby: false
profession: WEAPONSMITH
villagerType: SAVANNA
villagerLevel: 1
recipes:
'1':
item1:
==: org.bukkit.inventory.ItemStack
v: 2230
type: FIRE_CHARGE
amount: 48
item2:
==: org.bukkit.inventory.ItemStack
v: 2230
type: ENDER_PEARL
amount: 16
resultItem:
==: org.bukkit.inventory.ItemStack
v: 2230
type: BLAZE_ROD
meta:
==: ItemMeta
meta-type: UNSPECIFIC
display-name: §b§oBug Zapper
lore:
- ''
- '§r§7When in main hand:'
- §r§2 9 Attack Damage>spark healthreport --memory
[13:00:47] [Server thread/INFO]: [⚡] Generating server health report...
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > TPS from last 5s, 10s, 1m, 5m, 15m:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 11.3, 11.28, 10.89, 11.75, 13.03
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > CPU usage from last 10s, 1m, 15m:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 30%, 25%, 14% (system)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 14%, 16%, 13% (process)
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > Memory usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 1.2 GB / 4.0 GB (28%)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: [/////////// | ]
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > Non-heap memory usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 272.5 MB
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > G1 Eden Space pool usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 106.0 MB / 394.0 MB (26%)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: [|///////// |]
[13:00:47] [Craft Scheduler Thread - 32/INFO]: - Usage at last GC: 0 bytes
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > G1 Old Gen pool usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 1.1 GB / 4.0 GB (26%)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: [/////////|| ]
[13:00:47] [Craft Scheduler Thread - 32/INFO]: - Usage at last GC: 993.0 MB
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > G1 Survivor Space pool usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 2.0 MB / 2.0 MB (100%)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: [////////////////////////////////////////]
[13:00:47] [Craft Scheduler Thread - 32/INFO]: - Usage at last GC: 2.0 MB
[13:00:47] [Craft Scheduler Thread - 32/INFO]:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: > Disk usage:
[13:00:47] [Craft Scheduler Thread - 32/INFO]: 47.2 GB / 77.7 GB (60%)
[13:00:47] [Craft Scheduler Thread - 32/INFO]: [//////////////////////// I have to get back to testing pHD. I have saved the error reproduction environment.
Ugleh
commented
4 years ago You didn't mention but did the command block indicate the chunk was in fact loading with the NPC?
SlimeDog
commented
4 years ago You didn't mention but did the command block indicate the chunk was in fact loading with the NPC?
It did not (I didn't think to design it to do), but per the additional edit above:
EDIT: I removed the command block; no change in the result, so not needed.
In other words, the command block is not required to achieve the negative result.
SlimeDog
commented
4 years ago It did not (I didn't think to design it to do)
If that is useful information, I can run the experiment. But since there were no players connected, that seems pretty likely. Please let me know.
SlimeDog
commented
4 years ago Does the reproduction scenario described above not work for you? Anything more needed?
Ugleh
commented
4 years ago Oh, I misunderstood your intentions. I didn't know you where placing it down in case of negative results. I'm not sure if it will help in your case but I will roll out the update that prevents chunk loading. I have also hard code changed the tick rate of the sensor to 8 ticks, the same amount as a Hopper, from the original 5 ticks. However I did add an option in config to allow sysadmins to change it.
I will be releasing the update as soon as I finish coding the ability for custom crafting of the sensor.
I'm closing this issue, after the update if anything happens again go ahead and reopen. I have speculations of it being ping pong loading/unloading with the NPC trader but without looking at their code I couldn't say for sure.
SlimeDog
commented
4 years ago I don't understand "placing it down in case of negative results."
I will test the update and let you know.
SlimeDog
commented
4 years ago Confirmed issue resolved with RPS 2.5.0. Thank you.
Spigot 1.15.2 RPS 2.4.5
RPS configured for trigger by Owner+Player is triggered by a nearby Shopkeepers NPC. It occurs whether or not players are nearby or distant, or connected or not. Server performance degrades within 15 minutes, due to occurrence of the following every few ticks. Server does not crash, but TPS<5.
Here are the sensor data. Nothing peculiar.