Timing breakdown (#588)

Author: felixbarny

NOTICE

@@ -359,3 +359,48 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 
 ###############################################################################
 
+This product includes code from HdrHistogram, dual-licensed under CC0 and BSD 2-Clause License
+
+The code in this repository code was Written by Gil Tene, Michael Barker,
+and Matt Warren, and released to the public domain, as explained at
+http://creativecommons.org/publicdomain/zero/1.0/
+
+For users of this code who wish to consume it under the "BSD" license
+rather than under the public domain or CC0 contribution text mentioned
+above, the code found under this directory is *also* provided under the
+following license (commonly referred to as the BSD 2-Clause License). This
+license does not detract from the above stated release of the code into
+the public domain, and simply represents an additional license granted by
+the Author.
+
+-----------------------------------------------------------------------------
+** Beginning of "BSD 2-Clause License" text. **
+
+ Copyright (c) 2012, 2013, 2014, 2015, 2016 Gil Tene
+ Copyright (c) 2014 Michael Barker
+ Copyright (c) 2014 Matt Warren
+ All rights reserved.
+
+ Redistribution and use in source and binary forms, with or without
+ modification, are permitted provided that the following conditions are met:
+
+ 1. Redistributions of source code must retain the above copyright notice,
+    this list of conditions and the following disclaimer.
+
+ 2. Redistributions in binary form must reproduce the above copyright notice,
+    this list of conditions and the following disclaimer in the documentation
+    and/or other materials provided with the distribution.
+
+ THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
+ AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
+ LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
+ CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
+ SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+ INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
+ CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+ ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF
+ THE POSSIBILITY OF SUCH DAMAGE.
+
+###############################################################################

apm-agent-benchmarks/src/main/java/co/elastic/apm/agent/benchmark/ElasticApmContinuousBenchmark.java

@@ -150,6 +150,7 @@ public void setUp(Blackhole blackhole) {
 
     @TearDown
     public void tearDown() throws ExecutionException, InterruptedException {
+        Thread.sleep(1000);
         tracer.getReporter().flush().get();
         server.stop();
         System.out.println("Reported: " + tracer.getReporter().getReported());

apm-agent-core/pom.xml

@@ -92,6 +92,11 @@
             <artifactId>byte-buddy</artifactId>
             <version>${version.byte-buddy}</version>
         </dependency>
+        <dependency>
+            <groupId>org.hdrhistogram</groupId>
+            <artifactId>HdrHistogram</artifactId>
+            <version>2.1.11</version>
+        </dependency>
 
         <dependency>
             <groupId>com.squareup.okhttp3</groupId>

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

@@ -11,9 +11,9 @@
  * the Apache License, Version 2.0 (the "License"); you may
  * not use this file except in compliance with the License.
  * You may obtain a copy of the License at
- * 
+ *
  *   http://www.apache.org/licenses/LICENSE-2.0
- * 
+ *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
@@ -399,7 +399,7 @@ public void endSpan(Span span) {
         if (span.isSampled() && !span.isDiscard()) {
             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/async/SpanInScopeCallableWrapper.java

@@ -11,9 +11,9 @@
  * the Apache License, Version 2.0 (the "License"); you may
  * not use this file except in compliance with the License.
  * You may obtain a copy of the License at
- * 
+ *
  *   http://www.apache.org/licenses/LICENSE-2.0
- * 
+ *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY

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

@@ -11,9 +11,9 @@
  * the Apache License, Version 2.0 (the "License"); you may
  * not use this file except in compliance with the License.
  * You may obtain a copy of the License at
- * 
+ *
  *   http://www.apache.org/licenses/LICENSE-2.0
- * 
+ *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY

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

@@ -11,9 +11,9 @@
  * the Apache License, Version 2.0 (the "License"); you may
  * not use this file except in compliance with the License.
  * You may obtain a copy of the License at
- * 
+ *
  *   http://www.apache.org/licenses/LICENSE-2.0
- * 
+ *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
@@ -26,13 +26,17 @@
 
 import co.elastic.apm.agent.impl.ElasticApmTracer;
 import co.elastic.apm.agent.impl.context.AbstractContext;
+import co.elastic.apm.agent.matcher.WildcardMatcher;
+import co.elastic.apm.agent.objectpool.Recyclable;
+import co.elastic.apm.agent.report.ReporterConfiguration;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nullable;
 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);
@@ -43,37 +47,98 @@ public abstract class AbstractSpan<T extends AbstractSpan> extends TraceContextH
      * Generic designation of a transaction in the scope of a single service (eg: 'GET /users/:id')
      */
     protected final StringBuilder name = new StringBuilder();
+    protected final boolean collectBreakdownMetrics;
     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;
+    private ChildDurationTimer childDurations = new ChildDurationTimer();
     protected AtomicInteger references = new AtomicInteger();
     protected volatile boolean finished = true;
 
     public int getReferenceCount() {
         return references.get();
     }
 
+    private static class ChildDurationTimer implements Recyclable {
+
+        private AtomicInteger activeChildren = new AtomicInteger();
+        private AtomicLong start = new AtomicLong();
+        private AtomicLong duration = new AtomicLong();
+
+        /**
+         * Starts the timer if it has not been started already.
+         *
+         * @param startTimestamp
+         */
+        void onChildStart(long startTimestamp) {
+            if (activeChildren.incrementAndGet() == 1) {
+                start.set(startTimestamp);
+            }
+        }
+
+        /**
+         * Stops the timer and increments the duration if no other direct children are still running
+         * @param endTimestamp
+         */
+        void onChildEnd(long endTimestamp) {
+            if (activeChildren.decrementAndGet() == 0) {
+                incrementDuration(endTimestamp);
+            }
+        }
+
+        /**
+         * Stops the timer and increments the duration even if there are direct children which are still running
+         *
+         * @param endTimestamp
+         */
+        void onSpanEnd(long endTimestamp) {
+            if (activeChildren.getAndSet(0) != 0) {
+                incrementDuration(endTimestamp);
+            }
+        }
+
+        private void incrementDuration(long epochMicros) {
+            duration.addAndGet(epochMicros - start.get());
+        }
+
+        @Override
+        public void resetState() {
+            activeChildren.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);
+        collectBreakdownMetrics = !WildcardMatcher.isAnyMatch(tracer.getConfig(ReporterConfiguration.class).getDisableMetrics(), "span.self_time");
     }
 
     public boolean isReferenced() {
         return references.get() > 0;
     }
 
     /**
-     * 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')
      */
@@ -124,6 +189,7 @@ public void resetState() {
         timestamp = 0;
         duration = 0;
         traceContext.resetState();
+        childDurations.resetState();
         references.set(0);
     }
 
@@ -177,20 +243,23 @@ 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");
             }
-            doEnd(epochMicros);
-            // has to be set last so doEnd callbacks don't think it has already been finished
+            childDurations.onSpanEnd(epochMicros);
+            beforeEnd(epochMicros);
             this.finished = true;
+            afterEnd();
         } else {
             logger.warn("End has already been called: {}", this);
             assert false;
         }
     }
 
-    protected abstract void doEnd(long epochMicros);
+    protected abstract void beforeEnd(long epochMicros);
+
+    protected abstract void afterEnd();
 
     @Override
     public boolean isChildOf(TraceContextHolder other) {
@@ -242,6 +311,18 @@ public void setStartTimestamp(long epochMicros) {
         timestamp = epochMicros;
     }
 
+    void onChildStart(long epochMicros) {
+        if (collectBreakdownMetrics) {
+            childDurations.onChildStart(epochMicros);
+        }
+    }
+
+    void onChildEnd(long epochMicros) {
+        if (collectBreakdownMetrics) {
+            childDurations.onChildEnd(epochMicros);
+        }
+    }
+
     public void incrementReferences() {
         references.incrementAndGet();
         if (logger.isDebugEnabled()) {

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

@@ -11,9 +11,9 @@
  * the Apache License, Version 2.0 (the "License"); you may
  * not use this file except in compliance with the License.
  * You may obtain a copy of the License at
- * 
+ *
  *   http://www.apache.org/licenses/LICENSE-2.0
- * 
+ *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
@@ -77,12 +77,10 @@ public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T
         if (parentContext instanceof Transaction) {
             this.transaction = (Transaction) parentContext;
             this.parent = this.transaction;
-            this.parent.incrementReferences();
         } else if (parentContext instanceof Span) {
             final Span parentSpan = (Span) parentContext;
             this.parent = parentSpan;
             this.transaction = parentSpan.transaction;
-            this.parent.incrementReferences();
         }
         if (dropped) {
             traceContext.setRecorded(false);
@@ -103,6 +101,15 @@ public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T
         return this;
     }
 
+    @Override
+    protected void onAfterStart() {
+        super.onAfterStart();
+        if (parent != null) {
+            this.parent.incrementReferences();
+            this.parent.onChildStart(getTimestamp());
+        }
+    }
+
     /**
      * Any other arbitrary data captured by the agent, optionally provided by the user
      */
@@ -188,7 +195,7 @@ public String getAction() {
     }
 
     @Override
-    public void doEnd(long epochMicros) {
+    public void beforeEnd(long epochMicros) {
         if (logger.isDebugEnabled()) {
             logger.debug("} endSpan {}", this);
             if (logger.isTraceEnabled()) {
@@ -198,9 +205,17 @@ public void doEnd(long epochMicros) {
         if (type == null) {
             type = "custom";
         }
+        if (transaction != null) {
+            transaction.incrementTimer(type, subtype, getSelfDuration());
+        }
         if (parent != null) {
+            parent.onChildEnd(epochMicros);
             parent.decrementReferences();
         }
+    }
+
+    @Override
+    protected void afterEnd() {
         this.tracer.endSpan(this);
     }