Blocking synchronous operation
SlimeDog opened this issue ยท 20 comments
Spigot 1.13.2 final
MobHunting 6.5.4-b783
[19:11:44] [Server thread/WARN]: [LagMonitor] Plugin MobHunting is performing a blocking I/O operation (Socket: https://bstats.org/) on the main thread. This could affect the server performance, because the thread pauses until it gets the response. Such operations should be performed asynchronous from the main thread. If this happens on server startup, fixing it can drastically reduce startup time. Keep in mind to keep the code thread-safe. Report it to the plugin author
[19:11:44] [Server thread/WARN]: [LagMonitor] The following exception is not an error. It's a hint for the plugin developer to find the source. LagMonitor doesn't prevent this action. It just warns you about it.
java.lang.IllegalAccessException: null
at com.github.games647.lagmonitor.threading.BlockingActionManager.logCurrentStack(BlockingActionManager.java:66) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.threading.BlockingActionManager.checkBlockingAction(BlockingActionManager.java:52) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.listener.BlockingConnectionSelector.select(BlockingConnectionSelector.java:30) [LagMonitor-1.17.1-b155.jar:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1175) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1065) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1063) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1062) [?:?]
at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:177) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1581) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1501) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1499) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498) [?:?]
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) [?:?]
at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:329) [?:?]
at one.lindegaard.MobHunting.HttpTools.isHomePageReachable(HttpTools.java:25) [MobHunting-6.5.4-b783.jar:?]
at one.lindegaard.MobHunting.MetricsManager$1.run(MetricsManager.java:77) [MobHunting-6.5.4-b783.jar:?]
at org.bukkit.craftbukkit.v1_13_R2.scheduler.CraftTask.run(CraftTask.java:81) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at org.bukkit.craftbukkit.v1_13_R2.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:392) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at net.minecraft.server.v1_13_R2.MinecraftServer.b(MinecraftServer.java:889) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at net.minecraft.server.v1_13_R2.DedicatedServer.b(DedicatedServer.java:417) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at net.minecraft.server.v1_13_R2.MinecraftServer.a(MinecraftServer.java:831) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at net.minecraft.server.v1_13_R2.MinecraftServer.run(MinecraftServer.java:729) [spigot-1.13.2.jar-2019-04-22-2230:git-Spigot-1a3504a-a46fdbc]
at java.lang.Thread.run(Thread.java:834) [?:?]
Hmm. I guess I will have to find a solution to this warning. I plan to make a 1.14 release first :-)
This is caused by the intentional main-thread blocking operation if the server denies MobHunting bStats collection (outbound network connections are among the many things I test). So I guess it is going to remain, since we have not convinced you to stop doing that. But the error return should be handled gracefully, if possible. :)
I think think problem started when I moved to Minecraft 1.14. I got an error that I was not alowed to start an AsyncTask som I changed to a SyncTask, when now seems to be the wrong solution.
I will have to investigate this problem again.
Here is my problem if I make the task Async, the I get this error...
[14:15:38] [Craft Scheduler Thread - 4/WARN]: [BagOfGold] Plugin BagOfGold v2.5.7-SNAPSHOT-BTestBuild generated an exception while executing task 36
java.lang.IllegalStateException: ServiceRegisterEvent cannot be triggered asynchronously from another thread.
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:502) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at org.bukkit.plugin.SimpleServicesManager.register(SimpleServicesManager.java:59) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at one.lindegaard.BagOfGold.bukkit.Metrics.<init>(Metrics.java:132) ~[?:?]
at one.lindegaard.BagOfGold.MetricsManager.startBStatsMetrics(MetricsManager.java:49) ~[?:?]
at one.lindegaard.BagOfGold.MetricsManager.access$100(MetricsManager.java:17) ~[?:?]
at one.lindegaard.BagOfGold.MetricsManager$1.run(MetricsManager.java:34) ~[?:?]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftTask.run(CraftTask.java:81) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:54) [spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]
[14:15:38] [Craft Scheduler Thread - 1/WARN]: [MobHunting] Plugin MobHunting v6.5.6-SNAPSHOT-BTestBuild generated an exception while executing task 62
java.lang.IllegalStateException: ServiceRegisterEvent cannot be triggered asynchronously from another thread.
at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:502) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at org.bukkit.plugin.SimpleServicesManager.register(SimpleServicesManager.java:59) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at one.lindegaard.MobHunting.bukkit.Metrics.<init>(Metrics.java:132) ~[?:?]
at one.lindegaard.MobHunting.MetricsManager.startBStatsMetrics(MetricsManager.java:93) ~[?:?]
at one.lindegaard.MobHunting.MetricsManager.access$100(MetricsManager.java:60) ~[?:?]
at one.lindegaard.MobHunting.MetricsManager$1.run(MetricsManager.java:78) ~[?:?]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftTask.run(CraftTask.java:81) ~[spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:54) [spigot-1.14.jar:git-Spigot-1eece4f-d203283]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_171]
>
I dont know, but my guess i that it is bStat which uses a service.
That would explain why I couldn't find it in the sources. :)
Could you please help me testing the latest snapshot?
I hope fixed the problem
https://fractal.lindegaard.one:8181/job/MobHunting/
and
https://fractal.lindegaard.one:8181/job/BagOfGold/
if you use BagOfGold too.
I get a different error result for MB 6.5.6-b788, with both Spigot 1.14 and Spigot 1.13.2 final, when I am blocking the bStats get.
[13:06:02] [Server thread/WARN]: [LagMonitor] Plugin MobHunting is performing a blocking I/O operation (Socket: https://bstats.org/) on the main thread. This could affect the server performance, because the thread pauses until it gets the response. Such operations should be performed asynchronous from the main thread. If this happens on server startup, fixing it can drastically reduce startup time. Keep in mind to keep the code thread-safe. Report it to the plugin author
[13:06:02] [Server thread/WARN]: [LagMonitor] The following exception is not an error. It's a hint for the plugin developer to find the source. LagMonitor doesn't prevent this action. It just warns you about it.
java.lang.IllegalAccessException: null
at com.github.games647.lagmonitor.threading.BlockingActionManager.logCurrentStack(BlockingActionManager.java:66) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.threading.BlockingActionManager.checkBlockingAction(BlockingActionManager.java:52) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.listener.BlockingConnectionSelector.select(BlockingConnectionSelector.java:30) [LagMonitor-1.17.1-b155.jar:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1175) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1065) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1063) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1062) [?:?]
at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:177) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1581) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1501) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1499) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498) [?:?]
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) [?:?]
at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:329) [?:?]
at one.lindegaard.Core.HttpTools.isHomePageReachable(HttpTools.java:31) [MobHunting-6.5.6-b788.jar:?]
at one.lindegaard.MobHunting.MetricsManager$1.run(MetricsManager.java:80) [MobHunting-6.5.6-b788.jar:?]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftTask.run(CraftTask.java:81) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:394) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at net.minecraft.server.v1_14_R1.MinecraftServer.b(MinecraftServer.java:1008) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at net.minecraft.server.v1_14_R1.DedicatedServer.b(DedicatedServer.java:396) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at net.minecraft.server.v1_14_R1.MinecraftServer.a(MinecraftServer.java:956) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at net.minecraft.server.v1_14_R1.MinecraftServer.run(MinecraftServer.java:801) [spigot-1.14.jar-2019-05-08-0434:git-Spigot-1eece4f-ee88184]
at java.lang.Thread.run(Thread.java:834) [?:?]```
Hmmm I thought I had made it non blocking now :-( i will have to look at this again tonight.
Please test newest build
https://fractal.lindegaard.one:8181/job/MobHunting/789/
I don't understand how you can make it non-blocking and still impose a 15-second delay. Isn't that blocking, by it's very nature?
BTW, this issue doesn't affect server performance in any way, other than the 15-second delay on start-up. So it's not clear that it is a warning that you should address. LagMonitor is telling it like it is. Just saying...
Spigot 1.13.2 final or Spigot 1.14 (2280)
MobHunting 6.5.6-b79
[10:12:05] [Server thread/WARN]: [LagMonitor] Plugin MobHunting is performing a blocking I/O operation (Socket: https://bstats.org/) on the main thread. This could affect the server performance, because the thread pauses until it gets the response. Such operations should be performed asynchronous from the main thread. If this happens on server startup, fixing it can drastically reduce startup time. Keep in mind to keep the code thread-safe. Report it to the plugin author
[10:12:05] [Server thread/WARN]: [LagMonitor] The following exception is not an error. It's a hint for the plugin developer to find the source. LagMonitor doesn't prevent this action. It just warns you about it.
java.lang.IllegalAccessException: null
at com.github.games647.lagmonitor.threading.BlockingActionManager.logCurrentStack(BlockingActionManager.java:66) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.threading.BlockingActionManager.checkBlockingAction(BlockingActionManager.java:52) [LagMonitor-1.17.1-b155.jar:?]
at com.github.games647.lagmonitor.listener.BlockingConnectionSelector.select(BlockingConnectionSelector.java:30) [LagMonitor-1.17.1-b155.jar:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1175) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1065) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1063) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1062) [?:?]
at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:177) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1581) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1501) [?:?]
at sun.net.www.protocol.http.HttpURLConnection$9.run(HttpURLConnection.java:1499) [?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:793) [?:?]
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498) [?:?]
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:527) [?:?]
at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:329) [?:?]
at one.lindegaard.Core.HttpTools.isHomePageReachable(HttpTools.java:31) [MobHunting-6.5.6-b789.jar:?]
at one.lindegaard.MobHunting.MetricsManager$1.run(MetricsManager.java:80) [MobHunting-6.5.6-b789.jar:?]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftTask.run(CraftTask.java:81) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at org.bukkit.craftbukkit.v1_14_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:394) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at net.minecraft.server.v1_14_R1.MinecraftServer.b(MinecraftServer.java:1008) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at net.minecraft.server.v1_14_R1.DedicatedServer.b(DedicatedServer.java:396) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at net.minecraft.server.v1_14_R1.MinecraftServer.a(MinecraftServer.java:956) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at net.minecraft.server.v1_14_R1.MinecraftServer.run(MinecraftServer.java:801) [spigot-1.14.jar-2019-05-09-0938:git-Spigot-1eece4f-6ceffb0]
at java.lang.Thread.run(Thread.java:834) [?:?]
Well to me there is a difference.
- The number of users is one of the things which motivates me to continue my development on my plugins. Therefor it is very important to me that the users tell me that they use my plugins. I have oftens turned the question and asked why they dont want to do this? The collected data does not contain any track of the senders id - only a randomly generated id (in bstats config.yml)
The 15sec blocking on startup is only done once, and I used a blocking method.
-
If the server owner has accepted bStats collection. The plugins will start to report data every 30 min, unless the bStats servers is down. If the bStats server is down, it would normally throw an error in the console, telling that the data could not be delivered. To skip this error I have tried to make a test, to see if the bStats web-server can be reached and then send a nicer message to the server console. It seems that the new Bukkit server has changed how new tasks is run, which seems to give me problems.
-
If you choose to block bStats IP adress in your firewall, situation 2 will happen.
But why do you want to block bStats?
I don't. But I test everything. And since you do make this issue, I test it. No worries.
As you may recall from the discussion, I defend your right to impose the delay, even though I think it is misguided. I also support you in other ways, some visible, some not.
Sorry. I could not remember if you were one of users who block bStats! But I do remember that you always help me with testing and good ideas. I have about 5 users like you, who is helping like you do. I appreciate that VERY much.
I will try to find a solution, which LagMonitor does not complain about. I have tried to look at LagMonitor, but I think it is hard to understand how to use Logmonitor.
I wouldn't worry over much about it. If bStats isn't blocked, there is no issue. :)
I have decided to remove the code I used to check if my plugins could reach http://bstats.org and let the bStats plugin do the hard work. This seems to work better now :-)