SpringCloud升級之路2020.0.x版-15.UnderTow 訂製

本系列程式碼地址：https://github.com/HashZhang/spring-cloud-scaffold/tree/master/spring-cloud-iiford

我們使用 Spring Boot 的 SPI 機制對 Undertow 進行訂製，主要有如下兩個方面：

需要在 accesslog 中開啟響應時間統計。
期望通過 JFR 監控每個 Http 請求，同時佔用空間不能太大。

接下來我們依次實現這兩個需求：

首先，我們的框架作為基礎元件，應該按照基礎元件的標準來開發，使用這個系列之前介紹的 spring.factories 這個 Spring Boot SPI 機制，在引入我們這個基礎元件依賴的時候，就自動載入對應配置。

然後，對於是否開啟響應時間統計，應該根據使用者配置的 accesslog 格式而定（Undertow 的 accesslog 配置可以參考這個系列之前的文章）。

由此我們來編寫程式碼。目前比較遺憾的是，Spring Boot 對接 Undertow 並沒有直接的配置可以讓 Undertow 開啟響應時間統計，但是可以通過實現 WebServerFactoryCustomizer 介面的方式，對構造 WebServer 的 WebServerFactory 進行訂製。其底層實現原理非常簡單（以下參考原始碼：WebServerFactoryCustomizerBeanPostProcessor.java）：

Spring Boot 中指定了 WebServerFactoryCustomizerBeanPostProcessor 這個 BeanPostProcessor.
WebServerFactoryCustomizerBeanPostProcessor 的 postProcessBeforeInitialization 方法（即在所有 Bean 初始化之前會呼叫的方法）中，如果 Bean 型別是 WebServerFactory，就將其作為引數傳入註冊的所有 WebServerFactoryCustomizer Bean 中進行自定義。

接下來我們來實現自定義的 WebServerFactoryCustomizer

DefaultWebServerFactoryCustomizer

package com.github.hashjang.spring.cloud.iiford.spring.cloud.webmvc.undertow;

import io.undertow.UndertowOptions;
import org.apache.commons.lang.StringUtils;
import org.springframework.boot.autoconfigure.web.ServerProperties;
import org.springframework.boot.web.embedded.undertow.ConfigurableUndertowWebServerFactory;
import org.springframework.boot.web.server.WebServerFactoryCustomizer;

public class DefaultWebServerFactoryCustomizer implements WebServerFactoryCustomizer<ConfigurableUndertowWebServerFactory> {

    private final ServerProperties serverProperties;

    public DefaultWebServerFactoryCustomizer(ServerProperties serverProperties) {
        this.serverProperties = serverProperties;
    }

    @Override
    public void customize(ConfigurableUndertowWebServerFactory factory) {
        String pattern = serverProperties.getUndertow()
                .getAccesslog().getPattern();
        // 如果 accesslog 配置中列印了響應時間，則開啟記錄請求開始時間配置
        if (logRequestProcessingTiming(pattern)) {
            factory.addBuilderCustomizers(builder -> 
                    builder.setServerOption(
                            UndertowOptions.RECORD_REQUEST_START_TIME, 
                            true
                    )
            );
        }
    }

    private boolean logRequestProcessingTiming(String pattern) {
        //如果沒有配置 accesslog，則直接返回 false
        if (StringUtils.isBlank(pattern)) {
            return false;
        }
        //目前只有 %D 和 %T 這兩個佔位符和響應時間有關，通過這個判斷
        //其他的佔位符資訊，請參考系列之前的文章
        return pattern.contains("%D") || pattern.contains("%T");
    }
}

然後我們通過 spring.factories SPI 機制將這個類以一個單例 Bean 的形式，註冊到我們應用 ApplicationContext 中，如圖所示：

在 Configuration 和 spring.factories 之間多了一層 AutoConfiguration 的原因是：

隔離 SPI 與 Configuration，在 AutoConfiguration 同一管理相關的 Configuration。
@AutoConfigurationBefore 等類似的註解只能用在 SPI 直接載入的 AutoConfiguration 類上面才有效，隔離這一層也是出於這個考量。

在系列前面的文章中，我們提到過我們引入了 prometheus 的依賴。在引入這個依賴後，對於每個 http 請求，都會在請求結束返回響應的時候，將響應時間以及響應碼和異常等，記入統計，其中的內容類似於：

