Startup performances

[CeylonMigrationBot]

[@loicrouchon] I've noticed that it takes quite some time to startup a ceylon program.

I made the following tests:

Simple hello world program in both java and ceylon

Java version:

public class Hello {
  public static void main(String[] args) {
    System.out.println("hello");
  }
}

compiled with javac Hello.java and run with time java Hello
In average:

real    0m0.060s
user   0m0.050s
sys    0m0.012s

ceylon version:

shared void run(){
  print("hello");
}

compiled with ceylon compile hello and run with time ceylon run hello
In average:

real    0m1.445s
user   0m1.050s
sys    0m0.074s

Ceylon: lastest version from git
Java: openjdk "1.7.0_25"
OS: Ubuntu 13.10 64bits

I don't know if it's those differences are because of JBoss modules initialization, ceylon.language classloading or because of some specific ceylon startup process I'm not aware of.

I'm not really concerned about the fact that it's slower than java, but I would like to know if this can be improved to something more acceptable for command line tools like ceylon.build (below 200ms would be a great start)

[Migrated from ceylon/ceylon-runtime#53]

[CeylonMigrationBot]

[@tombentley] The tool stuff is another possible culprit

[CeylonMigrationBot]

[@alesj] Or that model generation?

• https://github.com/ceylon/ceylon-runtime/blob/master/impl/src/main/java/ceylon/modules/jboss/runtime/UtilRegistryTransformer.java#L62

[CeylonMigrationBot]

[@FroMage] So half of that time is spent trying to find the module version. If you run with ceylon run hello/1 you will see it takes about 800ms instead of 1500ms.

[CeylonMigrationBot]

[@FroMage] The biggest offenders:

• CeylonTool.getTool: 120ms
• checkModuleVersionsOrShowSuggestions: 600ms
• starting JBoss modules: 180ms
• creating JBoss modules class loader: 141ms
• Metamodel init: 91ms
• running the Ceylon code: 200ms

Total of the biggest offenders: 1332ms

[CeylonMigrationBot]

[@FroMage] checkModuleVersionsOrShowSuggestions appears to be 200ms when --offline, so the online part is only 400ms

[CeylonMigrationBot]

[@quintesse] Yes, the looking up of possible versions comes at a cost, and I agree that it seems pretty high. Most of that probably comes from somewhere deep down in the CMR. For what it does (in most cases just seeing if certain files exists in a certain directories) it seems a bit much.

[CeylonMigrationBot]

[@quintesse] Btw, one thing I had been thinking about to prevent the online cost on each invocation is to only query the online repositories if zero or multiple versions were found locally (cached or otherwise). Of course that would make the failure case (no versions exist neither locally nor online) even slower.
(edited for correctness: multiple versions also trigger this situation)

[CeylonMigrationBot]

[@FroMage] Yeah, so I'm improving it so that it will use whatever version is already compiled in the current output folder if there's only one, or whatever version is present in source. That's a lot faster.

[CeylonMigrationBot]

[@FroMage] Actually running it is just 10ms, my bad.

[CeylonMigrationBot]

[@FroMage] I've made several improvements and now finding a compiled module or a source module is a lot faster. There's still improvement to be done in CeylonTool.getTool (sure we can bring this down from 120ms), let's see if I can find something obvious.

[CeylonMigrationBot]

[@FroMage] Note that for some reason, parsing a single module file takes 150ms. I guess from initialisation of AntLR?

[CeylonMigrationBot]

[@FroMage] Added related #1631 for compiler speed for trivial modules.

[CeylonMigrationBot]

[@tombentley]
CeylonTool.getTool indirectly ends up doing a lot of reflection in order to instantiate the tool and inject it according to the arguments given on the command line It has to build a whole model of the tool to do this. That's pretty inefficient given that the model won't be reused and all this is standing in the way of actually running the program.

One thing which would speed it up a lot was if, for each tool, we generated a class (using an annotation processor) which did the parsing for that tool. That way the main tool would only need to instantiate the relevant class and give it the command line arguments, and all the reflection would be avoided. But that's a lot of work.

It has been noted that our tooling is a lot like JBoss forge, and I would have suggested that in the long term we look to use that. But then it turns out that their performance isn't great either

[CeylonMigrationBot]

[@FroMage] Do you think alternative reflection libs would help?

[CeylonMigrationBot]

[@tombentley] No idea. What, specifically, did you have in mind?

[CeylonMigrationBot]

[@FroMage] Nothing, just wondering if something like Scannotation would be faster.

[CeylonMigrationBot]

[@FroMage] Hah, it looks like the main issue is that we create lots of models instead of just one ;)

[CeylonMigrationBot]

[@tombentley] I don't think Scannotation would help because fundamentally something has to instantiate the tool and call a bunch of setters. AFAICS, Scannotation cannot make invoking those setters any faster. Maybe using method handles would help. But avoiding any kind of reflection would be fastest.

[CeylonMigrationBot]

[@FroMage]

[0ms] getToolModel for ''
[37ms] getToolModel done
[41ms] getToolModel for 'run'
[154ms] getToolModel done
[154ms] getTool bind for 'run'
[163ms] getTool bind done
[164ms] getToolModel for 'run'
[175ms] getToolModel done
[175ms] getTool bind for 'run'
[176ms] getTool bind done
[177ms] getToolModel for 'run'
[185ms] getToolModel done
[185ms] getTool bind for 'run'
[187ms] getTool bind done

[CeylonMigrationBot]

[@tombentley] Mmm, well that looks stupid.

[CeylonMigrationBot]

[@FroMage] So once I removed a few too many instantiations of Tool, I am down to finding that iterating /usr/bin to detect path plugins takes about 100ms. I cut it down to 40ms using NIO2 and changing the order of the file tests.

[CeylonMigrationBot]

[@tombentley] Out of interest what's the cost of CeylonTool.getTool() now?

[CeylonMigrationBot]

[@FroMage] So now, a Hello World runs in 800ms. I'm going to stop optimisation for 1.1, and move this issue to 1.2 when we have more time.

[CeylonMigrationBot]

[@FroMage] The whole tool setup seems to be around 140ms now.