什么？我一行日志代码竟然让接口响应延迟了1s

一、背景

在某次开发过程中，对于一个接口，我只是加了一行代码竟然让接口响应延迟大大增加，感觉是很小一个错误，在此记录一下。

二、情景复现

先简单模拟一下当时的代码：

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.concurrent.TimeUnit;

@RestController
@Slf4j
public class TestController {

    @GetMapping("/hello")
    public String hello(String type) {
        if ("old".equals(type)) {
            log.debug("type is old: {}", test());
        }
        return "hello," + type;
    }

    private String test() {
        try {
            // 模拟方法内容耗时
            TimeUnit.SECONDS.sleep(1);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println("test method run...");
        return "old";
    }

}

把应用日志级别指定为INFO级别：

logging:
  level: 
    root: info

代码逻辑很简单，参数type如果是old，日志级别是debug的话，需要打印一下debug日志，debug日志中需要调用一个方法。

下面我们进行测试：

• 首先测试正常参数

  

  可以看到此时响应时间在几十毫秒的样子。

• 测试特殊参数

  

  可以看到此时响应时间增长到1000多毫秒了，两者只是一行日志的区别。

三、问题解决

通过查看应用日志可以发现，即使是日志级别为debug才会打印的日志信息，也会触发里面的方法执行：

解决方法也很简单，增加一个判断就行，修改代码：

@GetMapping("/hello")
    public String hello(String type) {
        if ("old".equals(type)) {
            if (log.isDebugEnabled()) { // 判断是否是debug级别日志，否则不触发test()方法执行
                log.debug("type is old: {}", test());
            }
        }
        return "hello," + type;
    }

重新测试：

可以看到此时，方法耗时已经下降到正常范围了，通过应用日志也可以发现test()方法不再执行。