快捷導(dǎo)航

springboot 項(xiàng)目某個(gè)接口響應(yīng)特別慢問(wèn)題排查分析

更新時(shí)間：2025年12月08日 17:19:07 作者：ByteX

文章描述了一個(gè)Spring Boot項(xiàng)目中某個(gè)接口請(qǐng)求日志顯示耗時(shí)極短,但通過(guò)Postman發(fā)起相同請(qǐng)求時(shí)耗時(shí)顯著增加的問(wèn)題,經(jīng)過(guò)排查,發(fā)現(xiàn)耗時(shí)主要集中在自定義的ControllerInterceptor中的logBefore方法,特別是SensitiveInfoSerialize.getJson方法,感興趣的朋友跟隨小編一起看看吧

問(wèn)題現(xiàn)象

接口請(qǐng)求日志顯示耗時(shí)僅為幾十毫秒，但通過(guò)Postman發(fā)起相同請(qǐng)求時(shí)，實(shí)際耗時(shí)卻高達(dá)7秒多。

[2025-12-02 09:06:27.344]-[INFO]-[http-nio-3012-exec-3]-[logId:6600b2f0-8d68-4c2c-a7b5-bce11a42e140]-[com.xxx.interceptor.ControllerInterceptor.info:63] 調(diào)用 接口：//task/retry Class:com.xxx.xxx.xxx.controller.TaskController,Method:taskRetry,Request:101   
SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@63bd0ef2] was not registered for synchronization because synchronization is not active
JDBC Connection [com.mysql.jdbc.JDBC4Connection@3448c914] will not be xxxd by Spring
==>  Preparing: select id, task_code, task_name, task_desc, task_execute_time, task_over_time, task_timer, file_path, status, task_type, create_name, update_name, create_date, update_date from r_task where id = ? and status = ? 
==> Parameters: 101(Integer), 4(Byte)
<==      Total: 0
Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@63bd0ef2]
[2025-12-02 09:06:27.354]-[WARN]-[http-nio-3012-exec-3]-[logId:6600b2f0-8d68-4c2c-a7b5-bce11a42e140]-[com.xxx..xxx.service.impl.RetryTaskServiceImpl.taskRetry:50]-任務(wù)重試任務(wù)查詢(xún)?yōu)榭?id:101
[2025-12-02 09:06:27.355]-[INFO]-[http-nio-3012-exec-3]-[logId:6600b2f0-8d68-4c2c-a7b5-bce11a42e140]-[com.xxx.interceptor.ControllerInterceptor.logReturn:81]-Class:com.xxx..xxx.controller.TaskController,Method:taskRetry,Response:{"code":"999","msg":"任務(wù)重試失敗"}

postman請(qǐng)求示例

問(wèn)題排查

先用arthas的 trace命令 確定哪塊執(zhí)行比較耗時(shí)

    `---[6792.636ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:intercept()
        +---[0.0061ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:getTarget() #655
        +---[0.005ms] org.springframework.aop.framework.AdvisedSupport:getInterceptorsAndDynamicInterceptionAdvice() #659
        +---[0.0079ms] org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation:<init>() #673
        +---[6792.5681ms] org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation:proceed() #673
        |   `---[10.2326ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:intercept()
        |       +---[0.0044ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:getTarget() #655
        |       +---[0.0047ms] org.springframework.aop.framework.AdvisedSupport:getInterceptorsAndDynamicInterceptionAdvice() #659
        |       +---[0.0092ms] org.springframework.aop.framework.AopProxyUtils:adaptArgumentsIfNecessary() #668
        |       +---[10.1483ms] org.springframework.cglib.proxy.MethodProxy:invoke() #669
        |       +---[0.0034ms] org.springframework.aop.framework.CglibAopProxy:access$000() #675
        |       `---[0.0031ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:releaseTarget() #680
        +---[0.0034ms] org.springframework.aop.framework.CglibAopProxy:access$000() #675
        `---[0.0025ms] org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor:releaseTarget() #680

經(jīng)過(guò)斷點(diǎn)調(diào)試，程序最終進(jìn)入了自定義的ControllerInterceptor中的logBefore方法。該方法的主要邏輯相對(duì)簡(jiǎn)單，主要用于打印請(qǐng)求日志并對(duì)輸入?yún)?shù)進(jìn)行脫敏處理。問(wèn)題出在負(fù)責(zé)參數(shù)脫敏的SensitiveInfoSerialize.getJson方法上。

通過(guò)斷點(diǎn)跟蹤發(fā)現(xiàn)，程序是在MethodBeforeAdviceInterceptor中執(zhí)行this.advice.before這行代碼時(shí)進(jìn)入自定義ControllerInterceptor的。

public class MethodBeforeAdviceInterceptor implements MethodInterceptor, Serializable {
    private MethodBeforeAdvice advice;
    public MethodBeforeAdviceInterceptor(MethodBeforeAdvice advice) {
        Assert.notNull(advice, "Advice must not be null");
        this.advice = advice;
    }
    public Object invoke(MethodInvocation mi) throws Throwable {
        this.advice.before(mi.getMethod(), mi.getArguments(), mi.getThis());
        return mi.proceed();
    }
}

ControllerInterceptor 的logBefore

 /**
     * /**
     * 記錄輸入日志
     *
     * @param joinPoint
     */
    @Before(value = "controllerService()")
    public void logBefore(JoinPoint joinPoint) {
        LogUtil.bindLogId(UUID.randomUUID().toString());
        String className = joinPoint.getTarget().getClass().getName();
        String methodName = joinPoint.getSignature().getName();
        Object[] args = joinPoint.getArgs();
        if (ArrayUtils.isNotEmpty(args)) {
            LogHelper.info(logger, "調(diào)用", "接口：" + logTool.getServiceKey(), "Class:" + className
                    + ",Method:" + methodName + ",Request:" + SensitiveInfoSerialize.getJson(args[0]), "", "", "");
        }
    }

這段代碼的核心邏輯是：

遍歷 Java Bean 的所有字段
識(shí)別帶有 SensitiveInfo 注解的 String 類(lèi)型字段
對(duì)這些字段執(zhí)行脫敏處理
對(duì)嵌套對(duì)象、數(shù)組、集合和 Map 進(jìn)行遞歸處理

需要注意的是，這是一個(gè)內(nèi)部工具類(lèi)，雖然具體實(shí)現(xiàn)不便展示，但實(shí)際使用中存在一些需要注意的問(wèn)題。

結(jié)論

根本原因是對(duì)參數(shù)進(jìn)行遞歸的時(shí)候沒(méi)有排除基本數(shù)據(jù)類(lèi)型，導(dǎo)致對(duì)基本數(shù)據(jù)類(lèi)型的字段進(jìn)行遞歸導(dǎo)致耗時(shí)很長(zhǎng)。

所以使用遞歸時(shí)要特別注意退出條件，不然可能會(huì)導(dǎo)致耗時(shí)很長(zhǎng)甚至棧溢出。

到此這篇關(guān)于springboot 項(xiàng)目某個(gè)接口響應(yīng)特別慢排查的文章就介紹到這了,更多相關(guān)springboot接口響應(yīng)慢內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

您可能感興趣的文章: