Case Study: Scala’s Compiler – Part 1
This is the first part in a series of articles on the “how to of software performance analysis” using JXInsight/OpenCore. Please read the preamble before proceeding if you have not already done so.
Most developers would expect that in the initial phase of a performance investigation that you would start immediately looking to find the latency hotspots using timers (or time based meters). But the problem here is that with a relatively unknown code base you can’t be sure what exactly you are measuring, how you should be measuring it and how will the resulting performance model be impacted by the overhead in instrumentation, measurement and collection. Then there is the question of which measurement technique to use: sample or event based (or a combination)?
With an application that has challenged other performance measurement tools you need to start with the activities that drive the cost (overhead) and cause of such solutions to fail – the measured method executions. So for us we start with using our probe.count meter with our strategy based metering extension disabled because we are not concerned about timing (or the impact of measurement) at least in the case of this case study which is a single threaded test with no temporal dependencies in the workload generation.
Below are a series of screenshots of our console displaying the metering snapshot generated following the completion of the test script listed at the bottom of this page along with the configuration of the metering runtime.
In the first screenshot we can see that in compiling the compiler’s own source code more than 16.5 billion method calls within the scala.* and ch.* packages have been metered. Considering that this test normally executes in 2 minutes, compiling 367 scala files, without any instrumentation we can very quickly understand the challenge it presents especially as some of these solutions have an overhead unit cost of 600 ns which comes to 2.7 hours for this test. We will come back to this in a future article in the series.
Here is the same metering model with the scala.* package expanded. The biggest contributor is scala.tools.* with 9.6 billion calls and scala.collection.* with 4.7 billion calls.
Below is the metering model with the scala.tools.ncs.* package expanded. The biggest contributor is scala.tools.nsc.symtab.* with 7.5 billion calls.
In the scala.tools.ncs.symtab.* package the biggest contributors are classes Symbols$Symbol and SymbolTable with 2.3 and 1.3 billion calls respectively.
The biggest contributor within the scala.tools.nsc.symtab.Symbols$Symbol class is the method(s) named scala$tools$nsc$symtab$Symbols$Symbol$$$outer with 0.6 billion calls.
What is much more useful to know is which packages, classes and method drive the execution of other methods and in particular in other classes and packages. The following metering table screenshot allows us to do this.
The Count column represents the number of times a method was executed or in the case of aggregates the number of times a method within a particular class or package (included nested packages) was executed.
The Total column represents the number of (nested) method executions metered within the scope of a metered method’s execution. For example in executing 0.34 billion calls in package scala.tools.nsc.typechecker a total of 8.8 billion calls were made directly or indirectly.
The Total (I) column, with (I) standing for inherent which is called self in other solutions, allows us to see the number of methods executed directly from within a particular method. For example scala.tools.nsc.symtab.Symbols$Symbol.rawinfo made on average 13 direct calls and 21 direct and indirect calls.
Here is a listing of the top number of executed (and metered) methods during the test.
Having this frequency information can be useful especially when drafting filtered instrumentation sets as well as measurement strategies. It can also be used to already direct tuning efforts as the smallest of cost savings within a particular method can globally be significant (if the frequency is sufficiently high). In addition this information can be used to forewarn those of the performance sensitivity of certain areas in the code base.
But first and foremost this initial exercise is all about building the underpinnings (a reference point) for future knowledge acquisition, investigation and analysis. Clearly our metering runtime can’t meter the execution of 16.5 billion calls without perturbing the system so we (and it) are going to need to reduce this number down to a few million. The art and skill will be in how we do this whilst ensuring the resulting model remains useful, relevant and accurate.
In the next part we move onto using an extremely useful metering extension, tierpoint, that helps build up a scalable and relevant model, both in the tool and in our own mind, of the call flow whilst tackling the issue of the HUGE (nearly 2000 deep) call stack.
[script]
../../bin/scalac -J-agentpath:/OpenCore/bin/osx-64/libjxinsight.jnilib=prod -J-javaagent:/OpenCore/bundle/java/default/opencore-ext-aj-javaagent.jar -J-noverify -J-Xmx1024M -nobootcp -d classes @classes.list
[jxinsight.override.config]
jxinsight.server.probes.console.enabled=true
jxinsight.server.probes.meter.clock.time.include=false
jxinsight.server.probes.meter.probe.count.include=true
jxinsight.server.probes.strategy.enabled=false
[jxinsight.aspectj.filters.config]
scala.
ch.