Hikari: Connection is not available, request timeout after 30000ms

Ngày xửa ngày xưa… mà cũng không xưa lắm, câu chuyện xảy ra mới cách đây vài năm trước…

Mình tin rằng không ít các Java Developer đã từng gặp dòng lỗi ám ảnh này, và nếu nó xảy ra đúng vào 30 hay mùng 1 Tết thì đúng là… không còn từ gì có thể diễn tả được cảm xúc lúc này.

Nhưng đừng lo, nếu chuyện đó xảy ra thì hi vọng Google đã kịp index bài viết của mình để các bạn search ra và xử lí một cách nhanh gọn lẹ, sớm quay về chén chú chén anh sum vầy ngày xuân.

Theo đúng thể lệ chương trình, mình có đôi ba lời chúc mừng văn mẫu gửi đến cộng đồng Viblo như sau:

• Vài phút biến thành vài giờ vì đọc bài của chủ thớt mà chẳng hiểu gì cả. Thôi thì lại có thêm 365 ngày nữa đọc lại đến khi nào hiểu thì thôi.
• Chúc cộng đồng Viblo năm mới vui vẻ, dồi dào sức khỏe, mọi sự hanh thông công danh tấn tới, nhớ click upvote và bookmark cho mình nhé (1 lần là được rồi k cần click 2 lần đâu).

Quay lại chủ đề chính, nếu bạn đang gặp lỗi Hikari: Connection is not available, request timeout after 30000ms mà chưa tìm ra cách xử lí thì bài viết này chính xác là dành cho bạn. Let’s go!

Buy me a coffee & give your kindness to the world

1) Scenario

Các dự án với Java thường được phát triển với Spring ecosystem, và tất nhiên dự án của mình cũng vậy, bao gồm:

• Spring Boot
• Spring Web
• Spring Validation
• Spring Data JPA
• …

Quan trọng nhất là 2 default config:

• Spring DataJPA: sử dụng Hikari để quản lí connection pool.
• Spring Web: mặc định sử dụng config spring.jpa.open-in-view=true.

Vậy 2 config trên thì có gì đặc biệt và quan trọng?

Câu chuyện cũng chẳng có gì, mọi thứ đều rất ổn, cho đến khi release project lên prod được vài ngày.

Thỉnh thoảng app bắn lỗi Hikari: Connection is not available, request timeout after 30000ms. Anh em nghĩ chắc do setting config app.datasource.default.configuration.maximum-pool-size thấp quá, trước mắt cứ tăng xem thế nào, trong lúc đó sẽ tìm hiểu root cause và xử lí tiếp.

Và đúng như dự đoán, service sống lại, anh em lại có buổi nhậu chúc mừng… ấy thế nhưng còn chưa kịp hoàn hồn thì tiếp tục vẫn là Hikari: Connection is not available… còn chưa kịp nhậu xong mà -_-.

Chém thế chứ làm gì có buổi nhậu nào.. haizz..

2) Investigation

Sớm muộn gì cũng phải tìm root cause chứ cứ nâng maximum-pool-size cũng không phải là cách hay, team tiến hành review lại source code và đưa ra 2 phán đoán chính:

• Heavy read/write query, thời gian thực hiện transaction quá lâu.
• Lỗi Hikari (nhưng chắc là không phải ).

2.1) Long running transaction

Cùng quay lại config cho Hikari pool:

• app.datasource.default.configuration.connection-timeout=30000
• app.datasource.default.configuration.maximum-pool-size=50

Dựa vào 2 config này của Hikari, ta có thể hiểu exception sẽ xảy ra khi thỏa mãn 2 điều kiện:

• Số lượng connection đang bị chiếm dụng đã đạt đến limit = 50.
• Cả 50 connections đều bị chiếm dụng quá connection-timeout = 30s.

Như vậy, khi thực hiện transaction và chờ quá 30s mà không có bất kì connection nào available, lỗi sẽ xảy ra.

Nhưng việc tất cả các connection đều bị chiếm dụng quá 30s thật sự khó có thể tin được. Team tiến hành kiểm tra tất cả các query, các heavy read/write nhưng không thu được thêm manh mối gì. Các query đa số được thực hiện dưới 500ms, một vài query phức tạp chỉ trong khoảng 1 – 2s.

Do chưa tìm thêm được nguyên nhân gì, team chuyển hướng sang nghi ngờ lỗi do Hikari .

2.2) Hikari lỗi

Và chắc chắn là không phải rồi, vì nếu có lỗi thì đây là lỗi rất nghiêm trọng, cộng đồng Java rộng lớn như vậy mà chẳng nhẽ không có ai report, lại đến lượt các anh em dev Đông Lào như mình ra tay? Team cùng các chuyên gia đã mày mò đọc source-code của Hikari, đồng thời test rất kĩ nhưng không hề có lỗi gì liên quan đến Hikari connection pool.

Mọi chuyện thật sự bế bắc…

2.3) Business flow

Mọi thứ dường như đi vào ngõ cụt… team quyết định quay lại phương án ban đầu, review source code, thống kê lại các business flow và execution time cho từng loại flow. Chốt lại có 2 tình huống:

• API call with internal execution only.
• API call with external 3rd-party.

Với trường hợp đầu tiên, API call từ client đến services và call nội bộ giữa các micro-services với nhau, total execution time < 30s.

Trường hợp thứ hai, do phụ thuộc vào các 3rd-party nên thỉnh thoảng total execution time > 30s.

Tiếp tục phân tích lại execution time cho các loại communication:

• Avg execution time cho database transaction rơi vào khoảng 15 – 500 ms.
• Avg execution time cho external call đến các micro-service khoảng 50 – 1000ms.
• Avg execution time cho external call đến 3rd-party khoảng 80 – 40000ms, cá biệt có trường hợp đến 50 – 60s.

