CMDHELPER-2851 - Reported by Tom.Gebbett

I'm not sure if this is a CommandHelper problem, but the tests seem to point towards it.

I'll use player_interact as an example:

I have 5 binds on player_interact, when I measure the entire code contained in the binds using simple nano_time() calls, I'm seeing all of them taking less than 1 ms.

However, when measuring the difference between the 'highest' priority bind and the 'monitor' priority bind, I see anywhere between 10 and 30 ms.

When I unbind all the player_interact events in CH, the time between 'highest' and 'monitor' becomes around 3 ms. I'm guessing this is the time used by other plugins.

This wouldn't be so bad if it was player_command or something, but because the player_interact event is able to run every ~25 ms per player, this extra delay can cause the entire server to hang for a while as long as a few people are building, or fighting.

after unbinding, I started gradually adding more CH events, containing only the minimum amount of code, and the same thing happened. The time taken for the entire event was about the same as before, when I had the same number of binds.

I only mention this because it seems like the extra time is probably due to an unknown problem in CH's bind system, it really does affect the performance of the server.

For anyone else suffering this problem, it may work better to use one single bind for everything within the bind type, and use your own code to emulate prefilters and priorities. I may add a system to do this temporarily.

I'll do some more testing and report back if there's more information.

CH Version: 2439 (Yes, I haven't updated since a little before the 1.7 builds, do they work on a 1.6.4 server? I need to stay 1.6.4 for a bit longer.)

Comment by LadyCailin

All CH events run in the same segment, then the remaining plugin events run. The timeline is:

| possibly a bukkit event | All CH events | All other bukkit events, including monitor level |

Regardless, this is certainly an issue that can hopefully improve, and I will look into it. Thanks for finding it!

1.7 builds should work in 1.6.4, I believe, though you may get some warnings, you probably won't get any fatal errors, but I don't know for sure.

Comment by Tom.Gebbett

Does that order of events mean that other bukkit events ultimately get the final say on event parameters? (unless we lock them?) I noticed that your order of highest to lowest is the opposite of bukkit's (according to their documentation), did you feel that consume and lock were enough to justify reversing it? Either way works for me to be honest, yours is a little more sensical and extensive.

Also, i've noticed that consuming an event in commandhelper doesn't prevent it from reaching other plugins, is it supposed to? I don't think super_cancel() does anything special either, unless I'm missing something. Right now i'm not using play-dirty mode, but i've tested it in both.

Thanks for responding, good luck with the problem.

Comment by LadyCailin

It does mean that, unfortunately. If CH fights with other plugins, the results are completely undefined. The way that bukkit does events is really quite terrible compared to most other event frameworks out there, mine is based more on javascript's event framework, with a few added features that are only possible with mscript. And actually, consume and lock only affect other CH scripts, not other plugins, because consuming the event is impossible with bukkit (since the higher priority handlers expect to be able to get them, but they run second), and locking individual parameters is also impossible with the bukkit event. These are extra states that are separately maintained by CH, and once CH is done with the event and it is passed to other plugins, that extra data is completely lost. This has caused some frustrations in the past for users that are trying to override another plugin's event handling, and they don't ignore cancelled events. Btw, cancel() does work to cancel the underlying bukkit event, though plugins are free to ignore that flag.

super_cancel() is completely broken, and I have no real intention of fixing it, because play-dirty mode is currently completely broken. What it did previously was to replace the bukkit event handling system with CH's custom event handler (using incredibly evil and fragile techniques) to basically allow consume() to work for other plugins.

I wish Bukkit would implement a better event system, but since they haven't, I cannot match up the CH events 1:1 with bukkit events. What has been suggested in the past is to have a second framework for events that mscript can attach to that works exactly like the bukkit framework, and then all data would just be passed through. I'm not sure how I feel about this, since it cheapens the CH event framework, and would also be exceedingly difficult to implement without support for objects yet. Hope that answers all your questions!

Comment by Tom.Gebbett

It does, thank you for giving such a comprehensive answer. That is an unfortunate situation, but you aren't expected to do anything that is unmaintainable, what you've done so far is more than enough :)

Comment by Tom.Gebbett

I wrote a system to emulate the CommandHelper binds system, but it's all within a single bind (with almost no overhead). This has helped, but not as much as I had hoped. There is still some optimisation I can do with the code in the binds, so once that's done, I think this won't be much of a problem.

This is in the latest build, server is 1.7, didn't test the latest on 1.6.4 in the end.

Comment by PseudoKnight

Could this be an inaccuracy in the measurement method? I see nothing significantly wrong in a Spigot timings report, for example. Though I should try and replicate the exact setup.

Comment by Tom.Gebbett

Well, unless nano_time() is broken, it's certainly true that the server is running the event for the time between the two calls. The variances in time reported that I mentioned seem to indicate the problem is with CommandHelper and the measurements of my code itself indicate that that isn't the problem.

I am of course, not certain that what I'm saying is accurate, but mentioning it here should help us find a solution either way.

I just thought of something that could theoretically be causing it, but I can't test it now. I'll report back on it later.

Thanks for the suggestion and information :)

Comment by Tom.Gebbett

Well, I figured out the problem. I don't know if anyone else has tested events timings with an auto_include.ms file of over 75,000 characters, which include()s 18 other utilities files of varying lengths (totalling about 160,000 characters).

I assumed that include() just adjusted some variable controlling procedure scope, but it seems to run through the entire file, including every procedure and running extraneous code.

Running through all the include files was taking over 0.5ms per bind, often double or more, which doesn't sound like much on its own, but with several binds running many times per second, it all adds up. The single-bind system is speeding things up because it is only including the utilities files once. Since I fixed the problem, it isn't really necessary to use it.

Using the constant inclusion system was only really necessary in older versions of my various systems, I can now just include those files once and their procedures will always be available, so that's what I'm doing now, and the inclusion takes only about 0.04ms. (there are still a few tiny bits of code in auto_include.ms).

The disadvantage of this is not being able to access any procedures in aliases, but since the server_command event works, I don't need to use aliases. (except in rare cases where commandblocks are needed for something.)

Now that I've fixed this, the bottleneck is my own code, and the actual overhead of the bind system is almost nothing. Apologies if I seemed accusatory in my initial explanation.

To clarify, this doesn't seem to be a bug or problem with CH, but perhaps it would be a good idea to do one or both of the following:

1. cache inclusion scope states, instead of individually including every procedure (apologies if my vague understanding of the underlying code is incorrect)
2. document the potential overhead of constantly including large files, recommend that users avoid putting every procedure in auto_include.ms.

Thank you both for your help on this issue.

Comment by LadyCailin

Optimizing includes is planned in future versions, for now, it just naively re-runs all includes. Procs individually should have low overhead, but will add up eventually, if you have enough. This is a known problem, at least to me, which is why I've got future plans for optimizing this. I have plans to make includes work more so like Java's import, that is, it can't be dynamic, and it can only include "non executing" code, that is, only procs or includes. The dynamic includes are already warned against, but not enforced. In future versions they will be enforced, as well as the non-executing code bit. Once this happens, procs can be stored away with scope information, and the includes will never actually be re-run. http://forum.sk89q.com/threads/possible-breaking-design-change-thoughts.1526/ See this post for a more detailed writeup of future plans.

Regardless, I'm glad the overhead isn't the bind system, as I was under the impression that it was relatively efficient, so that's good to know that the overhead is with an already known issue. Closing as invalid. Thanks!