Hệ thống "hình như" chậm, nhưng tôi không biết chậm ở đâu

Huy NguyenHuy Nguyen
13 min read

Table of contents

Xin chào ace! Mình là Huy, một backend dev với 2+ năm kinh nghiệm. Nay mình lại ngoi lên viết bài sau một thời gian ngụp lặn :D

TL; DR

Bài viết chia sẻ việc tác giả cài đặt các cơ chế logging ghi lại thời gian query trên ứng dụng Spring Boot và theo dõi nó trên Elastic stack, mục đích để phát hiện tắc nghẽn truy vấn trong ứng dụng và đưa ra giải pháp tối ưu. Đồng thời giới thiệu một số cách thiết lập các dashboard thống kê đơn giản mà hiệu quả. (Không phải AI viết)

Spoil trước kết quả

Đây là kết quả của dashboard thống kê mình thiết lập được. Chi tiết hơn về cách set up và diễn giải thì mình sẽ nói kỹ hơn trong các bước dưới. Do chưa tìm hiểu kỹ về các phần đồ thị nên mình sẽ chỉ sử dụng bảng cho đơn giản. Anh em nếu có cách tiếp cận khác thì hãy comment nha 😁

Lan man

Chuyện là một ngày đẹp trời, anh lead có nhờ mình check hộ một số câu query xem đang dùng ở luồng nghiệp vụ nào. Mình lẩm bẩm rằng tự nhiên ổng nhờ mình check làm gì nhỉ, chắc cũng phải có cái gì đó không ổn ở đây. Thế rồi mình ngồi rà soát lại, và bằng tất cả những kiến thức tối ưu db học được, mình đưa ra một số phỏng đoán rằng tại sao câu lệnh chậm, đồng thời đưa ra một số giải pháp khắc phục. Cá nhân thì mình thấy những phần truy vấn trong db của dự án mình cũng không phức tạp lắm, mục đích bây giờ chỉ cần là phát hiện chậm và xử lý thôi, quá đơn giản.

Ơ thế nghe thì đơn giản đấy? Nhưng phát hiện chậm kiểu gì nhỉ? Mình băn khoăn một hồi, trong đầu mình chợt loé lên ý tưởng sử dụng AOP (Aspect Oriented Programming) hoặc là chọc ngoáy sâu hơn vào Hibernate để thực hiện intercept các method query, ghi lại tên method, bấm giờ và log ra thôi, quá đơn giản. Hệ thống của bên mình đang sử dụng Java + Spring, cùng với Log4j + Kafka + ELK để trace log.

Hôm nay mình sẽ chia sẻ một số cách cài đặt để theo dõi thời gian query đơn giản sử dụng Java + Spring + Log4j + Kafka + ELK (Elastic, Logstash, Kibana) stack. Mục đích là để phía dev chủ động monitor phát hiện được các tắc nghẽn do query chậm trong hệ thống, đồng thời tìm cách khắc phục, xử lý. Ngoài ra mình cũng sẽ chia sẻ thêm cách mình tự dựng lại hệ thống ở công ty trên máy local (rút lõi công nghệ :D). Các stack công nghệ kia cũng là stack chính mà bên mình đang sử dụng, hi vọng sẽ cung cấp thêm góc nhìn cho anh em.

Set up hệ thống sương sương

Kiến trúc hệ thống

Hình trên là kiến trúc của hệ thống mình đang set up.

  1. Ứng dụng Spring Boot ghi log sử dụng log4j2 logging framework kết hợp với KafkaAppender (Appender sử dụng để append log event đến một đích nào đó, ở đây là kafka, đích có thể là file, màn hình console...) để bắn log event lên kafka.

  2. Logstash sẽ tự động pull log từ kafka về.

  3. Logstash sẽ thiết lập data pipeline, tinh chế và đổ dữ liệu sang Elasticsearch.

  4. Người dùng sử dụng Kibana sẽ thiết lập các dashboard quản trị, theo dõi, dữ liệu sẽ được truy vấn từ Elasticsearch.

Set up project Spring Boot CRUD đơn giản