http_server_requests_seconds_count{exception="None",method="POST",outcome="SUCCESS",status="200",uri="/query/orders",} 120796.0
http_server_requests_seconds_sum{exception="None",method="POST",outcome="SUCCESS",status="200",uri="/query/orders",} 33588.274025738
http_server_requests_seconds_max{exception="None",method="POST",outcome="SUCCESS",status="200",uri="/query/orders",}  0.1671125
http_server_requests_seconds_count{exception="MissingRequestHeaderException",method="POST",outcome="CLIENT_ERROR",status="400",uri="/query/orders",} 6.0
http_server_requests_seconds_sum{exception="MissingRequestHeaderException",method="POST",outcome="CLIENT_ERROR",status="400",uri="/query/orders",} 0.947300794
http_server_requests_seconds_max{exception="MissingRequestHeaderException",method="POST",outcome="CLIENT_ERROR",status="400",uri="/query/orders",}  0.003059704

可以看出，記錄了從程式開始到現在，以 exception，method，outcome，status，uri 為 key 的呼叫次數，總時間和最長時間。

同時呢，還可以搭配 @io.micrometer.core.annotation.Timer 註解，訂製監控並且增加 Histogram，例如：

//@Timer 註解想生效需要註冊一個 io.micrometer.core.aop.TimedAspect Bean 並且啟用切面
@Bean
public TimedAspect timedAspect(MeterRegistry registry) {
    return new TimedAspect(registry);
}

@Timed(histogram=true)
@RequestMapping("/query/orders")
public xxxx xxxx() {
    .....
}

這樣就會除了上面的資料額外得到類似於 bucket 的統計資料：

http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="0.001",} 0.0
http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="0.001048576",} 0.0
http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="0.001398101",} 0.0
http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="0.001747626",} 0.0
//省略中間的時間層級
http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="30.0",} 1.0
http_server_requests_seconds_bucket{exception="None",method="GET",outcome="SUCCESS",status="200",uri="/facts-center/query/frontend/market-info",le="+Inf",} 1.0

以上這些統計給我們分析問題帶來了如下不便的地方：

採集分析壓力過大：我們採用了 grafana 採集 prometheus 上報的指標資料，grafana 的時序資料庫會將採集到的資料全部儲存。自帶的 http 監控指標過多，一個路徑，一個結果，一個異常，一個方法就有一個特定指標，如果是有將引數作為路徑引數的介面，那麼這個指標就更多更多了，例如將 userId 放入路徑中。我們其實只關注出問題的時間段的請求狀況，但是我們並不能預測啥時候出問題，也就無法按需提取，只能一直採集並儲存，這也就導致壓力過大。
指標對於壓力不敏感，無法很準確的用指標進行報警：由於指標並不是採集後就清空，而是從程式開始就一直採集。所以隨著程式的執行，這些指標對於瞬時壓力的表現波動越來越小。

所以，我們基本不會通過這個指標進行問題定位，也就沒必要開啟了，於是我們禁用這個 http 請求響應採集，目前沒有很優雅的方式單獨禁用，只能通過自動掃描註解中排除，例如：

@SpringBootApplication(
        scanBasePackages = {"com.test"}
        //關閉 prometheus 的 http request 統計，我們用不到
        , exclude = WebMvcMetricsAutoConfiguration.class
)

首先，JFR 採集是程式內的，並且 JVM 做了很多優化，效能消耗很小，可以指定保留多少天或者保留最多多大的 JFR 記錄（儲存在本地臨時目錄），我們可以隨用隨取。
並且，我們可以將我們感興趣的資訊放入 JFR 事件，作比較靈活的定製。
對於某個請求時間過長一直沒有響應的，我們可以分為收到請求和請求響應兩個 JFR 事件。

我們來定義這兩個 JFR 事件，一個是收到請求的事件，另一個是請求響應的事件：

HttpRequestReceivedJFREvent.java

package com.github.hashjang.spring.cloud.iiford.spring.cloud.webmvc.undertow.jfr;

import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.StackTrace;

import javax.servlet.ServletRequest;

