Spring AOP 實現方法執行時間監控：從入門到生產級方案

業務痛點

系統響應越來越慢，不知從何優化。需一個低侵入、高性能、可視化的方法級性能監控方案，快速定位慢 SQL、外部呼叫瓶頸。

方案架構

• Spring AOP 切面攔截 Service/Dao 層方法
• ThreadLocal 維護調用鏈樹狀結構
• 閾值過濾：僅記錄超過配置毫秒數的方法及其子調用
• 日誌輸出樹狀耗時，直觀定位熱點

核心配置：BeanNameAutoProxyCreator

<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
    <property name="proxyTargetClass" value="true"/> <!-- CGLIB 代理類 -->
    <property name="interceptorNames">
        <list><idref bean="profilerInterceptor"/></list>
    </property>
    <property name="beanNames">
        <list>
            <value>*Service</value>
            <value>*ServiceImpl</value>
            <value>*Manager</value>
            <value>*ManagerImpl</value>
            <value>*Dao</value>
        </list>
    </property>
</bean>

<bean id="profilerInterceptor" class="com.monitor.ProfilerInterceptor">
    <property name="monitorTime" value="500"/> <!-- 超過 500ms 記錄明細 -->
</bean>

攔截器實現：繼承 AbstractMonitoringInterceptor

public class ProfilerInterceptor extends AbstractMonitoringInterceptor {
    private int monitorTime = 500; // 閾值 ms

    @Override
    protected Object invokeUnderTrace(MethodInvocation invocation, Log logger) throws Throwable {
        String name = createInvocationTraceName(invocation); // 如 com.xxx.Service.method
        boolean needProfile = !PrintProfilerHelper.hasPrintProfilerAnnotation(invocation.getMethod());

        try {
            if (needProfile) Profiler.start(name, monitorTime);
            return invocation.proceed();
        } finally {
            if (needProfile) Profiler.stop(name);
        }
    }

    // getter/setter
}

Profiler 核心：ThreadLocal 管理調用鏈

public class Profiler {
    private static final ThreadLocal<ExecData> DATA_HOLDER = new ThreadLocal<>();
    private static final int DEFAULT_THRESHOLD = 500;

    public static void start(String name) { start(name, DEFAULT_THRESHOLD); }

    public static void start(String name, int threshold) {
        ExecData data = DATA_HOLDER.get();
        ExecNode node = new ExecNode(name, System.currentTimeMillis(), threshold);

        if (data == null) {
            data = new ExecData();
            data.root = node;
            DATA_HOLDER.set(data);
        } else {
            node.setParent(data.currentNode);
            data.currentNode.getChildren().add(node);
        }
        data.currentNode = node;
        data.level++;
    }

    public static void stop(String name) {
        ExecData data = DATA_HOLDER.get();
        if (data == null || data.currentNode == null) return;

        ExecNode node = data.currentNode;
        node.setEndTime(System.currentTimeMillis());
        long elapsed = node.getElapsed();

        // 閾值過濾：僅超過閾值的節點及其祖先輸出日誌
        if (elapsed >= node.getThreshold() || hasSlowChild(node)) {
            logTree(data.root);
        }

        data.currentNode = node.getParent();
        data.level--;
        if (data.level == 0) DATA_HOLDER.remove();
    }

    // 遞歸輸出樹狀日誌
    private static void logTree(ExecNode root) {
        StringBuilder sb = new StringBuilder();
        printNode(sb, root, 0);
        log.info(sb.toString());
    }

    private static void printNode(StringBuilder sb, ExecNode node, int depth) {
        sb.append('[').append(node.getElapsed()).append(', ')
          .append(node.getSelfTime()).append(', ')
          .append(node.getPercent()).append("%, ")
          .append(depth).append("]").append(node.getName()).append('\n');
        for (ExecNode child : node.getChildren()) {
            for (int i = 0; i <= depth; i++) sb.append(i == depth ? "+---" : "|   ");
            printNode(sb, child, depth + 1);
        }
    }
}

日誌輸出示例

[4359, 2, 100%, 0] com.profile.service.impl.OrderServiceImpl.findRecentlyProfile
+---[4357, 4357, 99%, 1] com.profile.dao.GenericMybatisDao.queryPage
+---[1, 1, 0%, 1] com.profile.service.impl.OrderServiceImpl.buildDTO

一眼定位：總耗時 4359ms，其中 4357ms 在 queryPage（SQL 查詢），優化重點明確。

生產環境優化建議

1. 異步日誌：使用 Log4j2 AsyncAppender 或 Kafka 推流，避免日誌 I/O 影響業務
2. 採樣控制：高併發下啟用 10% 採樣，或僅監控核心鏈路
3. 註解開關：@PrintProfiler 標註關鍵方法強制記錄，其餘依賴閾值
4. 指標聚合：對接 Prometheus/Grafana，將方法耗時轉為 Metrics 而非純文本日誌

此方案僅需 2 個類（Interceptor + Profiler）約 150 行代碼，零依賴，部署即用，已在多個高併發系統穩定運行 3 年+。