Mình sẽ sử dụng Java 21, Spring Boot 3.4.4, logging framework là Log4j, database thì mình dùng H2 database (một inmemory database, rất thích hợp cho việc phát triển ứng dụng demo nhỏ lẻ), code demo mình sẽ để ở cuối bài cho anh em nào quan tâm. Cơ bản thì sẽ có các API như thế này:

Còn lại tầng service và repository thì anh em tự xem code nhé, CRUD đơn giản thôi.

Chạy các cấu phần ghi log trên docker

Trong file docker-compose này, mình sẽ chỉ chạy 1 node kafka (dùng Kraft mode cho nhẹ), 1 node elasticsearch, 1 node kibana và 1 node logstash. File ở trong link: https://github.com/huyandres2001/query-duration-log/blob/main/docker-compose.yml

Chờ cho chạy lên hết là xong:

Thực hiện tạo index template và ingestion pipeline trên Elasticsearch

Sau khi chạy bước Set up project Spring Boot CRUD đơn giản, ta có sử dụng các thuộc tính queryMethod và duration cho log event, cần phải đánh index trên Elasticsearch để có thể tổng hợp dashboard một cách mượt mà, nhanh chóng. Mình sẽ không đào sâu về bản chất của index trong Elasticsearch trong bài viết này, chỉ cần biết nó giúp cho công việc tổng hợp báo cáo thuận lợi hơn là được.

Tạo index template

Tại sao phải tạo index template? Hiểu đơn giản là nó sẽ giúp mình tạo bộ index mới một cách nhanh, gọn và lẹ với các thuộc tính đã được thiết lập sẵn.

Mở link sau trên browser: http://localhost:5601/app/dev_tools#/console

Paste thông tin sau và click chạy để thực hiện tạo index template. Dưới đây, mình sẽ tạo mapping trên các trường:

  • duration: lưu lại thời gian xử lý chung của các step trong hệ thống, chẳng hạn như thời gian query.

  • httpMethod: lưu lại method mà http request hiện tại đang xử lý xuyên suốt request.

  • httpPath: lưu lại path của api mà http request hiện tại đang xử lý xuyên suốt request.

  • httpRequestDuration: lưu lại thời gian response một http request, gắn với log response trả về.

  • queryMethod: tên repository method của Spring Data.

  • sql: câu lệnh sql thực thi.

  • traceId: một mã giao dịch được gắn xuyên suốt một request.

PUT _index_template/app-logs-template
{
  "index_patterns": [
    "app-logs-*"
  ],
  "template": {
    "mappings": {
      "properties": {
        "contextMap": {
          "properties": {
            "duration": {
              "type": "long",
              "ignore_malformed": false,
              "coerce": true
            },
            "httpMethod": {
              "type": "keyword"
            },
            "httpPath": {
              "type": "keyword"
            },
            "httpRequestDuration": {
              "type": "long"
            },
            "queryMethod": {
              "type": "keyword"
            },
            "sql": {
              "type": "keyword"
            },
            "traceId": {
              "type": "keyword"
            }
          }
        },
        "duration": {
          "type": "long"
        }
      }
    }
  },
  "priority": 200,
  "version": 1
}

Thiết lập ingestion pipeline

Thiết lập ingestion pipeline để làm gì? Dữ liệu sau khi được Logstash pull về từ Kafka sẽ được thiết lập cho chạy qua một ingestion pipeline, trong pipeline này, Logstash sẽ thực hiện transform dữ liệu như được cấu hình dưới đây và đổ sang Elasticsearch.

Ở đây mình sẽ map lại trường contextMap.duration từ kiểu string sang kiểu long. Mình sẽ giải thích kỹ hơn tại sao lại map như vậy ở bước dưới.

PUT _ingest/pipeline/app-logs-pipeline
{
  "description": "Pipeline to convert contextMap.duration and contextMap.httpRequestDuration to long",
  "processors": [
    {
      "script": {
        "lang": "painless",
        "source": "if (ctx.contextMap != null) {\n    if (ctx.contextMap.duration != null) {\n        ctx.duration = Long.parseLong(ctx.contextMap.duration);\n    }\n    if (ctx.contextMap.httpRequestDuration != null) {\n        ctx.contextMap.httpRequestDuration = Long.parseLong(ctx.contextMap.httpRequestDuration);\n    }\n}"
      }
    }
  ]
}

Set up Spring AOP bọc các repository method

