This article outlines the reason behind, and usage of, the gap metering extension included in Satoris which unlike possibly all other application performance monitoring solutions focuses on what transpires between consecutive service request processing by a particular thread for the same entry point method. Measuring, or metering, the gap between consecutive root method invocations is important in trading environments as it offers an insight into possible performance bottlenecks further upstream (before) in the order submission. If throughput for each thread within a JVM process is tracked then observing and analyzing the gap between events, that constitute the actual throughput work, is incredibly important. The larger the gap the less throughput achieved. In some low latency environments that gap can be far greater than the service time but yet it is not readily observed or analyzed.
But how can an activity based metering engine track and present what is effectively a blind spot outside of any measured activity? It’s a strange sort of performance blind spot because nothing is actually occurring in terms of what is observed – call invocations. The gap metering extension addresses this by assigning the time, or metering, differences between the end of the last activity and the beginning of a new activity, by the same thread, to the subsequent activity. For every meter enabled within the metering runtime the gap metering extension creates an additional meter that is prefixed with "gap". The changes in the underlying meter measure are effectively carried forward into the new activity and assigned to it. This only happens if both the previous and next (current) activities are the same probe name.
Here is a simple snippet of code that will be used to demonstrate the gap metering extension in action. The outer() method, called repeatedly in a while loop, will initially represent the actual service entry point. The call spin(50_000L) will be the gap that occurs between each consecutive outer() call. The outer method takes approximately 125 microseconds to execute with 100 microseconds spent within outer and 25 microsecond within inner, called by outer. The spin method is not instrumented.
Below is a sample metering snapshot of the above code executed within the Satoris agent loaded. The gap metering has not been enabled yet so we only have the basic clock.time meter included in the model.
Here is the software execution behavior visualized by the blink metering extension. The white bar represents the outer method and the green the inner.
The following jxinsight.override.config file enables the gap metering extension and excludes main method from being augmented by the gap metering extension.
j.s.p.gap.enabled=true j.s.p.gap.filter.enabled=true j.s.p.gap.filter.exclude.name.groups=samples.Gaps.main
Below is a sample snapshot of the resulting performance metering model. There are now two metering rows per probe name – clock.time and gap.clock.time. The only probe to have an actual value assigned to the gap.clock.time total column is samples.Gap.outer. The average gap.clock.time for outer is 51 microseconds. Close to the explicit delay placed in the code.
In the following revised configuration the gap metering extension augmentation is restricted to the inner method.
j.s.p.gap.enabled=true j.s.p.gap.filter.enabled=true j.s.p.gap.filter.include.name.groups=samples.Gaps.inner
The following table is sample of a metering model generated with the above configuration applied. Note that both outer and inner have gap.clock.time metering assignments. That is because inner method is enclosed, executed, within the scope of outer method so any metering changes applied to inner method (probe) will propagated upwards the caller (probe) chain. Only the inner method has the inherent (self) gap.clock.time attributed to it. The average has also changed from 51 microseconds to 152 microseconds because the gap now relates to time interval between consecutive calls of inner and not outer.
