1. Bối cảnh

Tháng trước, một người bạn liên hệ với tôi về vấn đề hiệu suất trong chương trình của công ty anh ấy. Khi bộ nhớ đạt đến một ngưỡng nhất định (2GB+), logic nghiệp vụ trở nên chậm chạp rõ rệt, dẫn đến cảnh báo timeout từ thiết bị đầu cuối. Anh ấy muốn tôi xem xét nguyên nhân. Loại vấn đề này thường khó debug chỉ dựa vào dump, nhưng vì có ngưỡng tăng trưởng rõ ràng, tôi yêu cầu anh ấy chụp một dump khi bộ nhớ đạt 2GB+, càng lớn càng tốt để phân tích.

2. Phân tích chuyên sâu bộ nhớ

2.1 Bộ nhớ chứa những gì?

Debug nâng cao giống như một cuộc điều tra, cần tổng hợp nhiều thông tin rời rạc để xây dựng một chuỗi bằng chứng đáng tin cậy. Đầu tiên, chúng ta dùng lệnh !address -summary để xem bố cục bộ nhớ:

0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    648     7ff6`475ce000 ( 127.962 TB)           99.97%
<unknown>                              1642        8`a5283200 (  34.581 GB)  88.93%    0.03%
Heap                                   5255        0`d170f000 (   3.273 GB)   8.42%    0.00%
Image                                  1922        0`2906ee00 ( 656.433 MB)   1.65%    0.00%
Stack                                   277        0`10d40000 ( 269.250 MB)   0.68%    0.00%
Other                                    61        0`08228000 ( 130.156 MB)   0.33%    0.00%
TEB                                      92        0`000b8000 ( 736.000 kB)   0.00%    0.00%
PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                648     7ff6`475ce000 ( 127.962 TB)           99.97%
MEM_RESERVE                            3011        8`d5107000 (  35.329 GB)  90.86%    0.03%
MEM_COMMIT                             6239        0`e391b000 (   3.556 GB)   9.14%    0.00%

Từ kết quả trên, có thể thấy bộ nhớ đã commit hiện tại là 3.5GB, trong đó heap chiếm 3.2GB. Điều này cho thấy bộ nhớ chủ yếu bị tiêu thụ bởi các tài nguyên không được quản lý (unmanaged). Tiếp theo, tôi yêu cầu bạn tôi bật tùy chọn ust, chụp lại dump và dùng lệnh !heap -s để quan sát phân bố heap NT:

0:000> !heap -s

************************************************************************************************************************
                                              NT HEAP STATS BELOW
************************************************************************************************************************
NtGlobalFlag enables following debugging aids for new heaps:
    stack back traces
LFH Key                   : 0xfadda8b94efde698
Termination on corruption : ENABLED
          Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast 
                            (k)     (k)    (k)     (k) length      blocks cont. heap 
-------------------------------------------------------------------------------------
00000160dead0000 08000002  939860 804212 939080 112851  4562   406  279  17556   LFH
    External fragmentation  14 % (4562 free blocks)
    Virtual address fragmentation  14 % (406 uncommited ranges)
...
000001608b690000 08001002 1845428 1058576 1844648  16053  2856  1243    0   1786   LFH
    Virtual address fragmentation  42 % (1243 uncommited ranges)
...

Kết quả cho thấy heap tại địa chỉ 000001608b690000 chiếm tới 1.8GB. Sau khi lấy mẫu, tôi phát hiện phần lớn dữ liệu liên quan đến thư viện cogxsd.

2.2 Vấn đề có kết thúc ở đây không?

Những ngày sau đó, bạn tôi không tìm ra giải pháp hữu hiệu. Chương trình của anh ấy xử lý hàng loạt ảnh real-time, tài nguyên ảnh lớn là điều hiển nhiên. Anh ấy đã thử nhiều cách nhưng vẫn không cải thiện được độ trễ — thiếu một chuỗi bằng chứng hoàn chỉnh. Vì vậy, tôi quyết định tiếp cận vấn đề trực diện thay vì mãi xoay quanh bộ nhớ.

3. Sự thật qua PerfView

Một thuật ngữ quan trọng trong chương trình quản lý (managed) là "STW" (Stop-The-World), nguyên nhân lớn gây chậm. Tôi yêu cầu bạn tôi ghi lại trace PerfView trong khoảng thời gian hệ thống bị chậm (thiết bị đầu cuối cảnh báo timeout). Anh ấy đã ghi trong 12 phút. Mở PerfView và chọn tab Memory → GCStats:

Kết quả cho thấy trong khoảng thời gian theo dõi, chương trình đã kích hoạt tổng cộng 7363 lần GC, trong đó có 116 lần Full GC. Chi tiết kích hoạt GC như sau:

Tất cả các lần kích hoạt GC đều có nguyên nhân InducedNotForced, tức là GC bị gọi cưỡng bức. Đơn giản hơn, ai đó đang cố tình gọi GC.Collect. Trong các khóa học debug, tôi đã giới thiệu 18 nguyên nhân kích hoạt GC, và "Induced GC" là một trong những nguyên nhân quan trọng nhất cần tránh.

Tiếp theo, chuyển sang tab Event để xem call stack của sự kiện Triggered. Tìm thấy rất nhiều lệnh gọi liên quan đến khởi tạo các đối tượng Avl.Image và Avl.Region:

Khi xem xét mã nguồn của phương thức ProcessImageOne, phát hiện nhiều biến tạm thời như:

• Avl.Image
• Avl.Region

Kiểm tra lại heap thông qua lệnh !dumpheap -stat, số lượng đối tượng Avl.Image và Avl.Region lần lượt là 32,837 và 117,356:

0:000> !dumpheap -stat
Statistics:
              MT    Count    TotalSize Class Name
...
00007ff890744ca8    32837      1313480 Avl.Image
...
00007ff89077b6f8   117356      4694240 Avl.Region

Total 851246 objects
Fragmented blocks larger than 0.5 MB:
            Addr     Size      Followed by
0000016120b3eb70    0.6MB 0000016120bd7be8 Free

Đến đây, chuỗi bằng chứng đã hoàn chỉnh: Khi số lượng đối tượng Image và Region đạt đến ngưỡng nhất định, GC bị kích hoạt ngày càng thường xuyên hơn, dẫn đến thời gian STW tăng lên, khiến chương trình chậm dần và gây ra cảnh báo timeout từ thiết bị đầu cuối.

4. Giải pháp

Cách tiếp cận thông thường cho vấn đề này là pooling tài nguyên: hạn chế việc tạo mới các đối tượng new Image liên tục, giảm thiểu kích hoạt GC nội bộ.

5. Tổng kết

Sự cố sản xuất này có logic rõ ràng và nhấn mạnh tầm quan trọng của việc dựa trên dữ liệu cụ thể thay vì phỏng đoán để tránh đi lạc hướng trong quá trình debug.