Ở bước này, mình đã set up một aspect để bọc lời gọi repository method. Hiểu đơn giản là trước khi bắt đầu truy vấn thì mình bấm giờ, sau khi truy vấn xong mình bấm giờ phát nữa, rồi lấy sau trừ đi trước là ra thời gian thực hiện truy vấn. Ở đây, mình dùng HikariCP làm Connection Pool:

Khi bọc như vậy, thời gian thực hiện của mình thực chất là gồm 2 phần: thời gian thiết lập kết nối đến db và thời gian db truy vấn. Thời gian log ra trong dòng log sẽ bao gồm cả thời gian Hikari thiết lập kết nối, vậy nên thi thoảng nó sẽ lâu hơn bình thường một chút khi mà kết nối chưa có sẵn trong pool.

@Aspect  
@Component  
@Slf4j  
public class QueryExecutionLoggingAspect {  

    //bọc các repository con của JpaRepository  
    @Around("execution(* org.springframework.data.jpa.repository.JpaRepository+.*(..))")  
    public Object logQueryExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {  
        long startTime = System.currentTimeMillis();  
        Object result = joinPoint.proceed();  
        long duration = System.currentTimeMillis() - startTime; 
        //ThreadContext sẽ gắn thêm thuộc tính cho log event 
        ThreadContext.put(QUERY_METHOD, joinPoint.getSignature().toShortString());  
        ThreadContext.put(DURATION, String.valueOf(duration));  
        log.info("Query Method: {} executed in {} ms", joinPoint.getSignature().toShortString(), duration);  
        ThreadContext.remove(QUERY_METHOD);  
        ThreadContext.remove(DURATION);  
        return result;  
    }  
}

Các dòng code ThreadContext.put có mục đích là để mình gắn thêm thuộc tính vào log event, ở đây, mình sẽ gắn thêm thuộc tính queryMethod và duration để tiện cho việc tổng hợp và thống kê sau này.

Chạy thử một vài API

Chạy thử vài lần API tạo user:

curl -X POST --location "http://localhost:8088/users" \  
    -H "Content-Type: application/json" \  
    -d '{  
          "username": "Huy"  
        }'

Và chạy thử vài lần API truy vấn user:

curl -X GET --location "http://localhost:8088/users" \
    -H "Content-Type: application/json"

Thử truy vấn xem log trên giao diện

Vào giao diện xem log tại: http://localhost:5601/app/discover#

Ở trên giao diện, mình tìm theo traceId để lấy tất cả các log xuyên suốt giao dịch và xem được dòng log có tên queryMethod và duration như đã thiết lập.

Thiết lập dashboard quản lý

Vào giao diện tạo dashboard.

Mình sẽ tạo panel giám sát thời gian query theo repository method. Thực hiện mở Lens và tạo, ở phần query, mình sẽ query theo loggerName, tức là tìm theo cái class trong code mà log ra dòng đó, ở phần rows mình sẽ chọn functions Top Value của trường contextMap.queryMethod.

Tại sao lại là contextMap? contextMap là tên của map chứa các thuộc tính của log event. Vì ở trong code, mình đã sử dụng ThreadContext.put() để gắn thêm thuộc tính cho log event, method này đã gắn thêm các thuộc tính vào trong một map được lưu trữ trên chính thread hiện tại.

Ở phần metrics mình sẽ chọn 3 metrics là Average của duration (ở đây, trường này đã được map từ string sang long, việc này sẽ làm cho trường duration có thể dùng được các function số học như Average, Sum… mà string không làm được), Count của Record và Max của duration, đổi tên cột cho dễ đọc, và được bảng như dưới đây.

“Sâu” hơn nữa…

Tuy nhiên, với cách tiếp cận sử dụng Spring AOP để log ra thì mình thấy có một số hạn chế, đó là mình không thực sự theo dõi được câu lệnh đang được thực thi đến bảng đích nào, đặc biệt là khi sử dụng các method có sẵn như save(), findAll()… việc truy vết sẽ rất khó khăn. Nắm bắt được hạn chế này, mình nghĩ chắc sẽ phải có cách nào đó để log ra câu lệnh query. Và rồi mình đã quyết định vọc vạch xuống thư viện của Hibernate, sau đó đưa ra cách tiếp cận sau đây.

