Fix rest impl time. (sofastack#353)

jiayongming · Nov 30, 2018 · 7fc2357 · 7fc2357
1 parent 5d0d8a8
commit 7fc2357
Show file tree

Hide file tree

Showing 25 changed files with 336 additions and 93 deletions.
diff --git a/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/BaseLoadBalancerTest.java b/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/BaseLoadBalancerTest.java
@@ -17,6 +17,8 @@
 package com.alipay.sofa.rpc.client.lb;
 
 import com.alipay.sofa.rpc.client.ProviderInfo;
+import com.alipay.sofa.rpc.log.Logger;
+import com.alipay.sofa.rpc.log.LoggerFactory;
 
 import java.util.ArrayList;
 import java.util.List;
@@ -28,6 +30,8 @@
  */
 public abstract class BaseLoadBalancerTest {
 
+    protected static final Logger LOGGER = LoggerFactory.getLogger(BaseLoadBalancerTest.class);
+
     protected List<ProviderInfo> buildSameWeightProviderList(int size) {
         List<ProviderInfo> aliveConnections = new ArrayList<ProviderInfo>();
         for (int i = 0; i < size; i++) {

diff --git a/...pl/client/src/test/java/com/alipay/sofa/rpc/client/lb/ConsistentHashLoadBalancerTest.java b/...pl/client/src/test/java/com/alipay/sofa/rpc/client/lb/ConsistentHashLoadBalancerTest.java
@@ -18,6 +18,8 @@
 
 import com.alipay.sofa.rpc.client.ProviderInfo;
 import com.alipay.sofa.rpc.core.request.SofaRequest;
+import com.alipay.sofa.rpc.log.Logger;
+import com.alipay.sofa.rpc.log.LoggerFactory;
 import org.junit.Assert;
 import org.junit.Test;
 
@@ -31,6 +33,7 @@
  * @author <a href="mailto:[email protected]">GengZhang</a>
  */
 public class ConsistentHashLoadBalancerTest extends BaseLoadBalancerTest {
+
     @Test
     public void doSelect() throws Exception {
 
@@ -53,8 +56,8 @@ public void doSelect() throws Exception {
             cnt.put(port, cnt.get(port) + 1);
         }
         long end = System.currentTimeMillis();
-        System.out.println("elapsed" + (end - start) + "ms");
-        System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+        LOGGER.info("elapsed" + (end - start) + "ms");
+        LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
         int count = 0;
         for (int i = 0; i < size; i++) {

diff --git a/...l/client/src/test/java/com/alipay/sofa/rpc/client/lb/LocalPreferenceLoadBalancerTest.java b/...l/client/src/test/java/com/alipay/sofa/rpc/client/lb/LocalPreferenceLoadBalancerTest.java
@@ -62,8 +62,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             for (int i = 0; i < size; i++) {
                 Assert.assertTrue(cnt.get(9000 + i) == 0);
@@ -98,8 +98,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             for (int i = 0; i < size; i++) {
                 Assert.assertTrue(cnt.get(9000 + i) == 0);

diff --git a/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/RandomLoadBalancerTest.java b/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/RandomLoadBalancerTest.java
@@ -52,8 +52,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             int avg = total / size;
             for (int i = 0; i < size; i++) {
@@ -75,8 +75,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             Assert.assertTrue(cnt.get(9000) == 0);
 

diff --git a/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/RoundRobinLoadBalancerTest.java b/core-impl/client/src/test/java/com/alipay/sofa/rpc/client/lb/RoundRobinLoadBalancerTest.java
@@ -52,8 +52,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             int avg = total / size;
             for (int i = 0; i < size; i++) {
@@ -73,8 +73,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             // 忽略了权重
             int avg = total / size;
@@ -94,7 +94,7 @@ public static void main(String[] args) {
             y = a[i + 1];
             temp = gcd(x, y);
         }
-        System.out.println(temp);
+        LOGGER.info(String.valueOf(temp));
     }
 
     public static int gcd(int a, int b) {
@@ -105,7 +105,7 @@ public static int gcd(int a, int b) {
             b = temp;
             System.out.println("gcd(" + a + ", " + b + ")=");
         }
-        System.out.println(a);
+        LOGGER.info(String.valueOf(a));
         return a;
     }
 }
diff --git a/.../client/src/test/java/com/alipay/sofa/rpc/client/lb/WeightRoundRobinLoadBalancerTest.java b/.../client/src/test/java/com/alipay/sofa/rpc/client/lb/WeightRoundRobinLoadBalancerTest.java
@@ -18,6 +18,8 @@
 
 import com.alipay.sofa.rpc.client.ProviderInfo;
 import com.alipay.sofa.rpc.core.request.SofaRequest;
+import com.alipay.sofa.rpc.log.Logger;
+import com.alipay.sofa.rpc.log.LoggerFactory;
 import org.junit.Assert;
 import org.junit.Test;
 
@@ -31,6 +33,9 @@
  * @author <a href="mailto:[email protected]">GengZhang</a>
  */
 public class WeightRoundRobinLoadBalancerTest extends BaseLoadBalancerTest {
+
+    private static final Logger LOGGER = LoggerFactory.getLogger(WeightRoundRobinLoadBalancerTest.class);
+
     @Test
     public void doSelect() throws Exception {
         WeightRoundRobinLoadBalancer loadBalancer = new WeightRoundRobinLoadBalancer(null);
@@ -51,8 +56,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             int avg = total / size;
             for (int i = 0; i < size; i++) {
@@ -73,8 +78,8 @@ public void doSelect() throws Exception {
                 cnt.put(port, cnt.get(port) + 1);
             }
             long end = System.currentTimeMillis();
-            System.out.println("elapsed" + (end - start) + "ms");
-            System.out.println("avg " + (end - start) * 1000 * 1000 / total + "ns");
+            LOGGER.info("elapsed" + (end - start) + "ms");
+            LOGGER.info("avg " + (end - start) * 1000 * 1000 / total + "ns");
 
             Assert.assertTrue(cnt.get(9000) == 0);
             int count = 0;

diff --git a/...lient/src/test/java/com/alipay/sofa/rpc/client/lb/WeightRoundRobinLoadBalancerV2Test.java b/...lient/src/test/java/com/alipay/sofa/rpc/client/lb/WeightRoundRobinLoadBalancerV2Test.java
@@ -24,7 +24,7 @@
  *
  * @author <a href="mailto:[email protected]">GengZhang</a>
  */
-public class WeightRoundRobinLoadBalancerV2Test {
+public class WeightRoundRobinLoadBalancerV2Test extends BaseLoadBalancerTest {
 
     /**
      * 上次选择的服务器
@@ -131,7 +131,7 @@ public static void main(String args[]) {
 
         for (int i = 0; i < 15; i++) {
             Server server = weightRoundRobin.getServer();
-            System.out.println("server " + server.getIp() + " weight=" + server.getWeight());
+            LOGGER.info("server " + server.getIp() + " weight=" + server.getWeight());
         }
     }
 

diff --git a/core-impl/log/src/test/resources/log4j.xml b/core-impl/log/src/test/resources/log4j.xml
@@ -9,7 +9,7 @@
     </appender>
 
     <root>
-        <level value="DEBUG"/>
+        <level value="INFO"/>
         <appender-ref ref="CONSOLE"/>
     </root>
 

diff --git a/core-impl/proxy/src/test/resources/log4j.xml b/core-impl/proxy/src/test/resources/log4j.xml
@@ -9,7 +9,7 @@
     </appender>
 
     <root>
-        <level value="DEBUG"/>
+        <level value="INFO"/>
         <appender-ref ref="CONSOLE"/>
     </root>
 

diff --git a/core/api/src/main/java/com/alipay/sofa/rpc/common/RpcConstants.java b/core/api/src/main/java/com/alipay/sofa/rpc/common/RpcConstants.java
@@ -275,6 +275,14 @@ public class RpcConstants {
      * @since 5.4.0
      */
     public static final String  INTERNAL_KEY_CLIENT_SEND_TIME      = INTERNAL_KEY_PREFIX + "client_send_time";
+
+    /**
+     * 内部使用的key：_server_receive_time 服务端接收时间戳，long
+     *
+     * @since 5.4.8
+     */
+    public static final String  INTERNAL_KEY_SERVER_RECEIVE_TIME   = INTERNAL_KEY_PREFIX + "server_receive_time";
+
     /**
      * 内部使用的key：_router_record 路由记录，string
      */

diff --git a/...pl/fault-tolerance/src/test/java/com/alipay/sofa/rpc/client/aft/FaultBaseServiceTest.java b/...pl/fault-tolerance/src/test/java/com/alipay/sofa/rpc/client/aft/FaultBaseServiceTest.java
@@ -20,6 +20,8 @@
 import com.alipay.sofa.rpc.client.aft.bean.HelloServiceTimeOutImpl;
 import com.alipay.sofa.rpc.context.RpcInternalContext;
 import com.alipay.sofa.rpc.context.RpcInvokeContext;
+import com.alipay.sofa.rpc.log.Logger;
+import com.alipay.sofa.rpc.log.LoggerFactory;
 import org.junit.After;
 import org.junit.Before;
 

diff --git a/...sion-impl/fault-tolerance/src/test/java/com/alipay/sofa/rpc/client/aft/FaultBaseTest.java b/...sion-impl/fault-tolerance/src/test/java/com/alipay/sofa/rpc/client/aft/FaultBaseTest.java
@@ -29,6 +29,8 @@
 import com.alipay.sofa.rpc.config.ProviderConfig;
 import com.alipay.sofa.rpc.config.ServerConfig;
 import com.alipay.sofa.rpc.ext.ExtensionLoaderFactory;
+import com.alipay.sofa.rpc.log.Logger;
+import com.alipay.sofa.rpc.log.LoggerFactory;
 import com.alipay.sofa.rpc.module.FaultToleranceModule;
 import com.alipay.sofa.rpc.module.Module;
 import org.junit.After;
@@ -42,6 +44,9 @@
  * @version $Id: FaultBaseTest.java, v 0.1 2017年11月16日 下午3:14 bystander Exp $
  */
 public abstract class FaultBaseTest {
+
+    private static final Logger                  LOGGER    = LoggerFactory.getLogger(FaultBaseTest.class);
+
     public static final String                   APP_NAME1 = "testApp";
     public static final String                   APP_NAME2 = "testAnotherApp";
 

diff --git a/extension-impl/fault-tolerance/src/test/resources/log4j.xml b/extension-impl/fault-tolerance/src/test/resources/log4j.xml
@@ -9,7 +9,7 @@
     </appender>
 
     <root>
-        <level value="DEBUG"/>
+        <level value="INFO"/>
         <appender-ref ref="CONSOLE"/>
     </root>
 

diff --git a/extension-impl/remoting-bolt/src/test/resources/log4j.xml b/extension-impl/remoting-bolt/src/test/resources/log4j.xml
@@ -9,7 +9,7 @@
     </appender>
 
     <root>
-        <level value="DEBUG"/>
+        <level value="INFO"/>
         <appender-ref ref="CONSOLE"/>
     </root>
 

diff --git a/extension-impl/remoting-http/src/test/resources/log4j.xml b/extension-impl/remoting-http/src/test/resources/log4j.xml
@@ -9,7 +9,7 @@
     </appender>
 
     <root>
-        <level value="DEBUG"/>
+        <level value="INFO"/>
         <appender-ref ref="CONSOLE"/>
     </root>
 

diff --git a/...entracing-resteasy/src/main/java/com/alipay/sofa/rpc/server/rest/TraceResponseFilter.java b/...entracing-resteasy/src/main/java/com/alipay/sofa/rpc/server/rest/TraceResponseFilter.java
@@ -18,6 +18,7 @@
 
 import com.alipay.sofa.rpc.common.RpcConstants;
 import com.alipay.sofa.rpc.context.RpcInternalContext;
+import com.alipay.sofa.rpc.context.RpcRuntimeContext;
 
 import javax.annotation.Priority;
 import javax.ws.rs.container.ContainerRequestContext;
@@ -36,11 +37,16 @@ public class TraceResponseFilter implements ContainerResponseFilter {
     @Override
     public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext)
         throws IOException {
+
         // 补充服务端request和response大小
         if (RpcInternalContext.isAttachmentEnable()) {
             RpcInternalContext context = RpcInternalContext.getContext();
             context.setAttachment(RpcConstants.INTERNAL_KEY_REQ_SIZE, requestContext.getLength());
             context.setAttachment(RpcConstants.INTERNAL_KEY_RESP_SIZE, responseContext.getLength());
+            Long startTime = (Long) context.removeAttachment(RpcConstants.INTERNAL_KEY_SERVER_RECEIVE_TIME);
+            if (startTime != null) {
+                context.setAttachment(RpcConstants.INTERNAL_KEY_IMPL_ELAPSE, RpcRuntimeContext.now() - startTime);
+            }
         }
     }
 }
diff --git a/...acing-resteasy/src/main/java/com/alipay/sofa/rpc/tracer/sofatracer/RestTracerAdapter.java b/...acing-resteasy/src/main/java/com/alipay/sofa/rpc/tracer/sofatracer/RestTracerAdapter.java
@@ -46,11 +46,9 @@
 import static com.alipay.sofa.rpc.common.RpcConstants.INTERNAL_KEY_APP_NAME;
 
 /**
- *
  * 客户端：startRpc ——> filter --> beforeSend --> 存入tracer信息 --> clientReceived
  * 服务端：serverReceived --> filter --> serverSend
  *
- *
  * @author liangen
  * @version $Id: RestTracerAdapter.java, v 0.1 2017年11月29日 上午9:56 liangen Exp $
  */
@@ -65,7 +63,7 @@ public class RestTracerAdapter {
 
     /**
      * 存入tracer信息
-     * 
+     *
      * @param requestContext ClientRequestContext
      */
     public static void storeTracerInfo(ClientRequestContext requestContext) {
@@ -126,7 +124,7 @@ public static void serverReceived(NettyHttpRequest request) {
 
     /**
      * 适配服务端filter
-     * 
+     *
      * @param requestContext ContainerRequestContext
      */
     public static void serverFilter(ContainerRequestContext requestContext) {
@@ -135,6 +133,9 @@ public static void serverFilter(ContainerRequestContext requestContext) {
             SofaTracerSpan serverSpan = sofaTraceContext.getCurrentSpan();
             if (serverSpan != null) {
                 RpcInternalContext context = RpcInternalContext.getContext();
+
+                context.setAttachment(RpcConstants.INTERNAL_KEY_SERVER_RECEIVE_TIME, RpcRuntimeContext.now());
+
                 SofaResourceMethodInvoker resourceMethodInvoker = (SofaResourceMethodInvoker)
                         ((PostMatchContainerRequestContext) requestContext)
                             .getResourceMethod();
@@ -201,6 +202,16 @@ public static void serverSend(NettyHttpResponse response, Throwable throwable) {
                 }
             }
 
+            SofaTraceContext sofaTraceContext = SofaTraceContextHolder.getSofaTraceContext();
+            SofaTracerSpan serverSpan = sofaTraceContext.getCurrentSpan();
+
+            RpcInternalContext context = RpcInternalContext.getContext();
+
+            if (serverSpan != null) {
+                serverSpan.setTag(RpcSpanTags.SERVER_BIZ_TIME,
+                    (Number) context.getAttachment(RpcConstants.INTERNAL_KEY_IMPL_ELAPSE));
+            }
+
             Tracers.serverSend(sofaRequest, sofaResponse, null);
         } catch (Throwable t) {
             if (LOGGER.isWarnEnabled()) {

diff --git a/...g-resteasy/src/main/java/com/alipay/sofa/rpc/transport/rest/TraceClientRequestFilter.java b/...g-resteasy/src/main/java/com/alipay/sofa/rpc/transport/rest/TraceClientRequestFilter.java
@@ -16,18 +16,20 @@
  */
 package com.alipay.sofa.rpc.transport.rest;
 
+import com.alipay.sofa.rpc.common.RpcConstants;
+import com.alipay.sofa.rpc.context.RpcInternalContext;
 import com.alipay.sofa.rpc.log.Logger;
 import com.alipay.sofa.rpc.log.LoggerFactory;
 import com.alipay.sofa.rpc.tracer.sofatracer.RestTracerAdapter;
 
 import javax.annotation.Priority;
 import javax.ws.rs.client.ClientRequestContext;
 import javax.ws.rs.client.ClientRequestFilter;
+import javax.ws.rs.core.HttpHeaders;
 import javax.ws.rs.ext.Provider;
 import java.io.IOException;
 
 /**
- * 
  * @author <a href="mailto:[email protected]">zhanggeng</a>
  * @author <a href="mailto:[email protected]">liangen</a>
  */
@@ -40,6 +42,15 @@ public class TraceClientRequestFilter implements ClientRequestFilter {
     @Override
     public void filter(ClientRequestContext requestContext) throws IOException {
         try {
+
+            if (RpcInternalContext.isAttachmentEnable()) {
+                // 补充客户端request长度
+                RpcInternalContext context = RpcInternalContext.getContext();
+                context.setAttachment(RpcConstants.INTERNAL_KEY_REQ_SIZE,
+                    requestContext.getHeaderString(HttpHeaders.CONTENT_LENGTH));
+
+            }
+
             RestTracerAdapter.storeTracerInfo(requestContext);
         } catch (Exception e) {
             logger.error("the process of rest tracer client request occur error ", e);