CMDHELPER-2730 - Reported by Hekta

I recently added to my script a part which much uses the queue_* fonctions.
But when I do a /reloadaliases, if this part of my script was executed at least once, reloading takes a very long time.

After one execution, a /reloadaliases takes two minutes :

2013-07-01 17:41:25 [INFO] [CommandHelper]: Executing command on Hekta: /reloadaliases
2013-07-01 17:41:25 [INFO] 1.0.2-SNAPSHOT-10fcc73bec63c30da75b9a8d7dfec6283438fd38 unloaded.
2013-07-01 17:41:25 [INFO] 1.0.2-SNAPSHOT-10fcc73bec63c30da75b9a8d7dfec6283438fd38 loaded.
2013-07-01 17:43:59 [INFO] [CommandHelper]: MethodScript files processed
2013-07-01 17:43:59 [WARNING] [CommandHelper]: Economy could not be initialized. No further errors will occur, unless you try to use an Economy function.
2013-07-01 17:43:59 [INFO] [CommandHelper]: 355 alias(es) defined.
2013-07-01 17:43:59 [INFO] Hekta lost connection: disconnect.endOfStream

A /reloadaliases after 4 or 5 executions of the script crashes the server :

2013-07-01 21:45:42 [INFO] [CommandHelper]: Executing command on Hekta: /reloadaliases
2013-07-01 21:45:42 [INFO] 1.0.2-SNAPSHOT-10fcc73bec63c30da75b9a8d7dfec6283438fd38 unloaded.
2013-07-01 21:45:42 [INFO] 1.0.2-SNAPSHOT-10fcc73bec63c30da75b9a8d7dfec6283438fd38 loaded.
2013-07-01 22:01:45 [SEVERE] null
java.io.IOException: Erreur d'entrée/sortie
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:242)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
at java.io.FilterInputStream.read(FilterInputStream.java:83)
at org.bukkit.craftbukkit.libs.jline.console.ConsoleReader$1.read(ConsoleReader.java:167)
at org.bukkit.craftbukkit.libs.jline.internal.InputStreamReader.read(InputStreamReader.java:267)
at org.bukkit.craftbukkit.libs.jline.internal.InputStreamReader.read(InputStreamReader.java:204)
at org.bukkit.craftbukkit.libs.jline.console.ConsoleReader.readCharacter(ConsoleReader.java:995)
at org.bukkit.craftbukkit.libs.jline.console.ConsoleReader.readLine(ConsoleReader.java:1167)
at net.minecraft.server.v1_5_R3.ThreadCommandReader.run(ThreadCommandReader.java:31)
2013-07-01 22:01:45 [INFO] Stopping server

Aside /reloadaliases, I do not notice any other slowdown.

Comment by LadyCailin

Does it appear as though it is waiting for all queued tasks to complete before finishing? I'm wondering if it's blocking until it finishes or something.

Comment by Hekta

I always did a /reloadaliases only after all tasks were executed, I also tried with adding a queue_clear() at the end of the script, this does not change anything, the /reloadaliases is still very long.

Comment by PseudoKnight

I also experienced this. It would freeze up the server for a variable amount of time. I could be wrong, but I think it was looping queues that are the problem in my case? Stripped down example:

proc('_procedure',
  queue_delay(1000, 'id')
  queue_push(closure(_procedure()), 'id')
)

What I ended up doing is expanding my "/safereload" alias (I save certain session data here and check if certain mini-games are running) to try and clear what queues I suspected might be affecting this, then set_timeout for a couple seconds, then recompile. Clearing the queue and immediately recompiling didn't seem to work, but I may have had a different issue. Once it stopped freezing up the server, I didn't feel like experimenting with it anymore, as you can imagine. It also didn't seem to freeze things up every time, so it's hard to debug.

Comment by LadyCailin

I don't know if my fix will work or not, but can you try the next build? I've re-organized some stuff, and it may have fixed the bug in the process.

Comment by Hekta

I tried the last build, unfortunately it did not solve the problem, the reloading is still long, and after a while the queue_push() function generates a stacktrace (http://pastebin.com/gaD51j5N).

@PseudoKnight
Yes, I effectively have something like this in my script. It is a procedure which checks a condition and if the condition is false, the procedure is re-queued with a queue_push_front() and a queue_delay_front(), until the condition be true. But I know this loop is not running anymore when I do a /reloadaliases, otherwise I see it in the console.

Comment by VergilPrime

Steps to reproduce: Start server, Run a queue, Reloadaliases, Run the queue again.
Note: Queue will not fail if it was not run before Reloadliases.
queue_running() returns true indefinitely after the queue has failed.

Comment by LadyCailin

I think this has been resolved. I cannot reproduce this, and the queue system has essentially been redone enough that old errors are basically obsolete. Anyways, point is, I'm closing this bug, feel free to re-open if you can reproduce it again.

Comment by Hekta

I had not used my scripts with queue_* functions for some time, but I retested with the last build and the problem is still present.
I did a test which artificially reproduces the problem with this 2 aliases :

/queue test $t = >>>
    export('count', 0)
    for(assign(@i, 0), lt(@i, $t), inc(@i),
        queue_push(closure(assign(@count, import('count')) inc(@count) console(@count) export('count', @count)))
    )
<<<

/rel test = >>>
    store_value('time', time())
    run('/reloadaliases')
    console(simple_date('m \'min\' s.S \'sec\'', subtract(time(), get_value('time'))))
<<<

Without using ExecutionQueue :

2013-08-11 00:53:14 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:53:14 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:53:14 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:53:14 [INFO] CommandHelper: 0 min 0.64 sec

With 10 000 queue_push() :

2013-08-11 00:52:51 [INFO] CH: Running original command from a MCCommandSender ----> /queue test 10000
2013-08-11 00:52:51 [INFO] CommandHelper: 1
[...]
2013-08-11 00:52:53 [INFO] CommandHelper: 10000
2013-08-11 00:52:56 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:52:56 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:52:56 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:52:56 [INFO] CommandHelper: 0 min 0.451 sec

With 25 000 :

[...]
2013-08-11 00:32:46 [INFO] CommandHelper: 25000
2013-08-11 00:32:48 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:32:51 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:32:51 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:32:51 [INFO] CommandHelper: 0 min 2.940 sec

50 000 :

[...]
2013-08-11 00:33:44 [INFO] CommandHelper: 50000
2013-08-11 00:33:47 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:34:09 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:34:09 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:34:09 [INFO] CommandHelper: 0 min 22.198 sec

100 000 :

[...]
2013-08-11 00:35:05 [INFO] CommandHelper: 100000
2013-08-11 00:35:09 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:36:56 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:36:56 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:36:56 [INFO] CommandHelper: 1 min 46.692 sec

200 000 :

[...]
2013-08-11 00:38:43 [INFO] CommandHelper: 200000
2013-08-11 00:39:09 [INFO] CH: Running original command from a MCCommandSender ----> /rel test
2013-08-11 00:46:33 [INFO] [CommandHelper]: MethodScript files processed
2013-08-11 00:46:33 [INFO] [CommandHelper]: 2 alias(es) defined.
2013-08-11 00:46:33 [INFO] CommandHelper: 7 min 24.43 sec

The time what takes CommandHelper to perform a /reloadaliases increases exponentially, though all tasks was completely executed when I did a '/rel test'.

Comment by Hekta

I noticed that this only happens with the '/reloadaliases' command, the '/reload' command does not seem affected by the problem and takes a normal time with CommandHelper.

Comment by PseudoKnight

This seems like it was fixed. There were changes and now I cannot reproduce it.