Tại bước này, nhiều anh em có thể nghĩ là hoàn toàn có option để cho hibernate log ra câu lệnh query mà, đúng là có option spring.jpa.show-sql=true, nhưng nó không giúp cho mình gắn thêm thuộc tính duration để phục vụ cho thống kê.

Sử dụng Hibernate SPI để customize việc ghi log

Đơn giản thì Hibernate cung cấp cho mình một cách để customize việc tích hợp các extension vào nó, mình đã tận dụng việc này để thay class ghi log trong thư viện của HIbernate bằng class đã customize lại của mình, chi tiết anh em xem code nhé, mình sẽ chỉ liệt kê các phần chính liên quan đến việc lập dashboard thống kê.

Ở đây, mình sẽ gắn thêm thuộc tính sql và duration cho log event.

    @SneakyThrows
    @Override
    public void logSlowQuery(String sql, long startTimeNanos, JdbcSessionContext context) {
        Thread.sleep(10);//simulate query time, should be removed on production
        long queryExecutionMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTimeNanos);
        ThreadContext.put(DURATION, String.valueOf(queryExecutionMillis));
        ThreadContext.put("sql", sql);
        logSlowQueryInternal(context, queryExecutionMillis, sql);
        ThreadContext.remove(DURATION);
        ThreadContext.remove("sql");
    }

    private void logSlowQueryInternal(final JdbcSessionContext context, final long queryExecutionMillis, final String sql) {
        final String logData = "Query took " + queryExecutionMillis + " milliseconds [" + sql + "]";
        log.info("[CustomSqlStatementLogger][logSlowQueryInternal] {}", logData);
        if (context != null) {
            final StatisticsImplementor statisticsImplementor = context.getStatistics();
            if (statisticsImplementor != null && statisticsImplementor.isStatisticsEnabled()) {
                statisticsImplementor.slowQuery(sql, queryExecutionMillis);
            }
        }
    }

Thiết lập dashboard thống kê theo câu lệnh sql

Thiết lập tương tự như bước thiết lập dashboard thống kê ở trên thôi, khác một chút là ở mục rows mình sẽ chọn là Top value của contextMap.sql.

Ok vậy là khá ổn rồi nhỉ, thông tin câu lệnh query khá đầy đủ, giờ mình có thể trace ngược lại phần gốc rễ trong code một cách dễ hơn rồi.

Cải tiến hơn nữa: thiết lập thống kê tổng thời gian query theo từng API

Thiết lập trên ứng dụng

Trước khi ghi log nội dung http request, mình sẽ thêm thuộc tính httpMethod và httpPath vào contextMap để cho tất cả các log event trong request đó có thuộc tính này. Đồng thời, mình sẽ lưu httpRequestStartTime để đến khi request kết thúc, mình có thể sử dụng thuộc tính này để tính toán thời gian xử lý request đó.

    @Override
    public void logRequest(HttpServletRequest httpServletRequest, Object body) {
        Map<String, String> parameters = buildParametersMap(httpServletRequest);
        ThreadContext.put(HTTP_REQUEST_START_TIME, String.valueOf(System.currentTimeMillis()));
        ThreadContext.put(TRACE_ID, StringUtils.defaultIfBlank(httpServletRequest.getHeader(TRACE_ID), UUID.randomUUID().toString()));
        ThreadContext.put(HTTP_METHOD, httpServletRequest.getMethod());
        ThreadContext.put(HTTP_PATH, httpServletRequest.getRequestURI());
        String logMessage = """
                REQUEST
                Method: %s
                Path: %s
                Headers: %s%s%s""".formatted(
                httpServletRequest.getMethod(), httpServletRequest.getRequestURI(), buildHeadersMap(httpServletRequest),
                !parameters.isEmpty() ? "\nParameters: " + parameters : "", body != null ? "\nBody: " + JsonUtils.toJson(body) : ""
        );

        log.info(logMessage);
    }

