Profiling Sculptor generation via YourKit

[Ron Smith]

I tried out profiling Sculptor generation using YourKit, and was able to get some good results.  Haven't identified any performance improvements yet, but the profile results show what methods are taking longer.

I executed the Sculptor Generator in Maven, and set up YourKit to start profiling beginning with the SculptorGeneratorRunner.doRun method.  I attached a report of a part of the call tree view to this post, showing the hierarchy of method calls & their timings.

Following are my notes on setting up and using YourKit with Sculptor:

http://rpstechnologies.net/ron/blog/2013/10/profiling-maven-sculptor-execution-using-yourkit/

Also, I exported a profiling snapshot of the example library code generation run.  You can open this file in YourKit via File->Open Snapshot, and review all of the results captured by the profiler.

https://dl.dropboxusercontent.com/u/84534130/Launcher-2013-10-26-shutdown-12.snapshot

I'm using a YourKit evaluation license.  They offer a free license for developers of active open source projects, which we may want to look into if this works well.

http://www.yourkit.com/purchase/

Ron

[Pavel Tavoda]

Hello Ron,

nice you start to dig this direction. Can you select methods which require some optimization (e.g. caching)?

Pavel

[Ron Smith]

Life got very busy so I haven't been able to get back to this till today.  Attached (profilingResults.zip) are some profiling results of running sculptor generation on the library example via Maven.

I turned on detailed tracing, which slows down execution, so don't pay attention to the absolute execution times of methods, as they'll be significantly higher than normal execution.  But we can focus on the relative times between methods.

The overall execution time was 8,649 ms

See CPU-hot-spots.html.  This is a list of the most time consuming methods.

You can see loading classes takes a significant amount of time (3,087).

Longer term, maybe we could support a mode where Sculptor is kept loaded & initialized in memory within Eclipse, and can be triggered to generate on demand and/or based on model file changes, avoiding class loading & initializing each generation run.

Another hotspot is java code formatting (1, 276).  See helperFileOutput-Merged-callees.html.

DomainObjectTmpl.domainObject() takes 717 ms.  See domainObjectBase-Merged-callees.html.

Of the 717 ms, 328 ms + 112 ms is Helper.fileOutput, which calls the java code formatter mentioned above.  The rest, 277 ms is DomainObjectTmpl and DomainObjectPropertiesTmpl generator code we could look to optimizing.

The last set of results I included are for ChainOverrideAwareModule.configure(), which took 353 ms.  See chainOverrideAwareModuleConfigure-Merged-callees.html.

It looks like there's some opportunities to optimize this, in particular ChainOverrideAwareModule.discoverInjectedFields() which is called in two branches, taking 65 ms + 33 ms.

I was thinking of a good place to publish these results going forward...  What do you think of using github?  We could create a separate repository so it doesn't clutter the main repository and trigger CI builds.

Ron