[#9254] Use end time to store uri statistics

bootstraps/bootstrap-core/src/main/java/com/navercorp/pinpoint/bootstrap/context/Trace.java

@@ -34,6 +34,8 @@ public interface Trace extends StackOperation {
     @InterfaceAudience.Private
     long getStartTime();
 
+    @InterfaceAudience.Private
+    long getEndTime();
     //------------------------------------------------
 
     TraceId getTraceId();

bootstraps/bootstrap-core/src/main/java/com/navercorp/pinpoint/bootstrap/pair/NameValuePair.java

@@ -45,4 +45,21 @@ public V getValue() {
     public void setValue(V value) {
         this.value = value;
     }
+
+    @Override
+    public boolean equals(Object o) {
+        if (this == o) return true;
+        if (o == null || getClass() != o.getClass()) return false;
+
+        NameValuePair<?, ?> pair = (NameValuePair<?, ?>) o;
+        if (!name.equals(pair.getName())) return false;
+        return value.equals(pair.getValue());
+    }
+
+    @Override
+    public int hashCode() {
+        int result = name.hashCode();
+        result = 31 * result + value.hashCode();
+        return result;
+    }
 }

bootstraps/bootstrap-core/src/main/java/com/navercorp/pinpoint/bootstrap/plugin/request/ServletRequestListener.java

@@ -179,7 +179,7 @@ public void destroyed(REQ request, final Throwable throwable, final int statusCo
             this.traceContext.removeTraceObject();
             trace.close();
             boolean status = isNotFailedStatus(statusCode);
-            uriStatRecorder.record(request, rpcName, status, trace.getStartTime(), System.currentTimeMillis());
+            uriStatRecorder.record(request, rpcName, status, trace.getStartTime(), trace.getEndTime());
         }
     }
 

commons-server/src/main/java/com/navercorp/pinpoint/common/server/bo/serializer/stat/AgentStatDecodingContext.java

@@ -50,5 +50,4 @@ public long getTimestampDelta() {
     public void setTimestampDelta(long timestampDelta) {
         this.timestampDelta = timestampDelta;
     }
-
 }

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/AsyncChildTrace.java

@@ -53,6 +53,8 @@ public class AsyncChildTrace implements Trace {
     private final TraceRoot traceRoot;
     private final LocalAsyncId localAsyncId;
 
+    private long endTime = 0L;
+
     public AsyncChildTrace(final TraceRoot traceRoot, CallStack<SpanEvent> callStack, Storage storage, boolean sampling,
                              SpanRecorder spanRecorder, WrappedSpanEventRecorder wrappedSpanEventRecorder, final LocalAsyncId localAsyncId) {
 
@@ -147,6 +149,7 @@ public void traceBlockEnd(int stackId) {
 
         if (spanEvent.isTimeRecording()) {
             spanEvent.markAfterTime();
+            endTime = spanEvent.getAfterTime();
         }
         logSpan(spanEvent);
         // state restore
@@ -203,6 +206,11 @@ public long getStartTime() {
         return getTraceRoot().getTraceStartTime();
     }
 
+    @Override
+    public long getEndTime() {
+        return endTime;
+    }
+
     @Override
     public boolean canSampled() {
         return true;

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/AsyncTrace.java

@@ -49,6 +49,11 @@ public long getStartTime() {
         return this.traceRoot.getTraceStartTime();
     }
 
+    @Override
+    public long getEndTime() {
+        return this.trace.getEndTime();
+    }
+
 
     @Override
     public TraceId getTraceId() {

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DefaultTrace.java

@@ -56,6 +56,8 @@ public final class DefaultTrace implements Trace {
     private final Span span;
     private final ActiveTraceHandle activeTraceHandle;
 
+    private long endTime = 0L;
+
 
     public DefaultTrace(Span span, CallStack<SpanEvent> callStack, Storage storage, boolean sampling,
                         SpanRecorder spanRecorder, WrappedSpanEventRecorder wrappedSpanEventRecorder, ActiveTraceHandle activeTraceHandle) {
@@ -69,6 +71,7 @@ public DefaultTrace(Span span, CallStack<SpanEvent> callStack, Storage storage,
         this.wrappedSpanEventRecorder = Objects.requireNonNull(wrappedSpanEventRecorder, "wrappedSpanEventRecorder");
 
         this.activeTraceHandle = Objects.requireNonNull(activeTraceHandle, "activeTraceHandle");
+
         setCurrentThread();
     }
 
@@ -189,6 +192,7 @@ public void close() {
         }
 
         this.storage.close();
+        endTime = afterTime;
 
         purgeActiveTrace(afterTime);
     }
@@ -225,6 +229,11 @@ public long getStartTime() {
         return getTraceRoot().getTraceStartTime();
     }
 
+    @Override
+    public long getEndTime() {
+        return endTime;
+    }
+
     @Override
     public boolean canSampled() {
         return true;

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DisableAsyncChildTrace.java

@@ -86,6 +86,11 @@ public long getStartTime() {
         return getTraceRoot().getTraceStartTime();
     }
 
+    @Override
+    public long getEndTime() {
+        return 0L;
+    }
+
     @Override
     public TraceId getTraceId() {
         return getTraceRoot().getTraceId();

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DisableTrace.java

@@ -54,6 +54,11 @@ public long getStartTime() {
         return startTime;
     }
 
+    @Override
+    public long getEndTime() {
+        return 0L;
+    }
+
 
     @Override
     public SpanEventRecorder traceBlockBegin() {

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/grpc/GrpcUriStatMessageConverter.java

@@ -16,6 +16,7 @@
 
 package com.navercorp.pinpoint.profiler.context.grpc;
 
+import com.navercorp.pinpoint.bootstrap.pair.NameValuePair;
 import com.navercorp.pinpoint.common.trace.UriStatHistogramBucket;
 import com.navercorp.pinpoint.grpc.trace.PAgentUriStat;
 import com.navercorp.pinpoint.grpc.trace.PEachUriStat;
@@ -27,6 +28,8 @@
 import com.navercorp.pinpoint.profiler.monitor.metric.uri.UriStatHistogram;
 
 import java.util.Collection;
+import java.util.Map;
+import java.util.Set;
 
 /**
  * @author Taejin Koo
@@ -46,15 +49,14 @@ public PAgentUriStat toMessage(MetricType message) {
     }
 
     private PAgentUriStat createPAgentUriStat(AgentUriStatData agentUriStatData) {
-        long baseTimestamp = agentUriStatData.getBaseTimestamp();
-
         PAgentUriStat.Builder builder = PAgentUriStat.newBuilder();
-        builder.setTimestamp(baseTimestamp);
         builder.setBucketVersion(layout.getBucketVersion());
 
-        Collection<EachUriStatData> allUriStatData = agentUriStatData.getAllUriStatData();
-        for (EachUriStatData eachUriStatData : allUriStatData) {
-            PEachUriStat pEachUriStat = createPEachUriStat(eachUriStatData);
+        Set<Map.Entry<NameValuePair<String, Long>, EachUriStatData>> allUriStatData = agentUriStatData.getAllUriStatData();
+
+        for (Map.Entry<NameValuePair<String, Long>, EachUriStatData> eachUriStatData : allUriStatData) {
+            builder.setTimestamp(eachUriStatData.getKey().getValue());
+            PEachUriStat pEachUriStat = createPEachUriStat(eachUriStatData.getValue());
             builder.addEachUriStat(pEachUriStat);
         }
 

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/monitor/config/DefaultMonitorConfig.java

@@ -31,7 +31,7 @@ public class DefaultMonitorConfig implements MonitorConfig {
     @Value("${profiler.uri.stat.enable}")
     private boolean uriStatEnable = false;
     @Value("${profiler.uri.stat.completed.data.limit.size}")
-    private int completedUriStatDataLimitSize = 3;
+    private int completedUriStatDataLimitSize = 1000;
 
     @Value("${profiler.jvm.stat.collect.interval}")
     private int profileJvmStatCollectIntervalMs = DEFAULT_AGENT_STAT_COLLECTION_INTERVAL_MS;

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/recorder/DefaultUriStatRecorder.java

@@ -48,7 +48,7 @@ public void record(T request, String rawUri, boolean status, long startTime, lon
             return;
         }
 
-        uriStatStorage.store(uri, status, endTime - startTime);
+        uriStatStorage.store(uri, status, startTime, endTime);
     }
 
 }

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/storage/AsyncQueueingUriStatStorage.java

@@ -56,9 +56,9 @@ private AsyncQueueingUriStatStorage(int queueSize, String executorName, Executor
     }
 
     @Override
-    public void store(String uri, boolean status, long elapsedTime) {
+    public void store(String uri, boolean status, long startTime, long endTime) {
         Objects.requireNonNull(uri, "uri");
-        UriStatInfo uriStatInfo = new UriStatInfo(uri, status, elapsedTime);
+        UriStatInfo uriStatInfo = new UriStatInfo(uri, status, startTime, endTime);
         execute(uriStatInfo);
     }
 

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/storage/DisabledUriStatStorage.java

@@ -24,7 +24,7 @@
 public class DisabledUriStatStorage implements UriStatStorage {
 
     @Override
-    public void store(String uri, boolean status, long elapsedTime) {
+    public void store(String uri, boolean status, long startTime, long endTime) {
         // Do nothing
     }
 

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/storage/UriStatStorage.java

@@ -23,7 +23,7 @@
  */
 public interface UriStatStorage {
 
-    void store(String uri, boolean status, long elapsedTime);
+    void store(String uri, boolean status, long startTime, long endTime);
 
     AgentUriStatData poll();
 

profiler/src/main/java/com/navercorp/pinpoint/profiler/monitor/metric/uri/AgentUriStatData.java

@@ -16,22 +16,26 @@
 
 package com.navercorp.pinpoint.profiler.monitor.metric.uri;
 
+import com.navercorp.pinpoint.bootstrap.pair.NameValuePair;
 import com.navercorp.pinpoint.common.util.Assert;
+import com.navercorp.pinpoint.profiler.context.storage.AsyncQueueingUriStatStorage;
 import com.navercorp.pinpoint.profiler.monitor.metric.MetricType;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 
-import java.util.Collection;
 import java.util.HashMap;
 import java.util.Map;
+import java.util.Set;
 
 /**
  * @author Taejin Koo
  */
 public class AgentUriStatData implements MetricType {
-
+    private static final Logger LOGGER = LogManager.getLogger(AsyncQueueingUriStatStorage.class);
     private final int capacity;
     private final long baseTimestamp;
 
-    private final Map<String, EachUriStatData> eachUriStatDataMap = new HashMap<>();
+    private final Map<NameValuePair<String, Long>, EachUriStatData> eachUriStatDataMap = new HashMap<>();
 
     public AgentUriStatData(long baseTimestamp, int capacity) {
         Assert.isTrue(capacity > 0, "capacity must be  ` > 0`");
@@ -49,23 +53,27 @@ public long getBaseTimestamp() {
     }
 
     public boolean add(UriStatInfo uriStatInfo) {
+        String uri = uriStatInfo.getUri();
+
         if (eachUriStatDataMap.size() > this.capacity) {
+            LOGGER.warn("Number of URIs already collected met the capacity of " + this.capacity + ". Ignoring URI " + uri);
             return false;
         }
-        String uri = uriStatInfo.getUri();
 
-        EachUriStatData eachUriStatData = eachUriStatDataMap.get(uri);
+        NameValuePair key = new NameValuePair(uri, uriStatInfo.getEndTime());
+
+        EachUriStatData eachUriStatData = eachUriStatDataMap.get(key);
         if (eachUriStatData == null) {
             eachUriStatData = new EachUriStatData(uri);
-            eachUriStatDataMap.put(uri, eachUriStatData);
+            eachUriStatDataMap.put(key, eachUriStatData);
         }
 
         eachUriStatData.add(uriStatInfo);
         return true;
     }
 
-    public Collection<EachUriStatData> getAllUriStatData() {
-        return eachUriStatDataMap.values();
+    public Set<Map.Entry<NameValuePair<String, Long>, EachUriStatData>> getAllUriStatData() {
+        return eachUriStatDataMap.entrySet();
     }
 
     @Override

profiler/src/main/java/com/navercorp/pinpoint/profiler/monitor/metric/uri/UriStatInfo.java

@@ -25,12 +25,14 @@ public class UriStatInfo {
 
     private final String uri;
     private final boolean status;
-    private final long elapsed;
+    private final long startTime;
+    private final long endTime;
 
-    public UriStatInfo(String uri, boolean status, long elapsed) {
+    public UriStatInfo(String uri, boolean status, long startTime, long endTime) {
         this.uri = Objects.requireNonNull(uri, "uri");
         this.status = status;
-        this.elapsed = elapsed;
+        this.startTime = startTime;
+        this.endTime = endTime;
     }
 
     public String getUri() {
@@ -41,16 +43,25 @@ public boolean isStatus() {
         return status;
     }
 
+    public long getStartTime() {
+        return startTime;
+    }
+
+    public long getEndTime() {
+        return endTime;
+    }
+
     public long getElapsed() {
-        return elapsed;
+        return endTime - startTime;
     }
 
     @Override
     public String toString() {
         final StringBuilder sb = new StringBuilder("UriStatInfo{");
         sb.append("uri='").append(uri).append('\'');
         sb.append(", status=").append(status);
-        sb.append(", elapsed=").append(elapsed);
+        sb.append(", startTime=").append(startTime);
+        sb.append(", endTime=").append(endTime);
         sb.append('}');
         return sb.toString();
     }

profiler/src/test/java/com/navercorp/pinpoint/profiler/context/grpc/GrpcUriStatMessageConverterTest.java

@@ -72,7 +72,8 @@ private UriStatInfo createRandomUriStatInfo() {
         int index = RANDOM.nextInt(URI_EXAMPLES.length);
         boolean status = RANDOM.nextBoolean();
         final int elapsedTime = RANDOM.nextInt(10000);
-        return new UriStatInfo(URI_EXAMPLES[index], status, elapsedTime);
+        final long timestamp = System.currentTimeMillis();
+        return new UriStatInfo(URI_EXAMPLES[index], status, timestamp - elapsedTime, timestamp);
     }
 
     private void assertData(List<UriStatInfo> uriStatInfoList, List<PEachUriStat> eachUriStatList) {

profiler/src/test/java/com/navercorp/pinpoint/profiler/context/storage/AsyncQueueingUriStatStorageTest.java

@@ -17,13 +17,16 @@
 package com.navercorp.pinpoint.profiler.context.storage;
 
 import com.google.common.util.concurrent.Uninterruptibles;
+import com.navercorp.pinpoint.bootstrap.pair.NameValuePair;
 import com.navercorp.pinpoint.profiler.monitor.metric.uri.AgentUriStatData;
 import com.navercorp.pinpoint.profiler.monitor.metric.uri.EachUriStatData;
 import org.junit.jupiter.api.Assertions;
 import org.junit.jupiter.api.Test;
 
 import java.util.Collection;
+import java.util.Map;
 import java.util.Random;
+import java.util.Set;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -61,9 +64,9 @@ public void storageTest() {
             AgentUriStatData poll = storage.poll();
             Assertions.assertNotNull(poll);
 
-            Collection<EachUriStatData> allUriStatData = poll.getAllUriStatData();
-            for (EachUriStatData eachUriStatData : allUriStatData) {
-                storeCount -= eachUriStatData.getTotalHistogram().getCount();
+            Set<Map.Entry<NameValuePair<String, Long>, EachUriStatData>> allUriStatData = poll.getAllUriStatData();
+            for (Map.Entry<NameValuePair<String, Long>, EachUriStatData> eachUriStatData : allUriStatData) {
+                storeCount -= eachUriStatData.getValue().getTotalHistogram().getCount();
             }
 
             Assertions.assertEquals(0, storeCount);
@@ -75,7 +78,8 @@ public void storageTest() {
     }
 
     private void storeRandomValue(AsyncQueueingUriStatStorage storage) {
-        storage.store(URI_EXAMPLES[RANDOM.nextInt(URI_EXAMPLES.length)], RANDOM.nextBoolean(), RANDOM.nextInt(10000));
+        final long timestamp = System.currentTimeMillis();
+        storage.store(URI_EXAMPLES[RANDOM.nextInt(URI_EXAMPLES.length)], RANDOM.nextBoolean(), timestamp - RANDOM.nextInt(10000), timestamp);
     }
 
 }