CMDHELPER-2850 - Reported by EntityReborn

We are all aware CH takes forever and a day to start up during boot of the server. This is more a REMINDER issue than anything.

{{[z]}} proposes a fix, namely adding the following to ClassDiscovery:GetClassContainer before {{return new URL(packageRoot);}}:

	packageRoot = StringUtils.replaceLast(packageRoot, "!/", "");
	packageRoot = packageRoot.replaceFirst("jar:", "");
}```

The rationale behind this is https://github.com/sk89q/commandhelper/blob/master/src/main/java/com/laytonsmith/PureUtilities/ClassLoading/ClassDiscovery.java#L272 accounts for {{jar:...!/}} URL paths, yet https://github.com/sk89q/commandhelper/blob/master/src/main/java/com/laytonsmith/PureUtilities/ClassLoading/ClassDiscoveryCache.java#L77 doesn't.

I will personally do a small amount of testing to determine no immediate side effects, and proceed to submit a PR if I like what I end up with.

Comment by EntityReborn

Before the above change:
{{[13:48:41 INFO]: Done (82.633s)! For help, type "help" or "?"}}
After:
{{[14:13:36 INFO]: Done (17.494s)! For help, type "help" or "?"}}

Comment by CyaNox

My tests seem to confirm a large change as well:

{code:title=linux_withoutpatch}
time java -jar CommandHelper.jar cmdline empty.ms
real 0m7.675s
user 0m8.005s
sys 0m0.752s

{code:title=linux_patched}
time java -jar commandhelper-3.3.1-SNAPSHOT.jar cmdline empty.ms
real    0m1.808s
user    0m2.356s
sys     0m0.100s

{code:title=windows_withoutpatch}
PS D:\DEV\commandhelper\testrun> Measure-Command {start-process java -argumentlist "-jar commandhelper-3.3.1-SNAPSHOT.jar cmdline empty.ms" -Wait}
Days : 0
Hours : 0
Minutes : 0
Seconds : 12
Milliseconds : 886
Ticks : 128861428
TotalDays : 0.000149145171296296
TotalHours : 0.00357948411111111
TotalMinutes : 0.214769046666667
TotalSeconds : 12.8861428
TotalMilliseconds : 12886.1428

{code:title=windows_patched}
PS D:\DEV\commandhelper\testrun> Measure-Command {start-process java -argumentlist "-jar commandhelper-3.3.1-SNAPSHOT.jar cmdline empty.ms" -Wait}
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 2
Milliseconds      : 495
Ticks             : 24957811
TotalDays         : 2.88863553240741E-05
TotalHours        : 0.000693272527777778
TotalMinutes      : 0.0415963516666667
TotalSeconds      : 2.4957811
TotalMilliseconds : 2495.7811

Comment by LadyCailin

Edit: After re-reading the bug and speaking with [z] in IRC, I realize I misunderstood the nature of the report. I'm leaving the rest of this because I spent time typing it up, and I still would like to implement my proposed changes. However, carry on :)

Commenting here for the sake of visibility, though most involved may have already heard about this:

Yes, this is a known issue. The change made to permgen (I can't find the exact commit offhand) to prevent CH from using up a ton of permgen, by duplicating the reflection logic that is natively implemented in the JVM. Unfortunately, using the native reflection methods (namely Class.forName or equivalents) caused the class files to be loaded in memory, which is fine, as long as they get garbage collected, but actually they get loaded in the special "[permgen|https://blogs.oracle.com/jonthecollector/entry/presenting_the_permanent_generation]" section of memory, which the JVM more precisely controls. This too is not a huge issue, one could simply increase the amount of permgen available to the JVM at startup with the -XX:MaxPermSize=128M option. However, for many people, this isn't possible, due to some server hosts limiting control of the startup parameters. This led to the case of some people simply not being able to use CommandHelper at all, obviously a bad thing.

So I switched over to manually scanning the class files, and parsing the data that I needed out of them. This is ultimately the same data returned by the reflection methods, but this came at a higher overhead. But the key is that this overhead is in normal heap space, not permgen, therefore allowing the JVM to run it with default settings. The largest time spent during startup is during the scanning of the class files. It scans all class files in the CH jar, the bukkit jar, and any extensions. CH and extensions are relatively small, so that doesn't take very long, but scanning bukkit does take a while due to the sheer size. So I added caching to all files. In plugins/CommandHelper/.cache, you'll see various files which are caches of each jar scan. The very first time it starts up, it runs these scans, and creates that cache files. If you delete the cache files, you'll actually notice a significant slow down the first time.

However, even these cache files are quite large. They still take several seconds to read in and process, even though they are efficiently stored as native serialized objects. This is a naive but guaranteed approach: there are a number of fallbacks in place to ensure that all data can be gathered each time reliably, but if faster methods of answering the queries are available, they will use those. This provides a good "failsafe" so that CH will always be functional, if not efficient. As it stands, I do not want to ever get rid of this base functionality, though we can perhaps go one further. The main cache files contain ALL annotation data for the jars, which is in fact overkill for what CH actually needs.

So on to the proposal that I will eventually implement: Add an extra layer of caching to cache individual calls' returned data, down to the level of the individual functions. This means that instead of having one large cache file, have smaller, individualized cache files that answer just the one specific query. These can be pre-generated or dynamically generated and stored on disk, same as the existing large caches. However, with a smaller file size, reading in and processing these files should take less time. There are currently only 3 calls that are known to need caching, reading in the Event classes, reading in the Function classes, and dynamically finding the bukkit classes (currently only used in sudo()). The first two are easy. CH and any CH aware extensions could be forced to pre-cache this data via annotation processors, and otherwise cached at runtime. The tricky bit is figuring out the search space for the ClassDiscovery.fuzzyForName methods. This requires knowing all class names, but again, this is data that can be separately and specifically cached after the first call.

All this said, this should be a low priority task. Startup time is less of a concern (though still a very real concern) than mid app run time. However, I admit, it's a very visible problem compared to other issues, and seems to be giving the rest of the plugin a bad rap, so it may be worth dealing with sooner rather than later.

Comment by LadyCailin

Ok, I went ahead and added that code in and committed. I guess I'm going to close this bug, since the wall of text I wrote isn't really applicable to this bug.