Distributed Tracing: request chậm ở service nào?

Hệ thống spring-cloud-demo giờ đã có gateway, Feign, Resilience4j, event qua Stream. Bài này giải quyết câu hỏi mà ai vận hành microservices cũng gặp: request chậm, nhưng chậm ở đâu?

1. Bài toán

User báo: "Đặt hàng mất 4 giây". Request đi qua:

Client
  |
  v
api-gateway ──> order-service ──> payment-service ──> PostgreSQL
                     |
                     +──> inventory-service
                     |
                     +──> RabbitMQ ──> notification-service

2. Vấn đề

• Mỗi service có log riêng, trên máy/pod riêng. Mở 4 file log, tìm theo thời gian, đoán dòng nào cùng một request.
• Khi có 500 request/giây, log các request trộn vào nhau, không ghép được.
• Không biết 4 giây chia ra thế nào: gateway? Feign sang payment? query DB? retry của Resilience4j?

Cần một mã chung đi theo request qua mọi service, và đo thời gian từng đoạn.

3. Giải pháp: traceId và spanId

Công cụ trong Spring:

• Spring Cloud Sleuth: dùng ở Spring Boot 2. Không hỗ trợ Boot 3.
• Micrometer Tracing: thay Sleuth từ Boot 3. Là một facade (giống SLF4J cho log), bên dưới chọn bridge: Brave hoặc OpenTelemetry.
• Spring Boot Actuator tự cấu hình tracing cho RestTemplate/RestClient/WebClient, Feign, Gateway, Spring Cloud Stream, JDBC (qua thư viện bổ sung).

4. Code từng bước

Bước 1: Dependency (mọi service: gateway, order, payment, inventory, notification):

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<!-- gửi span tới Zipkin -->
<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-exporter-zipkin</artifactId>
</dependency>
<!-- Feign cần thêm để có span cho từng call -->
<dependency>
    <groupId>io.github.openfeign</groupId>
    <artifactId>feign-micrometer</artifactId>
</dependency>

Muốn gửi sang Tempo/collector chuẩn OTLP thì thay exporter Zipkin bằng opentelemetry-exporter-otlp.

Bước 2: Config (đặt chung trong application.yml của config-server repo):

