Timing breakdown

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java

@@ -374,7 +374,7 @@ public void endSpan(Span span) {
         if (span.isSampled()) {
             long spanFramesMinDurationMs = stacktraceConfiguration.getSpanFramesMinDurationMs();
             if (spanFramesMinDurationMs != 0 && span.isSampled()) {
-                if (span.getDuration() >= spanFramesMinDurationMs) {
+                if (span.getDurationMs() >= spanFramesMinDurationMs) {
                     span.withStacktrace(new Throwable());
                 }
             }

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/AbstractSpan.java

@@ -28,6 +28,7 @@
 import java.util.concurrent.Callable;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
 
 public abstract class AbstractSpan<T extends AbstractSpan> extends TraceContextHolder<T> {
     private static final Logger logger = LoggerFactory.getLogger(AbstractSpan.class);
@@ -40,18 +41,70 @@ public abstract class AbstractSpan<T extends AbstractSpan> extends TraceContextH
     protected final StringBuilder name = new StringBuilder();
     private long timestamp;
 
-    /**
-     * How long the transaction took to complete, in ms with 3 decimal points
-     * (Required)
-     */
-    protected double duration;
+    // in microseconds
+    protected long duration;
+    protected ReentrantTimer childDurations = new ReentrantTimer();
     protected AtomicInteger references = new AtomicInteger();
     protected volatile boolean finished = true;
 
     public int getReferenceCount() {
         return references.get();
     }
 
+    public static class ReentrantTimer implements Recyclable {
+
+        private AtomicInteger nestingLevel = new AtomicInteger();
+        private AtomicLong start = new AtomicLong();
+        private AtomicLong duration = new AtomicLong();
+
+        /**
+         * Starts the timer if it has not been started already.
+         *
+         * @param startTimestamp
+         */
+        public void start(long startTimestamp) {
+            if (nestingLevel.incrementAndGet() == 1) {
+                start.set(startTimestamp);
+            }
+        }
+
+        /**
+         * Stops the timer and increments the duration if no other direct children are still running
+         * @param endTimestamp
+         */
+        public void stop(long endTimestamp) {
+            if (nestingLevel.decrementAndGet() == 0) {
+                incrementDuration(endTimestamp);
+            }
+        }
+
+        /**
+         * Stops the timer and increments the duration even if there are direct children which are still running
+         *
+         * @param endTimestamp
+         */
+        public void forceStop(long endTimestamp) {
+            if (nestingLevel.getAndSet(0) != 0) {
+                incrementDuration(endTimestamp);
+            }
+        }
+
+        private void incrementDuration(long epochMicros) {
+            duration.addAndGet(epochMicros - start.get());
+        }
+
+        @Override
+        public void resetState() {
+            nestingLevel.set(0);
+            start.set(0);
+            duration.set(0);
+        }
+
+        public long getDuration() {
+            return duration.get();
+        }
+    }
+
     public AbstractSpan(ElasticApmTracer tracer) {
         super(tracer);
         traceContext = TraceContext.with64BitId(this.tracer);
@@ -62,13 +115,20 @@ public boolean isReferenced() {
     }
 
     /**
-     * How long the transaction took to complete, in ms with 3 decimal points
-     * (Required)
+     * How long the transaction took to complete, in µs
      */
-    public double getDuration() {
+    public long getDuration() {
         return duration;
     }
 
+    public long getSelfDuration() {
+        return duration - childDurations.getDuration();
+    }
+
+    public double getDurationMs() {
+        return duration / AbstractSpan.MS_IN_MICROS;
+    }
+
     /**
      * Generic designation of a transaction in the scope of a single service (eg: 'GET /users/:id')
      */
@@ -122,6 +182,7 @@ public void resetState() {
         timestamp = 0;
         duration = 0;
         traceContext.resetState();
+        childDurations.resetState();
         references.set(0);
     }
 
@@ -164,10 +225,11 @@ public void end() {
 
     public final void end(long epochMicros) {
         if (!finished) {
-            this.duration = (epochMicros - timestamp)  / AbstractSpan.MS_IN_MICROS;
+            this.duration = (epochMicros - timestamp);
             if (name.length() == 0) {
                 name.append("unnamed");
             }
+            childDurations.forceStop(epochMicros);
             doEnd(epochMicros);
             // has to be set last so doEnd callbacks don't think it has already been finished
             this.finished = true;
@@ -231,9 +293,11 @@ public void setStartTimestamp(long epochMicros) {
 
     private void onChildStart(Span span, long epochMicros) {
         incrementReferences();
+        childDurations.start(epochMicros);
     }
 
     void onChildEnd(Span span, long epochMicros) {
+        childDurations.stop(epochMicros);
         decrementReferences();
     }
 

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java

@@ -190,6 +190,9 @@ public void doEnd(long epochMicros) {
         if (type == null) {
             type = "custom";
         }
+        if (transaction != null) {
+            transaction.incrementTimer(getType(), getSelfDuration());
+        }
         if (parent != null) {
             parent.onChildEnd(this, epochMicros);
         }

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java

@@ -22,10 +22,15 @@
 import co.elastic.apm.agent.impl.ElasticApmTracer;
 import co.elastic.apm.agent.impl.context.TransactionContext;
 import co.elastic.apm.agent.impl.sampling.Sampler;
+import co.elastic.apm.agent.metrics.Labels;
+import co.elastic.apm.agent.metrics.Timer;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nullable;
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.ConcurrentMap;
 
 /**
  * Data captured by an agent representing an event occurring in a monitored service
@@ -43,6 +48,7 @@ public class Transaction extends AbstractSpan<Transaction> {
      */
     private final TransactionContext context = new TransactionContext();
     private final SpanCount spanCount = new SpanCount();
+    private final ConcurrentMap<String, Timer> spanTimings = new ConcurrentHashMap<>();
 
     /**
      * The result of the transaction. HTTP status code for HTTP-related transactions.
@@ -169,20 +175,26 @@ public void setUser(String id, String email, String username) {
 
     @Override
     public void doEnd(long epochMicros) {
+        incrementTimer("transaction", getSelfDuration());
         if (!isSampled()) {
             context.resetState();
         }
         if (type == null) {
             type = "custom";
         }
         context.onTransactionEnd();
+        trackMetrics();
         this.tracer.endTransaction(this);
     }
 
     public SpanCount getSpanCount() {
         return spanCount;
     }
 
+    public ConcurrentMap<String, Timer> getSpanTimings() {
+        return spanTimings;
+    }
+
     @Override
     public void resetState() {
         super.resetState();
@@ -226,4 +238,43 @@ public void decrementReferences() {
             tracer.recycle(this);
         }
     }
+
+    void incrementTimer(@Nullable String type, long duration) {
+        if (type != null && !finished) {
+            Timer timer = spanTimings.get(type);
+            if (timer == null) {
+                timer = new Timer();
+                Timer racyTimer = spanTimings.putIfAbsent(type, timer);
+                if (racyTimer != null) {
+                    timer = racyTimer;
+                }
+            }
+            timer.update(duration);
+            if (finished) {
+                // in case end()->trackMetrics() has been called concurrently
+                // don't leak timers
+                timer.resetState();
+            }
+        }
+    }
+
+    private void trackMetrics() {
+        final String type = getType();
+        if (type == null) {
+            return;
+        }
+        final StringBuilder transactionName = getName();
+        final Labels labels = new Labels();
+        for (Map.Entry<String, Timer> entry : getSpanTimings().entrySet()) {
+            final Timer timer = entry.getValue();
+            if (timer.getCount() > 0) {
+                labels.resetState();
+                labels.transactionName(transactionName)
+                    .transactionType(type)
+                    .spanType(entry.getKey());
+                tracer.getMetricRegistry().timer("self_time", labels).update(timer.getTotalTimeNs(), timer.getCount());
+                timer.resetState();
+            }
+        }
+    }
 }