Skip to content

Case Study: Scala Compiler – Part 7

This is the seventh part in a series of articles on the “how to of software performance analysis” using JXInsight/OpenCore. Please read the first, second, third, fourth, fifth and sixth parts as well as the preamble before proceeding if you have not already done so. If that sounds like too much work then at least read part 4 , part 5 and part 6.

Up to this point in the series we have obsessed over how to capture in our metering model the most important execution behavior of a performance test and at the lowest measurement overhead and in doing so eliminating noise and measurement error as much as possible. We have gone from metering 16.5 billion calls in the Scala compiler codebase to metering just under 1 million calls using intelligent activity metering extensions. In this part we move from instrumentation and measurement to collection augmenting the metering model with additional statistical and behavioral data structures.

The quantization metering extension can help us capture and understand the range(s) and distribution of metering values recorded for fully qualified metered probes. Enabling this collection extension is as easy as dynamic metering extensions.

jxinsight.server.probes.quantization.enabled=true

By default this enhancement will be applied to all metered probes (methods in our case study). This is generally overkill so lets limit the enhancement to our main entry point in the execution.

jxinsight.server.probes.quantization.filter.enabled=true
jxinsight.server.probes.quantization.filter.include.name.groups=scala.tools.nsc.Global$GlobalPhase.applyPhase

Here is the metering distribution (in powers of two) for the applyPhase method rendered in the management console. There are some outliers (> 100,000 microseconds) which contribute significantly to the overall metering total for the performance test.

We can use the transaction metering extension to determine what actually transpired (changed) during the execution of those methods which exceeded the 100,000 clock.time meter mark.

jxinsight.server.probes.transaction.enabled=true
jxinsight.server.probes.transactions=phase
jxinsight.server.probes.transaction.phase.name.groups=scala.tools.nsc.Global$GlobalPhase.applyPhase
jxinsight.server.probes.transaction.phase.meter=clock.time
jxinsight.server.probes.transaction.phase.threshold=100000

The above will result in metering change sets being collected within our metering model for each metering of the applyPhase which exceeded 100,000 in wall clock. A metering change set is effectively a metering model within a metering model representing the metering changes that occurred at the thread level within the metering model during the execution of the applyPhase method. Its not a trace or a path. Its a true transaction in the sense that it models (ex)change(s) in state – in this case the state is the metering model itself (associated with the executing thread).

Below are four transactions within the metering model that have been partially expanded revealing strong similarities in the metering change sets in terms of the (proportional) inherent total across the typechecker, ast and transform packages.

This view can also help reveal behavioral differences across different executions of the applyPhase method. From the three transactions shown below we can see different classes appearing under packages common to transactions as well as packages that only appear in one transaction such as matching in the second transaction and backend in the third transaction. From this information new transaction types can be defined starting at a lower and more specific entry point in the metered execution and/or using behavioral trait metering extension to more cleanly demarcate the metered work.

Metering transactions can be filtered on the occurrence of a particular probe name within the transactions underlying metering change set. This is incredibly useful when we have identified a problem probe (or group) in one transaction and what to compare its resource (meter) consumption profile across other similar transactions.

In the next part we will look at one of the major reasons for latency slow downs, garbage collection (GC), and its primary driver – object allocations.