management:
  tracing:
    sampling:
      probability: 1.0        # dev: 100%. Prod: 0.05 - 0.1
  zipkin:
    tracing:
      endpoint: ${ZIPKIN_URL:http://localhost:9411/api/v2/spans}

logging:
  pattern:
    level: "%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]"

spring:
  cloud:
    openfeign:
      micrometer:
        enabled: true

Bước 3: Code Java. Phần lớn tự động. Chỉ cần dùng client do Spring tạo (inject RestClient.Builder, không new RestTemplate()), và thêm span riêng cho đoạn logic muốn đo:

@Service
public class PaymentService {
    private static final Logger log = LoggerFactory.getLogger(PaymentService.class);
    private final ObservationRegistry registry;
    private final PaymentGatewayClient gatewayClient;

    public PaymentService(ObservationRegistry registry, PaymentGatewayClient gatewayClient) {
        this.registry = registry;
        this.gatewayClient = gatewayClient;
    }

    public PaymentResponse pay(PaymentRequest req) {
        log.info("Processing payment for order {}", req.orderId());
        return Observation.createNotStarted("payment.charge", registry)
                .lowCardinalityKeyValue("provider", "vnpay")
                .observe(() -> gatewayClient.charge(req));   // span riêng + metric thời gian
    }
}

Hoặc gọn hơn với annotation @Observed(name = "payment.charge") (cần thêm spring-boot-starter-aop).

Bước 4: Test

docker run -d -p 9411:9411 openzipkin/zipkin

curl -i -X POST http://localhost:8080/api/orders \
  -H "Content-Type: application/json" \
  -d '{"productId":"P01","quantity":2}'

Log các service cùng một traceId:

api-gateway       INFO [api-gateway,6f1c2a9e8b...,a1b2...]       Route order-service
order-service     INFO [order-service,6f1c2a9e8b...,c3d4...]     Creating order
payment-service   INFO [payment-service,6f1c2a9e8b...,e5f6...]   Processing payment for order 1001

Mở http://localhost:9411, tìm traceId đó, thấy biểu đồ thời gian:

api-gateway  POST /api/orders           |██████████████████████████████| 4.1s
 order-service POST /orders              |█████████████████████████████ | 4.0s
  inventory-service POST /reserve        |██                            | 0.15s
  payment-service POST /payments         |   ██████████████████████████ | 3.7s
   payment.charge (vnpay)                |    █████████████████████████ | 3.6s  ← thủ phạm
  rabbit send order.events               |                             █| 0.01s

5. Cách hoạt động

api-gateway   tạo traceId=6f1c, span A
     | header: traceparent: 00-6f1c...-A...-01
     v
order-service đọc header -> cùng traceId, span B (parent A)
     | Feign tự thêm traceparent (span C, parent B)
     v
payment-service -> span D (parent C)
     |
     +-- mỗi span kết thúc thì gửi bất đồng bộ (batch) tới Zipkin/Tempo
     +-- traceId/spanId đặt vào MDC -> log pattern in ra

order-service --> RabbitMQ/Kafka
     | traceparent nằm trong message headers (Spring Cloud Stream tự làm)
     v
notification-service -> span con, cùng traceId

Định dạng header W3C: traceparent: 00-<traceId 32 hex>-<spanId 16 hex>-<flags>. Flag 01 nghĩa là "đã được sample, hãy ghi lại".

Sampling: quyết định ở đầu trace (head-based), service sau tuân theo flag. Probability 0.1 nghĩa là ghi 10% trace. traceId vẫn có trong log 100% request, chỉ là span không được gửi lên backend.

6. So sánh

7. Khi nào nên dùng / không nên dùng

• Nên: từ khi có 2-3 service gọi nhau. Chi phí thêm thấp, lợi ích debug rất lớn. Ít nhất luôn có traceId trong log.
• Cẩn thận: sampling 100% ở prod tốn storage và CPU; không cho dữ liệu nhạy cảm (số thẻ, token) vào tag của span; tag high-cardinality (userId) làm nổ metric.
• Không thay thế: metric (Prometheus) để biết "có chậm không", log để biết "lỗi gì". Trace trả lời "chậm/lỗi ở đâu". Ba trụ observability đi cùng nhau.

Đúng rồi, đây là lỗi hay gặp nhất. Trace context được lưu theo ThreadLocal (MDC cũng vậy). Nhảy sang thread khác thì context không tự đi theo.

http-nio-thread-1  [traceId=6f1c]  createOrder()
      |
      | CompletableFuture.supplyAsync(...)   // ForkJoinPool common
      v
ForkJoinPool-1     [traceId=    ]  sendAnalytics()   ← mất context

Cách sửa: bọc executor để copy context.

@Configuration
public class AsyncTracingConfig {

    @Bean
    public ThreadPoolTaskExecutor taskExecutor() {
        ThreadPoolTaskExecutor ex = new ThreadPoolTaskExecutor();
        ex.setCorePoolSize(8);
        ex.setTaskDecorator(new ContextPropagatingTaskDecorator()); // Spring 6.1+
        return ex;
    }
}

// Với CompletableFuture: truyền executor có context, không dùng common pool
CompletableFuture.supplyAsync(() -> analytics.send(order),
        ContextExecutorService.wrap(Executors.newFixedThreadPool(4)));

ContextPropagatingTaskDecorator và ContextExecutorService đến từ thư viện context-propagation của Micrometer. Với WebFlux/Reactor thì bật Hooks.enableAutomaticContextPropagation().

Lý do thứ hai hay gặp: tự new RestTemplate() thay vì inject RestTemplateBuilder, nên không có interceptor gắn traceparent, service sau tạo trace mới.

Bạn hiểu gần đúng, chỉ cần chỉnh một điểm. Context được truyền qua message header: Spring Cloud Stream (hoặc KafkaTemplate/RabbitTemplate khi bật observation) thêm traceparent vào header lúc gửi, consumer đọc ra và tạo span con. Nên đúng là cùng traceId, dù xử lý sau 10 phút.

spring:
  cloud:
    stream:
      bindings:
        orderCreated-in-0:
          consumer:
            ...
  kafka:
    template:
      observation-enabled: true     # khi dùng Spring Kafka trực tiếp
    listener:
      observation-enabled: true
  rabbitmq:
    template:
      observation-enabled: true
    listener:
      simple:
        observation-enabled: true

Điểm cần chỉnh: trace kiểu này kéo rất dài trên biểu đồ (có khoảng trống 10 phút), và một event có thể có 5 consumer. Nhiều đội chọn cho consumer bắt đầu trace mới có link về trace gốc (span link) thay vì làm span con. Cả hai đều đúng, quan trọng là thống nhất trong team.

Với Outbox thì cần lưu traceparent vào cột của bảng outbox, lúc relay gửi đi thì gắn lại vào header. Nếu không, trace sẽ đứt ở outbox.

Q1. Distributed tracing là gì? traceId và spanId khác nhau thế nào?

🇻🇳 Tiếng Việt:

Distributed tracing theo dõi một request đi qua nhiều service. traceId là mã chung cho cả hành trình, giống nhau ở mọi service. Span là một đoạn công việc có thời gian, như một HTTP call hay một query, mỗi span có spanId và parentId để tạo thành cây. Nhờ vậy em xem được request chậm ở service nào, đoạn nào.

🇬🇧 English:

Distributed tracing follows one request across many services. The traceId identifies the whole journey and is the same in every service. A span is a timed unit of work, like an HTTP call or a query, with its own spanId and a parentId that forms a tree. This shows exactly which service and which step is slow.

Q2. Trong Spring Boot 3 bạn triển khai tracing thế nào?

🇻🇳 Tiếng Việt:

Sleuth không hỗ trợ Boot 3 nữa, em dùng Micrometer Tracing với bridge OpenTelemetry, cộng Actuator và một exporter tới Zipkin hoặc OTLP cho Tempo. Spring tự tạo span cho request vào, Feign, RestClient, WebClient, Gateway và messaging. Em đưa traceId vào log pattern qua MDC, đặt sampling khoảng 10% ở production, và dùng Observation API hoặc @Observed cho đoạn nghiệp vụ muốn đo riêng.

🇬🇧 English:

Sleuth doesn't support Boot 3, so I use Micrometer Tracing with the OpenTelemetry bridge, plus Actuator and an exporter to Zipkin or OTLP for Tempo. Spring instruments incoming requests, Feign, RestClient, WebClient, Gateway and messaging automatically. I put the traceId in the log pattern through MDC, use around 10% sampling in production, and use the Observation API or @Observed for custom business spans.

Q3. Trace context được truyền giữa các service như thế nào?

🇻🇳 Tiếng Việt:

Qua header. Với HTTP là header W3C traceparent (hoặc B3), chứa traceId, spanId của span cha và flag sampling. Với Kafka/RabbitMQ thì nằm trong message header. Trong một service, context nằm ở ThreadLocal, nên khi dùng @Async hay thread pool phải dùng executor có context propagation, nếu không sẽ mất traceId.

🇬🇧 English:

Through headers. Over HTTP it is the W3C traceparent header, or B3, carrying the traceId, the parent spanId and the sampling flag. With Kafka or RabbitMQ it travels in message headers. Inside a service the context lives in a ThreadLocal, so with @Async or thread pools I need a context-propagating executor, otherwise the traceId is lost.

Q4. Một API chậm trên production, bạn điều tra thế nào?

🇻🇳 Tiếng Việt:

Em bắt đầu từ metric: latency p95/p99 của endpoint tăng từ lúc nào. Rồi lấy một trace chậm trong Tempo hoặc Zipkin, xem span nào chiếm phần lớn thời gian, ví dụ call sang payment hay query DB. Từ traceId em tìm log của đúng request đó ở mọi service để xem lỗi, retry hay timeout. Metric cho biết có vấn đề, trace cho biết ở đâu, log cho biết vì sao.

🇬🇧 English:

I start from metrics: when the p95 or p99 latency of the endpoint went up. Then I open a slow trace in Tempo or Zipkin and find the span that takes most of the time, for example the payment call or a DB query. With the traceId I search the logs of that exact request across all services to see errors, retries or timeouts. Metrics tell me there is a problem, traces tell me where, logs tell me why.

Cách nhớ ngắn gọn

• Trace = cả hành trình; span = một đoạn; traceId đi theo header traceparent.
• Boot 3: Sleuth → Micrometer Tracing + bridge OTel + Zipkin/Tempo.
• traceId vào log qua MDC; đổi thread phải propagate context.
• Prod sampling 5-10%, không cho dữ liệu nhạy cảm vào tag.
• Metric: có chậm không. Trace: chậm ở đâu. Log: vì sao.