Như vậy với cả 2 lần review code, phân tích execution time của database transaction đều không quá 5s chứ chưa nói đến 30s. Vậy hà cớ làm sao mà lại connection is not available?

Chỉ có duy nhất số liệu về các external call đến 3rd-party là quá 30s, tuy nhiên có vẻ như chẳng liên quan gì đến connection is not available.

Team quyết định hạ số lượng maximum-connection xuống 2, run với scenario call/không call đến external 3rd-party (tất nhiên trên môi trường test nhé). Trường hợp call đến 3rd-party thay bằng Thread.sleep().

Và kết quả quá bất ngờ… khi bỏ các externall đến 3rd-party, application không còn gặp lỗi connection is not available. May quá, mặc dù chưa hiểu vì sao nhưng ít nhất đã có thêm chút manh mối.

Sau thêm nửa ngày tìm kiếm lùng sục khắp nơi, team đã tìm ra được root-cause, chính là do thằng của nợ spring.jpa.open-in-view=true!

3) spring.jpa.open-in-view

Vậy cụ thể config spring.jpa.open-in-view là cái của khỉ gì?

Trước khi trả lời câu hỏi này, hãy cùng đi qua cách thức Spring thực hiện các API với config spring.jpa.open-in-view=true đã để hiểu nó có liên quan gì đến external call, mà đáng nhẽ ra nó phải không liên quan mới đúng.

Mặc định, giá trị config của spring.jpa.open-in-view là true. Với config này, Spring thực hiện API có thao tác với database transaction như sau:

• Open session để làm việc với database.
• Session request connection và duy trì trong suốt quá trình xử lí của API chứ không close ngay khi thực hiện xong database transaction.

Lạ chưa, và chính vì lí do đó nên thời gian chiếm dụng connection là tổng execution time của toàn bộ flow bao gồm: database transaction, long running task, external call đến 3rd-party. Thời gian thực hiện transaction có thể chỉ 50ms, nhưng thời gian thực hiện các tác vụ nặng + thời gian external call > 30s thì connection cũng phải chờ toàn bộ flow complete mới được giải phóng.

Quá nhọ…

Nhưng vì sao không giải phóng connection luôn, lí do gì mà Spring lại set default value cho spring.jpa.open-in-view là true, lợi ích của nó là gì?

Có thể hiểu một cách đơn giản rằng open-in-view là cơ chế để Spring dùng Session để thực hiện lazy loading liên quan đến association mapping giữa các hibernate entity (@Entity).

Ví dụ với đoạn code sau:

Khai báo entity:

@Entity@Getter@Setter@Table(name ="theater")publicclassTheater{@Id@GeneratedValue(strategy =GenerationType.IDENTITY)privatelong id;@ColumnprivateString code;@ColumnprivateString name;}@Entity@Getter@Setter@Table(name ="room")publicclassRoom{@Id@GeneratedValue(strategy =GenerationType.IDENTITY)privatelong id;@ManyToOne(fetch =FetchType.LAZY)@JoinColumn(name ="theater_id")privateJpaTheater theater;@ColumnprivateString name;}

Với class Room, ta sử dụng fetchType=LAZY vì có những trường hợp không cần fetch theater lên ngay, cái này chắc chắn đã có rất nhiều các chuyên gia hướng dẫn cho chúng ta, tuy nhiên vô tình nó tạo ra mộtlỗ hổng vô cùng lớn đằng sau mà lại không ai nói cho chúng ta biết. Lỗ hổng gì thì theo dõi tiếp nhé.

Ở service layer, thực hiện dòng lệnh sau:

@Slf4j@Service@RequiredArgsConstructorclassRoomService{privatefinalRoomRepository roomRepository;publicvoidtest(){
        val roomOpt = roomRepository.findById(1L);if(roomOpt.isEmpty()){return;}
        
        val theater = roomOpt.get().getTheater();
        log.info("Theater name: {}", theater.getName());}}

Với default config open-on-view, đoạn code trên sẽ được thực thi bình thường. Tuy nhiên nếu update config về false, tức là spring.jpa.open-in-view=false, khi chạy đoạn code trên sẽ throw ra lỗi LazyInitializationException - no Session. Thú vị chưa.

Điều đó có nghĩa là chúng ta không thể sử dụng fetch lazy được nữa, thay vào đó toàn bộ phải fetch eager. Nhưng nếu fetch eager mà không sử dụng với các association entity đó thì thật lãng phí và hơi tốn performance?

Qua ví dụ trên chắc chắn chúng ta đã hiểu mục đích của spring.jpa.open-in-view là gì rồi. Và theo các chiên gia thì Open session in view là một anti-pattern, nhưng vì sao Spring lại để nó là defaut config? Theo mình phỏng đoán thì lí do là:

• Nó là framework nên cần support tận răng cho developer với các feature vô cùng ảo diệu như ví dụ lazy loading phía trên.

4) Conclusion

Sau khi tìm được root cause và fix ngon lành chỉ với 1 dòng code thì team cũng đã được đi chén chú chén anh ăn mừng chiến thắng.

Nhưng.. câu chuyện chưa dừng lại ở đó, vì một khi đã disable open-session-in-view thì không còn cơ chế lazy loading nữa… và phải refactor code: sửa các assication giữa các entity và fetch thông qua join hoặc DTO projection. Chi tiết các bạn có thể tham khảo tại đây nhé.

P/S: xin chúc mừng năm mới toàn thể cộng đồng Viblo một lần nữa tránh trường hợp BTC scan bài bỏ sót mất lời chúc . Happy new year!!!

Reference

• https://www.baeldung.com/spring-open-session-in-view
• https://vladmihalcea.com/the-open-session-in-view-anti-pattern