Trước khi ghi log nội dung response, mình sẽ bắt trường httpRequestStartTime và thực hiện tính toán thời gian xử lý của request, sau đó thêm thuộc tính httpRequestDuration để biểu thị vào các log event thôi.

    @Override
    public void logResponse(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object body) {
        String startTime = ThreadContext.get(HTTP_REQUEST_START_TIME);
        ThreadContext.remove(HTTP_REQUEST_START_TIME);
        Long elapsedTime = System.currentTimeMillis() - Long.parseLong(startTime);
        ThreadContext.put(HTTP_REQUEST_DURATION, String.valueOf(elapsedTime));
        String logMessage = """
                RESPONSE
                Method: %s
                Path: %s
                Headers: %s
                Body: %s""".formatted(
                httpServletRequest.getMethod(), httpServletRequest.getRequestURI(), buildHeadersMap(httpServletResponse),
                JsonUtils.toJson(body)
        );
        log.info(logMessage);
        ThreadContext.remove(HTTP_METHOD);
        ThreadContext.remove(HTTP_PATH);
        ThreadContext.remove(HTTP_REQUEST_DURATION);
    }

Thiết lập dashboard thống kê

Ở đây, phần thống kê sẽ khác một chút so với ở trên.

  • Ở phần rows, mình sẽ chọn 2 mục con:

    • Mục API: mình sẽ chọn 2 field là: contextMap.httpMethod và contextMap.httpPath

    • Mục thứ 2: chọn field contextMap.traceId, Collapse by thì chọn Average

  • Ở phần metrics:

    • Tổng thời gian query trung bình (chưa tính acquire connection) (đây là thời gian query mình log ra ở class customize việc ghi log): Chọn function sum theo trường duration, Filter by class ghi log query (xem ở bước Sử dụng Hibernate SPI để customize việc ghi log)

    • Tổng thời gian query từ repository method (bao gồm acquire connection) (đây là thời gian query mình log ra ở class sử dụng Spring AOP cho việc ghi log, xem ở bước Set up Spring AOP bọc các repository method): Chọn function sum theo trường duration, Filter by class ghi log query.

    • Thời gian phản hồi trung bình: Lấy function Sum theo trường contextMap.httpRequestDuration.

Tada!! Và đây là kết quả:

Kết luận

Ở bên mình thì có nguyên một phòng DBA, dev bên mình cũng không có quyền để mà chủ động vào DB Production giám sát, theo dõi. Vậy nên, việc thiết lập dashboard thống kê này là thực sự cần thiết để nhanh chóng phát hiện tắc nghẽn, tránh để khi DBA báo chậm thì có vẻ tình hình đã khá tệ :D

Ở phần demo trên đây, mình mới chỉ thiết lập đơn giản cho một service, trong kiến trúc microservices, việc thiết lập có thể phức tạp hơn một chút. Cơ bản thì tư tưởng vẫn như vậy, vẫn là thêm thuộc tính cho log event để phân biệt các microservice với nhau.

Nhắc lại một chút, vì mình không hiểu rõ bản chất của các đồ thị lắm nên không biết phải sử dụng nó lúc nào. Mong được các anh em rành rọt về đồ thị, hoặc là có những cách thiết lập chỉ số thống kê nào khác thì cho mình xin thêm góc nhìn ạ 🥰

Well, đọc đến đây thì chắc hẳn là anh em đã khá kiên trì, hoặc là anh em là người đọc từ dưới lên, hoặc là anh em mất kiên nhẫn nên tua đến đây, dù sao thì cảm ơn anh em đã đọc bài viết của mình. Mong bài viết này có thể giúp anh em có thêm góc nhìn, thêm cách để áp dụng vào cải thiện hệ thống của mình.

Hẹn gặp lại anh em trong các bài viết sắp tới!

Phụ lục

Source code: https://github.com/huyandres2001/query-duration-log

Tài liệu tham khảo:

Doc của Elasticsearch https://www.elastic.co/guide/en/elasticsearch/reference/current/docs.html

Doc của Hibernate:

https://docs.jboss.org/hibernate/orm/6.6/integrationguide/html_single/Hibernate_Integration_Guide.html

https://docs.jboss.org/hibernate/orm/6.6/userguide/html_single/Hibernate_User_Guide.html

0
Subscribe to my newsletter

Read articles from Huy Nguyen directly inside your inbox. Subscribe to the newsletter, and don't miss out.

DatabaseOptimizationelasticsearchkibanaSpringbootSpring Data Jpa

Written by

Huy Nguyen
Huy Nguyen