@Category({"Http Request"})
@Label("Http Request Received")
@StackTrace(false)
public class HttpRequestReceivedJFREvent extends Event {
    //請求的 traceId，來自於 sleuth
    private final String traceId;
    //請求的 spanId，來自於 sleuth
    private final String spanId;

    public HttpRequestReceivedJFREvent(ServletRequest servletRequest, String traceId, String spanId) {
        this.traceId = traceId;
        this.spanId = spanId;
    }
}

HttpRequestJFREvent.java

package com.github.hashjang.spring.cloud.iiford.spring.cloud.webmvc.undertow.jfr;

import io.undertow.servlet.spec.HttpServletRequestImpl;
import io.undertow.servlet.spec.HttpServletResponseImpl;
import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.StackTrace;

import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import java.util.Enumeration;

@Category({"Http Request"})
@Label("Http Request")
@StackTrace(false)
public class HttpRequestJFREvent extends Event {
    //請求的 http 方法
    private final String method;
    //請求的路徑
    private final String path;
    //請求的查詢引數
    private final String query;
    //請求的 traceId，來自於 sleuth
    private String traceId;
    //請求的 spanId，來自於 sleuth
    private String spanId;
    //發生的異常
    private String exception;
    //http 響應碼
    private int responseStatus;

    public HttpRequestJFREvent(ServletRequest servletRequest, String traceId, String spanId) {
        HttpServletRequestImpl httpServletRequest = (HttpServletRequestImpl) servletRequest;
        this.method = httpServletRequest.getMethod();
        this.path = httpServletRequest.getRequestURI();
        this.query = httpServletRequest.getQueryParameters().toString();
        Enumeration<String> headerNames = httpServletRequest.getHeaderNames();
        StringBuilder stringBuilder = new StringBuilder();
        headerNames.asIterator().forEachRemaining(s -> stringBuilder.append(s).append(":").append(httpServletRequest.getHeader(s)).append("\n"));
        this.traceId = traceId;
        this.spanId = spanId;
    }

    public void setResponseStatus(ServletResponse servletResponse, Throwable throwable) {
        this.responseStatus = ((HttpServletResponseImpl) servletResponse).getStatus();
        this.exception = throwable != null ? throwable.toString() : null;
    }
}

然後，我們仿照文中前面關閉的 WebMvcMetricsAutoConfiguration 中的 WebMvcMetricsFilter 編寫我們自己的 Filter 並仿照註冊，這裡我們只展示核心程式碼：

JFRTracingFilter.java

@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
    HttpRequestJFREvent httpRequestJFREvent = null;
    try {
        //從 sleuth 中獲取 traceId 和 spanId
        TraceContext context = tracer.currentSpan().context();
        String traceId = context.traceId();
        String spanId = context.spanId();
        //收到請求就建立 HttpRequestReceivedJFREvent 並直接提交
        HttpRequestReceivedJFREvent httpRequestReceivedJFREvent = new HttpRequestReceivedJFREvent(servletRequest, traceId, spanId);
        httpRequestReceivedJFREvent.commit();
        httpRequestJFREvent = new HttpRequestJFREvent(servletRequest, traceId, spanId);
        httpRequestJFREvent.begin();
    } catch (Exception e) {
        log.error("JFRTracingFilter-doFilter failed: {}", e.getMessage(), e);
    }

    Throwable throwable = null;
    try {
        filterChain.doFilter(servletRequest, servletResponse);
    } catch (IOException | ServletException t) {
        throwable = t;
        throw t;
    } finally {
        try {
            //無論如何，都會提交 httpRequestJFREvent
            if (httpRequestJFREvent != null) {
                httpRequestJFREvent.setResponseStatus(servletResponse, throwable);
                httpRequestJFREvent.commit();
            }
        } catch (Exception e) {
            log.error("JFRTracingFilter-doFilter final failed: {}", e.getMessage(), e);
        }
    }
}

我們這一節針對 Undertow 進行了兩個定製：分別是需要在 accesslog 中開啟響應時間統計以及通過 JFR 監控每個 Http 請求，同時佔用空間不能太大。下一節，我們將開始介紹我們微服務的註冊中心 Eureka 的使用以及細節配置。

微信搜尋“我的程式設計喵”關注公眾號，每日一刷，輕鬆提升技術，斬獲各種offer：

SpringCloud升級之路2020.0.x版-15.UnderTow 訂製

相關文章