Documentation / Enhancement

Enhancement

Quick links:

Maven Plugin

The maven plugin uses the agent to enhance the classes. You need to specify the packages that you want the agent to search for classes that it should enhance.

packages

The packages specified are scanned for classes annotated with @Singleton, @Path, @Service etc as well as the Avaje Metrics @Timed annotation.

debug=0..9

In the transformArgs element you can specify a debug level from 0 to 9 which provides some debug logging of what the enhancement process is doing. 

<build>
  <plugins>

    <plugin>
      <groupId>org.avaje.metric</groupId>
      <artifactId>enhance-maven-plugin</artifactId>
      <version>4.2.1</version>
      <executions>
        <execution>
          <id>main</id>
          <phase>process-classes</phase>
          <configuration>
            <packages>org.example.myapp.**</packages>
            <transformArgs>debug=1</transformArgs>
          </configuration>
          <goals>
            <goal>enhance</goal>
          </goals>
        </execution>
      </executions>
    </plugin>

  </plugins>
</build>

Agent

The agent utilises ASM (repackaged and included with the agent) to perform the enhancement. Most often I'd expect people to not use the agent directly and instead use the maven plugin but you certainly can. You can use the agent using the usual javaagent command line and alternatively you can load the agent at runtime using the avaje-agentloader.

Maven artifact
<dependency>
  <groupId>org.avaje.metric</groupId>
  <artifactId>avaje-metric-agent</artifactId>
  <version>4.2.1</version>
</dependency>

If you want to find out exactly how the enhancement works you want to review the source code for the agent.

metric-name-mapping.txt

When the agent starts it searches for all metric-name-mapping.txt resources in the classpath. These resources are loaded using Properties and are expected to be in properties format of name=value pairs per line. These name=value pairs are then sorted by longest name ... and this is the order in which they are searched in order to transform/truncate the default metric names (of package.Class.method) into typically shorter metric names that often have common prefixs like web.api etc.

Bytecode specifics

So when the agent determines that a particular class should be enhanced it adds some bytecode. The source for this is at https://github.com/avaje-metric/avaje-metric-agent.

ADD STATIC FIELDS

Say the agent determines that there are 3 methods that it is going to enhance and 2 of those are TimedMetric and the 3rd is a BucketTimedMetric. The agent will generate bytecode that is equivilent to the Java code below. 

// Add one static field for each method
private static TimedMetric _$metric_1;
private static TimedMetric _$metric_2;
private static BucketTimedMetric _$metric_3;

// create a static initialisation block if
// one does not already exist. Otherwise add
// the _$initMetrics() to the existing one.
static {
  _$initMetrics();
}

// Add this method to initialise each metric
private static void _$initMetrics() {
  _$metric_1 = MetricManager.getTimedMetric("simpleSerivce.doSomething");
  _$metric_2 = MetricManager.getTimedMetric("simpleSerivce.doSomethingElse");
  _$metric_3 = MetricManager.getTimedMetric("simpleSerivce.doBucketSomething", 100, 200);
}
...

Having the _$initMetrics() method means that is it easy to either add the static initialisation block or add the call to _$initMetrics(); to an existing static initialisation block.

Note that the metric names and bucket ranges have been determined at this point.

ENHANCE METHODS

Each timed method is enhanced using the ASM AdviceAdapter. In Java terms it looks something like the code below. 

public void doSomething() {

  // local variables to store the start nanos
  // and active status of the 'Per request' timing
  boolean _$metricActiveThreadContext = _$metric_1.isActiveThreadContext();
  long _$metricStart = System.nanoTime();
  try {

    // The original method code in here ...
    ...

    // opCode is one of the return opcodes;
    _$metric_1.operationEnd(opCode, _$metricStart, _$metricActiveThreadContext);

  } catch (RuntimeException e) {

    // opCode = ATHROW;
    _$metric_1.operationEnd(opCode, _$metricStart, _$metricActiveThreadContext);
    throw e;
  }
}

Note that there was a conscience decision to have the operationEnd() method on TimedMetric and BucketTimedMetric and pass the opcode and start nanos. This was so that the added bytecode was as simple and minimalist as possible. In the case where you want to turn off metric collection with enhanced code the added bytecode is still executed but the TimedMetric.operationEnd() method is a NOOP. The operationEnd() methods do look a little clunky on the API but it serves a reasonable purpose.

Overhead

The overhead of an enhanced method should be in the order of 140 nanoseconds. Micro benchmarks are notoriously difficult but I believe 140 nanoseconds to be a good indication of the overhead added by the timed metric enhancement.

For perspective, executing approx 7000 methods with an overhead of 140 nanoseconds would add 1 millisecond to execution time.

DOCUMENTATION