openFeign自定义耗时统计

最近测出调用耗时过大，为了看到全部问题，老大要求添加耗时拦截器，打印请求总时长、远程调用时长。
本次改造部分基于此博客：原部分内容

一、说明

• openFeign 本身自带相关日志功能，但是打开debug级别日志，打印的东西过多。于是自己写

二、openFeign请求拦截器：设定远程请求起始时间

@Slf4j
@Component
public class CipherInterceptor implements RequestInterceptor {

    /**
     * 耗时统计
     */
    private long start = 0;

    @Override
    public void apply(RequestTemplate template) {
        if (log.isInfoEnabled()) {
            start = System.currentTimeMillis();
            log.info("---套件请求开始---");
        }
        try {
            byte[] body = template.body();
            String bodyStr = new String(body, StandardCharsets.UTF_8);
            // 打印请求消息
            log.info("cipher-request-path: {}",template.path());
            log.info("cipher-request-bodyStr : {}",bodyStr);
        }catch (Exception e){
            log.error("CipherInterceptor error :",e);
        }
    }

    /**
     * 请求结束
     */
    public void end(){
        if (log.isInfoEnabled()) {
            long cost = System.currentTimeMillis() - start;
            log.info("---套件请求结束-耗时： {} ms ---", cost);
        }
    }

}

三、openFeign请求解码器：统计远程请求耗时

@Slf4j
@Component
public class CipherDecoder implements Decoder,ErrorDecoder {

    @Resource
    CipherInterceptor interceptor;

    /**
     * 对象映射
     */
    private final ObjectMapper objectMapper = new ObjectMapper();

    @Override
    public Object decode(Response response, Type type) throws FeignException {
        interceptor.end();
        if (null == response.body()) {
            log.error("解码异常，响应体为空 status: {}", response.status());
            throw new CipherSuiteRpcException();
        }
        String respond;
        // 解析通用响应
        try {
            respond = StreamUtils.copyToString(response.body().asInputStream(), StandardCharsets.UTF_8);
            log.info("cipher-respond: {}", respond);
            // 响应字符转dto
            return resultToDto(respond, type);
        } catch (Exception e) {
            log.error("CipherRespondDecoder error:", e);
            throw new CipherSuiteRpcException();
        }
    }

    /**
     * 响应转传输对象
     *
     * @param respond 响应
     * @param type    类型
     * @return 最终响应对象
     * @throws JsonProcessingException json处理异常
     */
    private Object resultToDto(String respond, Type type) throws JsonProcessingException {
        TypeFactory typeFactory = objectMapper.getTypeFactory();
        CipherClientResponse baseResponse = objectMapper.readValue(respond,
                typeFactory.constructParametricType(CipherClientResponse.class, typeFactory.constructType(type)));
        log.info("CipherClientResponse : {}", baseResponse);
        // 直接返回
        if (type instanceof CipherClientResponse) {
            log.debug("无响应返回：{}", baseResponse);
            return baseResponse;
        }
        // 过滤
        if (baseResponse.isOk()) {
            return baseResponse.getData();
        }
        // 抛出异常
        log.error("异常响应: {}", baseResponse);
        throw new CipherSuiteRpcException();
    }

    @Override
    public Exception decode(String methodKey, Response response) {
        interceptor.end();
        log.info("methodKey: {}", methodKey);
        // 成功响应码不做处理
        if (HttpStatus.SC_OK == response.status()) {
            return new ErrorDecoder.Default().decode(methodKey, response);
        }
        String respond = null;
        // 解析响应
        try {
            InputStream inputStream = response.body().asInputStream();
            respond = StreamUtils.copyToString(inputStream, StandardCharsets.UTF_8);
        } catch (Exception e) {
            log.error("error : ", e);
        }
        log.error("error respond : {}", respond);
        throw new CipherSuiteRpcException();
    }

}

四、设定服务内部：总耗时拦截器

@Slf4j
@Configuration
public class ServletFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        if (log.isInfoEnabled()) {
            long start = System.currentTimeMillis();
            log.info("---request-start---");
            chain.doFilter(request, response);
            long end = System.currentTimeMillis();
            long cost = end - start;
            log.info("---request-end 耗时 : {} ms ---", cost);
        }else{
            chain.doFilter(request, response);
        }
    }
}

五、后续补充：测试找我说“并发测试分辨不清晰”

日志没问题，但是测试需要对照“远程耗时”、“服务内部耗时”的时候，发现高并发情况下，打印出来的日志长一个模样
于是加上追踪id，调整拦截器的架构方式（第二、四步的对象合一了），代码如下：

@Slf4j
@Component
public class CipherInterceptor implements RequestInterceptor, Filter {

    /**
     * 耗时统计
     */
    private long start = 0;

    /**
     * 并发追踪
     */
    private String tranId = null;

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        // 统计耗时
        if (log.isInfoEnabled()) {
            tranId = UUID.randomUUID().toString().replace("-", "");
            long reqStart = System.currentTimeMillis();
            log.info("--- {} request-start---", tranId);
            chain.doFilter(request, response);
            long reqEnd = System.currentTimeMillis();
            long cost = reqEnd - reqStart;
            log.info("--- {} request-end 耗时 : {} ms ---", tranId, cost);
        } else {
            chain.doFilter(request, response);
        }
    }

    @Override
    public void apply(RequestTemplate template) {
        if (log.isInfoEnabled()) {
            start = System.currentTimeMillis();
            log.info("--- {} 套件请求开始---", tranId);
        }
        try {
            byte[] body = template.body();
            String bodyStr = new String(body, StandardCharsets.UTF_8);
            // 打印请求消息
            log.info("cipher-request-path: {}", template.path());
            log.info("cipher-request-bodyStr : {}", bodyStr);
        } catch (Exception e) {
            log.error("CipherInterceptor error :", e);
        }
    }

    /**
     * 请求结束
     */
    public void end() {
        if (log.isInfoEnabled()) {
            long cost = System.currentTimeMillis() - start;
            log.info("--- {} 套件请求结束-耗时： {} ms ---", tranId, cost);
        }
    }

}

六、再次补充（高并发情况下，第五步有bug。最后改用了MDC）

改造博文链接：MDC改造

任何想法，欢迎留言讨论