Thực chiếnĐiều tra một truy vấn chậm, phần 3/3

Điều tra một truy vấn chậm: sửa gốc bằng chỉ mục phủ và hậu kiểm

Sửa gốc một sự cố parameter sniffing bằng chỉ mục phủ trên bảng phân vùng: tính dung lượng, dựng online, sửa staging của SWITCH, kiểm chứng theo hai thứ tự biên dịch, gỡ ép kế hoạch, rồi hậu kiểm và thêm giám sát ở cả SQL Server lẫn API .NET.

Mục lục
  1. 1. Thiết kế chỉ mục phủ
  2. 2. Triển khai chỉ mục phủ an toàn
  3. 3. Kiểm chứng và gỡ ép
  4. 4. Hậu kiểm
  5. 5. Giám sát thêm sau sự cố
  6. 6. Áp dụng trong .NET
  7. 7. Checklist: khi một API đột nhiên chậm
  8. Những chỗ hay hiểu sai
  9. Kết luận
  10. Đọc tiếp
  11. Nguồn

Ép kế hoạch đã tắt sự cố, nhưng nguyên nhân còn đó và kế hoạch bị ghim có thể hết tác dụng mà không báo. Một chỉ mục phủ đúng câu hỏi làm kế hoạch hết nhạy với tham số: khách 42 đọc 3 page, khách thường 9 page. Phần 3 dựng chỉ mục đó an toàn, kiểm chứng, gỡ ép, rồi hậu kiểm và thêm giám sát để lần sau bắt được sớm hơn.

Đọc nhanh

  • Thêm INCLUDE (TrangThai, TongTien) làm seek có thứ tự rẻ hơn scan với mọi khách, nên ai gọi trước cũng ra cùng một kế hoạch.
  • Chỉ mục mới tốn thêm khoảng 96 MB, phải dựng ONLINE, và bảng staging của SWITCH phải đổi theo.
  • Ngay khi chỉ mục đổi, lần ép kế hoạch cũ thất bại NO_PLAN mà ứng dụng không hay biết.
  • Suy giảm kéo dài hơn hai giờ trước cảnh báo; giám sát theo mức bình thường của từng câu bịt lỗ đó.

1. Thiết kế chỉ mục phủ

Thủ tục dbo.usp_DonHang_CuaKhach lấy TOP (50) đơn mới nhất của một khách. Phần 2 cho thấy khi biên dịch cho khách 42 (300.000 đơn), scan ngược PK_DonHang thắng chỉ vì seek phải Key Lookup lấy TrangThai và TongTien. Khi chỉ mục chứa sẵn hai cột đó, seek có thứ tự cộng Top không cần lookup: với khách 42, chi phí ước lượng 0,013, scan ngược vẫn 0,021. Seek thắng với mọi giá trị.

Khóa giữ NgayTao tăng dần, không đổi sang DESC: kế hoạch trên bản thử đọc ngược chỉ mục tăng dần, không Sort, và dừng sau 50 dòng nên đọc xuôi hay ngược tốn như nhau. Giữ khóa thì các câu khác không đổi hành vi, và staging của SWITCH, vốn đòi trùng chiều sắp xếp từng cột khóa, chỉ phải thêm INCLUDE.

Thứ tự giữa các partition phải kiểm chứng, vì chỉ mục chỉ được sắp bên trong từng partition. KB 2965553 mô tả TOP, MAX, MIN trên bảng phân vùng có thể quét toàn bộ chỉ mục khi cột đó không phải cột phân vùng. Ở đây cột sắp xếp là NgayTao, chính cột phân vùng, và trên SQL Server 2019 CU27 kế hoạch là Index Seek Ordered, BACKWARD qua các partition, không có Sort.

Kết luận này chỉ đúng cho đúng câu này. Trên cùng bản thử, thêm AND TrangThai <> 5 vào thủ tục là kế hoạch đổi: khách thường được seek xuôi cộng Top N Sort, còn khi biên dịch cho khách 42, trình tối ưu lại chọn scan ngược PK_DonHang. Kế hoạch seek kèm Sort dùng lại cho khách 42 phải đọc hết 300.000 dòng chỉ mục của khách đó, khoảng 300.000 / 238 ≈ 1.261 page. Mỗi lần sửa câu, chạy lại phép thử ở mục 3 theo cả hai thứ tự biên dịch.

2. Triển khai chỉ mục phủ an toàn

Kích thước tính theo công thức của Page, dòng và extent. Dòng lá của chỉ mục không clustered mang khóa, khóa clustered và cột INCLUDE (NgayTao đã có trong khóa nên không lặp), cộng header 1 byte, null bitmap 3 byte, slot 2 byte.

IX_DonHang_KhachHang hiện tại Chỉ mục phủ
Cột ở tầng lá KhachHangId 4, NgayTao 6, DonHangId 8 Thêm TrangThai 1, TongTien 9
Dòng lá 18 + 1 + 3 = 22 byte 28 + 1 + 3 = 32 byte
Dòng mỗi page 8.096 / 24 = 337 8.096 / 34 = 238
Page lá cho 10 triệu dòng khoảng 29.674 khoảng 42.017
Dung lượng khoảng 232 MB khoảng 328 MB

Chênh lệch khoảng 12.343 page, chừng 96 MB. Bản thử đo được dòng lá 22 và 32 byte, cây sâu 3 tầng ở mỗi partition, khớp ước lượng. Trên máy thật, đo trước bằng sys.dm_db_partition_stats:

Kích thước từng chỉ mục của dbo.DonHangSQL · 10 dòng
SELECT
    i.name,
    SUM(ps.used_page_count) AS page_dung,
    SUM(ps.used_page_count) * 8 / 1024 AS mb
FROM sys.dm_db_partition_stats AS ps
JOIN sys.indexes AS i
    ON i.object_id = ps.object_id
   AND i.index_id = ps.index_id
WHERE ps.object_id = OBJECT_ID(N'dbo.DonHang')
GROUP BY i.name;

Ba ràng buộc của lần dựng:

  • Log: recovery model FULL ghi log cỡ kích thước chỉ mục mới, vài trăm MB. Log 8 GB với log backup 15 phút một lần đủ chỗ; xem sys.dm_db_log_space_usage trước khi chạy.
  • tempdb: SORT_IN_TEMPDB = ON cần chỗ cỡ kích thước chỉ mục.
  • Khóa: ONLINE = ON vẫn giữ S rất ngắn lúc đầu và Sch-M rất ngắn lúc cuối. Sch-M chờ các lần gọi đang chạy, lần gọi mới xếp sau nó, nên chạy lúc vắng. WAIT_AT_LOW_PRIORITY cho CREATE INDEX chỉ có từ SQL Server 2022.

Lệnh chạy lúc 22:00 thứ Ba 2026-10-06:

CREATE INDEX IX_DonHang_KhachHang
    ON dbo.DonHang (KhachHangId, NgayTao)
    INCLUDE (TrangThai, TongTien)
    WITH (DROP_EXISTING = ON, ONLINE = ON, SORT_IN_TEMPDB = ON, MAXDOP = 4)
    ON ps_DonHang_Ngay (NgayTao);

Bản Standard không có ONLINE

Trên SQL Server tự cài, dựng chỉ mục online chỉ có ở bản Enterprise (và Developer). Không có ONLINE = ON, DROP_EXISTING giữ Sch-M suốt thời gian dựng, mọi câu đọc và ghi dbo.DonHang đứng chờ; trên bản thử mất khoảng 40 giây. Đo lại trên bản restore của production và chạy trong cửa sổ bảo trì.

Chỉ mục phải nằm trên cùng partition scheme với bảng, nếu không SWITCH bị chặn: mọi dòng của truy vấn dưới đây phải có type_desc = PARTITION_SCHEME và noi_dat = ps_DonHang_Ngay.

Kiểm tra chỉ mục nằm trên ps_DonHang_NgaySQL · 5 dòng
SELECT i.name, ds.name AS noi_dat, ds.type_desc
FROM sys.indexes AS i
JOIN sys.data_spaces AS ds
    ON ds.data_space_id = i.data_space_id
WHERE i.object_id = OBJECT_ID(N'dbo.DonHang');

Căn chỉnh partition chưa đủ. Bảng staging ở mục SWITCH của Kỹ thuật thường dùng tạo chỉ mục không có INCLUDE, và trên bản thử SWITCH thất bại với lỗi 4947: không có chỉ mục giống hệt trong bảng nguồn. Script staging phải đổi thành:

CREATE INDEX IX_DonHang_Staging_KhachHang
    ON dbo.DonHang_Staging (KhachHangId, NgayTao)
    INCLUDE (TrangThai, TongTien)
    ON FG_ARCHIVE;

Khi dựng chỉ mục có phân vùng, SQL Server tạo thống kê bằng lấy mẫu mặc định, không quét toàn bộ như với chỉ mục không phân vùng. Thủ tục không còn phụ thuộc ước lượng đó, nhưng các câu khác dùng histogram này thì có, cho tới khi job Chủ nhật chạy FULLSCAN.

3. Kiểm chứng và gỡ ép

22:09:38, lệnh dựng xong. Query Store ngay sau đó:

Trạng thái ép kế hoạch của query 4187SQL · 4 dòng
SELECT plan_id, is_forced_plan, force_failure_count, last_force_failure_reason_desc,
       SWITCHOFFSET(initial_compile_start_time, '+07:00') AS bien_dich_luc
FROM sys.query_store_plan
WHERE query_id = 4187;
plan_id is_forced_plan force_failure_count last_force_failure_reason_desc bien_dich_luc
3907 1 1 NO_PLAN 2026-08-10 07:14:52 +07:00
5521 0 0 NONE 2026-10-05 06:02:14 +07:00
6034 0 0 NONE 2026-10-06 22:09:41 +07:00

Plan 3907 có Key Lookup. Trên chỉ mục mới, cột cần lấy đã nằm sẵn, engine không dựng lại được hình dạng có lookup: NO_PLAN. Câu được biên dịch tự do thành plan 6034, đúng như trên bản thử.

Ép kế hoạch có thể thất bại mà ứng dụng không biết

is_forced_plan vẫn là 1 khi lần ép thất bại, và câu chạy bằng kế hoạch biên dịch tự do. Nếu đổi chỉ mục mà chưa sửa được gốc, sniffing quay lại trong khi mọi người tin kế hoạch vẫn bị ghim.

Phép thử quyết định: biên dịch với khách lớn nhất trước, rồi dùng lại cho khách thường. Lần này cố ý để SSMS ở ARITHABORT ON, để mục plan cache riêng của SSMS chắc chắn được biên dịch lần đầu với khách 42.

EXEC sp_recompile N'dbo.usp_DonHang_CuaKhach';

SET STATISTICS IO, TIME ON;
EXEC dbo.usp_DonHang_CuaKhach @KhachHangId = 42;      -- biên dịch với khách 300.000 đơn
EXEC dbo.usp_DonHang_CuaKhach @KhachHangId = 7315;    -- dùng lại kế hoạch đó, khách 20 đơn
EXEC dbo.usp_DonHang_CuaKhach @KhachHangId = 18420;   -- khách 50 đơn
SET STATISTICS IO, TIME OFF;
Table 'DonHang'. Scan count 2, logical reads 3, physical reads 0, ...
Table 'DonHang'. Scan count 4, logical reads 9, physical reads 0, ...
Table 'DonHang'. Scan count 4, logical reads 10, physical reads 0, ...

Scan count là số partition được seek: khách 42 chỉ cần partition 4 (trống) và 3, khách thường cần cả bốn, mỗi partition 3 page từ gốc xuống lá. Chạy theo thứ tự ngược, biên dịch với khách 7315 trước, cho cùng kế hoạch và cùng số reads.

Logical reads mỗi lần gọi Plan 5521 (sự cố) Plan 3907 (đang ép) Chỉ mục phủ
Khách 42, 300.000 đơn 12 khoảng 156 3
Khách 7315, 20 đơn khoảng 46.000 78 9
Khách 18420, 50 đơn khoảng 44.000 164 10

Chỉ mục phủ đọc 3 đến 10 page cho cả ba khách; plan 5521 đọc khoảng 46.000 page với khách 20 đơn

Plan 5521 (sự cố)Plan 3907 (đang ép)Chỉ mục phủ
Khách 42, 300.000 đơn121563Khách 7315, 20 đơn46.000789Khách 18420, 50 đơn44.00016410
Logical reads mỗi lần gọi trên bản thử. 46.000, 44.000 và 156 là số khoảng như trong bảng. Thang log.
Bảng số liệu
Plan 5521 (sự cố)Plan 3907 (đang ép)Chỉ mục phủ
Khách 42, 300.000 đơn121563
Khách 7315, 20 đơn46.000789
Khách 18420, 50 đơn44.00016410

Gỡ ép, vì plan 3907 không còn dựng lại được và không còn cần:

EXEC sys.sp_query_store_unforce_plan @query_id = 4187, @plan_id = 3907;

Một ngày sau, plan 6034 trung bình 9 logical reads, CPU dưới 0,1 ms, p95 của API 61 ms lúc cao điểm. Thứ Hai 12/10, 06:02, job của đại lý 42 lại gọi đầu tiên sau bảo trì: last_compile_start_time của plan 6034 nhảy lên 06:02, không có plan_id mới.

4. Hậu kiểm

Thời điểm Chuyện gì xảy ra Kết quả
30/09 – 05/10 01:12 ERP đại lý 42 gọi từ 06:00; UPDATE STATISTICS xong 01:12 Kế hoạch phải biên dịch lại
05/10 06:02 – 08:15 Khách 42 gọi đầu, plan 5521; p95 khoảng 1 s, không cảnh báo Ngưỡng tuyệt đối 2 s chưa chạm
08:30 – 08:36 13 lần gọi/giây, vượt sức chứa khoảng 11; APM báo 08:33 CPU 97%, timeout đầu tiên
08:38 – 08:55 SSMS 3 ms (sai ARITHABORT), rồi request, wait, Query Store, plan XML Parameter sniffing
09:01 – 09:10 Plan 3907 không có Sort, ép lúc 09:05 p95 81 ms, CPU 12%
09:30 – 11:00 Phân tích histogram, mật độ, lịch bảo trì Dữ liệu lệch cộng lần biên dịch đầu
06/10 22:00 – 22:15 Chỉ mục phủ, ép 3907 thất bại NO_PLAN, gỡ ép Plan 6034: 3, 9, 10 logical reads
12/10 06:02 Khách 42 lại gọi đầu tiên sau bảo trì Vẫn plan 6034

Phần điều tra sáng 05/10 gọn lại thành chuỗi câu hỏi và câu trả lời:

sequenceDiagram
  participant D as DMV request, wait
  participant T as Người trực
  participant Q as Query Store
  Note over T: 08:33 APM báo p95 trên 2 s
  T->>D: 08:41 request và wait 60 giây
  D-->>T: 79 request, SOS_SCHEDULER_YIELD
  T->>Q: 08:48 kế hoạch của query 4187
  Q-->>T: plan 5521 từ 06:02:14
  T->>Q: 08:55 đọc plan XML
  Q-->>T: compiled value 42, row goal
  T->>Q: 09:01 plan 3907 có Sort?
  Q-->>T: không có Sort
  T->>Q: 09:05 ép plan 3907
  Note over T: 09:10 p95 81 ms, CPU 12%

Tác động: suy giảm từ 06:02 đến 09:07, khoảng 24.400 lần gọi lỗi (theo các dòng Aborted trong Query Store), 37 phút từ cảnh báo đến hồi phục.

Làm tốt: Query Store bật sẵn; đo trước khi sửa, loại trừ khóa và memory grant trong 3 phút; đọc plan 3907 trước khi ép để khách 42 không thành 900.000 reads; ép kế hoạch thay vì xóa plan cache; thử bản sửa gốc trên bản sao theo hai thứ tự biên dịch.

Làm chưa tốt:

  • Hai giờ rưỡi suy giảm không ai biết: cảnh báo dùng ngưỡng tuyệt đối 2 giây, trong khi p95 đã tăng 12 lần.
  • Không có tín hiệu nào khi một câu nóng đổi kế hoạch.
  • Một khách mới gọi API với khối dữ liệu gấp 15.000 lần trung vị không được xem là thay đổi có rủi ro.
  • Lần đo đầu trong SSMS dùng sai ARITHABORT.

5. Giám sát thêm sau sự cố

Ba truy vấn Query Store chạy bằng SQL Server Agent 15 phút một lần, gửi cảnh báo khi có dòng trả về:

  • Câu có CPU mỗi lần chạy trong giờ qua gấp hơn 10 lần trung bình 7 ngày trước, với ít nhất 100 lần chạy.
  • Câu đã có kế hoạch cũ vừa có thêm kế hoạch mới trong giờ qua. Nếu có từ trước, kiểm tra này sẽ báo ở lần chạy 06:15 sáng 05/10.
  • Kế hoạch đang ép nhưng ép thất bại (force_failure_count > 0).
Ba truy vấn Query Store cho SQL Server AgentSQL · 49 dòng
-- 1. CPU mỗi lần chạy trong giờ qua gấp hơn 10 lần trung bình 7 ngày trước đó
DECLARE @bay_gio datetimeoffset = SYSDATETIMEOFFSET();

WITH so_lieu AS (
    SELECT
        p.query_id,
        CASE WHEN i.start_time >= DATEADD(HOUR, -1, @bay_gio) THEN 'gan' ELSE 'truoc' END AS ky,
        SUM(rs.avg_cpu_time * rs.count_executions) AS cpu_us,
        SUM(rs.count_executions) AS so_lan
    FROM sys.query_store_runtime_stats AS rs
    JOIN sys.query_store_runtime_stats_interval AS i
        ON i.runtime_stats_interval_id = rs.runtime_stats_interval_id
    JOIN sys.query_store_plan AS p
        ON p.plan_id = rs.plan_id
    WHERE i.start_time >= DATEADD(DAY, -7, @bay_gio)
    GROUP BY p.query_id,
             CASE WHEN i.start_time >= DATEADD(HOUR, -1, @bay_gio) THEN 'gan' ELSE 'truoc' END
)
SELECT
    g.query_id,
    CAST(t.cpu_us / t.so_lan / 1000.0 AS decimal(12, 2)) AS cpu_ms_truoc,
    CAST(g.cpu_us / g.so_lan / 1000.0 AS decimal(12, 2)) AS cpu_ms_gan,
    g.so_lan AS so_lan_gan
FROM so_lieu AS g
JOIN so_lieu AS t
    ON t.query_id = g.query_id
   AND t.ky = 'truoc'
WHERE g.ky = 'gan'
  AND g.so_lan >= 100
  AND g.cpu_us / g.so_lan > 10 * (t.cpu_us / t.so_lan);

-- 2. Câu đã có kế hoạch cũ vừa có thêm kế hoạch mới trong giờ qua
SELECT
    p.query_id,
    p.plan_id,
    SWITCHOFFSET(p.initial_compile_start_time, '+07:00') AS bien_dich_luc
FROM sys.query_store_plan AS p
WHERE p.initial_compile_start_time >= DATEADD(HOUR, -1, SYSDATETIMEOFFSET())
  AND EXISTS (
        SELECT 1
        FROM sys.query_store_plan AS cu
        WHERE cu.query_id = p.query_id
          AND cu.plan_id <> p.plan_id);

-- 3. Kế hoạch đang ép nhưng ép thất bại
SELECT query_id, plan_id, force_failure_count, last_force_failure_reason_desc
FROM sys.query_store_plan
WHERE is_forced_plan = 1
  AND force_failure_count > 0;

Ngưỡng cho wait và APM:

Tín hiệu Ngưỡng cảnh báo
Tỷ lệ signal_wait_time_ms trên tổng wait, lấy chênh lệch 5 phút Trên 25%
sys.dm_exec_query_memory_grants có dòng grant_time IS NULL Có dòng chờ quá 30 giây
p95 của từng endpoint so với trung vị p95 cùng giờ 4 tuần trước Gấp 3 lần trong 10 phút
Lỗi SqlException số -2 Trên 0,5% trong 5 phút

Trên Enterprise từ SQL Server 2017, automatic plan correction (ALTER DATABASE BanHang SET AUTOMATIC_TUNING (FORCE_LAST_GOOD_PLAN = ON);, mặc định tắt) tự ép lại kế hoạch tốt gần nhất khi kế hoạch mới tệ hơn. Tài liệu nói engine ép khi lợi ích CPU ước tính trên 10 giây; với 0,7 s phí mỗi lần gọi, ngưỡng đó đạt sau vài chục lần gọi, còn thời điểm phát hiện do engine quyết định. Đây là lưới an toàn, không thay chỉ mục, và cũng gặp đúng giới hạn ở mục 3.

6. Áp dụng trong .NET

Phía API cần tín hiệu riêng: câu nào chậm, của endpoint nào, với tham số nào. Endpoint Dapper đã có span SQL của OpenTelemetry ở phần 1. Với câu EF Core, một DbCommandInterceptor đọc tag do TagWith đặt (phần 2), ghi histogram thời gian theo tag và ghi log khi vượt ngưỡng. ReaderExecutedAsync và ReaderExecuted cùng gọi Ghi(cmd, e.Duration):

void Ghi(DbCommand cmd, TimeSpan thoiGian)
{
    var tag = TagCua(cmd.CommandText);
    ThoiGian.Record(thoiGian.TotalMilliseconds,
        new KeyValuePair<string, object?>("db.query.tag", tag));
    if (thoiGian > nguong)
        log.LogWarning("Truy van cham {Ms:0} ms, tag \"{Tag}\", tham so {ThamSo}",
            thoiGian.TotalMilliseconds, tag,
            string.Join(", ", cmd.Parameters.Cast<DbParameter>()
                .Select(p => $"{p.ParameterName}={p.Value}")));
}

ThoiGian là Histogram<double> của new Meter("BanHang.Db"). Phải override cả bản sync lẫn async, vì lời gọi async không đi qua method sync; CommandFailed ghi lỗi khi SqlException.Number là -2. Đăng ký bằng AddInterceptors, xuất histogram bằng AddMeter("BanHang.Db") của OpenTelemetry.

Bản chạy thử dùng database LocalDB 4 triệu đơn của phần 1, Microsoft.EntityFrameworkCore.SqlServer và Microsoft.Extensions.Logging.Console 10.0.12, ngưỡng 500 ms. Mỗi giai đoạn xóa plan cache rồi gọi khách 42, 7315, 18420, trước và sau khi thêm INCLUDE (TrangThai, TongTien), cuối cùng một lệnh WAITFOR quá CommandTimeout:

--- Chỉ mục (KhachHangId, NgayTao), như trước sự cố
warn: BanHang.Db[0] Truy van cham 640 ms, tag "GET /api/khach-hang/{id}/don-hang", tham so @p=50, @id=7315
warn: BanHang.Db[0] Truy van cham 890 ms, tag "GET /api/khach-hang/{id}/don-hang", tham so @p=50, @id=18420
--- Chỉ mục phủ INCLUDE (TrangThai, TongTien)
fail: BanHang.Db[0] Timeout sau 1068 ms, tag "job dong bo don dai ly 42"
--- Histogram banhang.db.query.duration (ms)
GET /api/khach-hang/{id}/don-hang: 6 lần, 182.0, 640.0, 889.6, 22.6, 13.8, 9.1

Trước khi sửa, hai khách thường bị log kèm đúng tham số, còn khách 42, người biên dịch kế hoạch, thì không. Sau chỉ mục phủ, cả ba lần gọi dưới 25 ms và không còn dòng log nào. Với ngưỡng 500 ms, tín hiệu kiểu này (log ở đây, hay span SQL ở phần 1 cho Dapper) sẽ bật ngay trong khung 06:00 sáng 05/10, khi plan 5521 trung bình 0,8 s mỗi lần, hơn hai giờ trước cảnh báo của APM.

TruyVanCham.cs: interceptor ghi log truy vấn chậm và histogram theo tag, chạy bằng dotnet run TruyVanCham.csC# · 140 dòng
#:package Microsoft.EntityFrameworkCore.SqlServer@10.0.12
#:package Microsoft.Extensions.Logging.Console@10.0.12
#:property PublishAot=false

using System.Data.Common;
using System.Diagnostics.Metrics;
using Microsoft.Data.SqlClient;
using Microsoft.EntityFrameworkCore;
using Microsoft.EntityFrameworkCore.Diagnostics;
using Microsoft.Extensions.Logging;

const string ChuoiKetNoi = @"Server=(localdb)\MSSQLLocalDB;Database=Kumeo_dieutra;Integrated Security=true;TrustServerCertificate=true";

using var loggerFactory = LoggerFactory.Create(b => b.AddSimpleConsole(o => o.SingleLine = true));
var chanTruyVan = new TruyVanChamInterceptor(loggerFactory.CreateLogger("BanHang.Db"), TimeSpan.FromMilliseconds(500));

// Trong demo, đọc histogram bằng MeterListener. Production: AddMeter("BanHang.Db") trong OpenTelemetry.
var soDo = new Dictionary<string, List<double>>();
using var listener = new MeterListener();
listener.InstrumentPublished = (inst, l) => { if (inst.Meter.Name == "BanHang.Db") l.EnableMeasurementEvents(inst); };
listener.SetMeasurementEventCallback<double>((inst, ms, tags, _) =>
{
    var tag = (string)tags[0].Value!;
    if (!soDo.TryGetValue(tag, out var list)) soDo[tag] = list = [];
    list.Add(ms);
});
listener.Start();

await using var db = new BanHangDb(ChuoiKetNoi, chanTruyVan);
db.Database.SetCommandTimeout(300);   // đủ cho lệnh dựng chỉ mục trên bảng thử

async Task GoiTheoThuTu(string giaiDoan)
{
    Console.WriteLine($"--- {giaiDoan}");
    await db.Database.ExecuteSqlRawAsync("ALTER DATABASE SCOPED CONFIGURATION CLEAR PROCEDURE_CACHE;");
    foreach (var id in new[] { 42, 7315, 18420 })   // khách 42 biên dịch trước
        await db.DonHang
            .TagWith("GET /api/khach-hang/{id}/don-hang")
            .Where(d => d.KhachHangId == id)
            .OrderByDescending(d => d.NgayTao)
            .Take(50)
            .AsNoTracking()
            .ToListAsync();
}

// Nạp bảng vào buffer pool để số đo không lẫn thời gian đọc đĩa.
await db.Database.ExecuteSqlRawAsync("SELECT COUNT_BIG(*) FROM dbo.DonHang WITH (INDEX(1));");

await GoiTheoThuTu("Chỉ mục (KhachHangId, NgayTao), như trước sự cố");

await db.Database.ExecuteSqlRawAsync("""
    CREATE INDEX IX_DonHang_KhachHang ON dbo.DonHang (KhachHangId, NgayTao)
        INCLUDE (TrangThai, TongTien) WITH (DROP_EXISTING = ON);
    """);
await GoiTheoThuTu("Chỉ mục phủ INCLUDE (TrangThai, TongTien)");

// Lệnh quá CommandTimeout: interceptor ghi lỗi với SqlException.Number = -2.
db.Database.SetCommandTimeout(1);
try { await db.Database.ExecuteSqlRawAsync("-- job dong bo don dai ly 42\nWAITFOR DELAY '00:00:03';"); } catch (SqlException) { }
db.Database.SetCommandTimeout(300);

// Trả database thử về như cũ để chạy lại được.
await db.Database.ExecuteSqlRawAsync("CREATE INDEX IX_DonHang_KhachHang ON dbo.DonHang (KhachHangId, NgayTao) WITH (DROP_EXISTING = ON);");

listener.Dispose();
Console.WriteLine("--- Histogram banhang.db.query.duration (ms)");
foreach (var (tag, list) in soDo)
    Console.WriteLine($"{tag}: {list.Count} lần, {string.Join(", ", list.Select(x => x.ToString("0.0")))}");

sealed class TruyVanChamInterceptor(ILogger log, TimeSpan nguong) : DbCommandInterceptor
{
    static readonly Histogram<double> ThoiGian =
        new Meter("BanHang.Db").CreateHistogram<double>("banhang.db.query.duration", unit: "ms");

    // e.Duration: từ lúc gửi lệnh tới lúc có DbDataReader, gần như toàn bộ thời gian server với câu ít dòng.
    public override ValueTask<DbDataReader> ReaderExecutedAsync(
        DbCommand cmd, CommandExecutedEventData e, DbDataReader reader, CancellationToken ct = default)
    {
        Ghi(cmd, e.Duration);
        return ValueTask.FromResult(reader);
    }

    public override DbDataReader ReaderExecuted(DbCommand cmd, CommandExecutedEventData e, DbDataReader reader)
    {
        Ghi(cmd, e.Duration);
        return reader;
    }

    public override void CommandFailed(DbCommand cmd, CommandErrorEventData e) => GhiLoi(cmd, e);

    public override Task CommandFailedAsync(DbCommand cmd, CommandErrorEventData e, CancellationToken ct = default)
    {
        GhiLoi(cmd, e);
        return Task.CompletedTask;
    }

    void Ghi(DbCommand cmd, TimeSpan thoiGian)
    {
        var tag = TagCua(cmd.CommandText);
        ThoiGian.Record(thoiGian.TotalMilliseconds,
            new KeyValuePair<string, object?>("db.query.tag", tag));
        if (thoiGian > nguong)
            log.LogWarning("Truy van cham {Ms:0} ms, tag \"{Tag}\", tham so {ThamSo}",
                thoiGian.TotalMilliseconds, tag,
                string.Join(", ", cmd.Parameters.Cast<DbParameter>()
                    .Select(p => $"{p.ParameterName}={p.Value}")));
    }

    void GhiLoi(DbCommand cmd, CommandErrorEventData e)
    {
        if (e.Exception is SqlException { Number: -2 })
            log.LogError("Timeout sau {Ms:0} ms, tag \"{Tag}\"", e.Duration.TotalMilliseconds, TagCua(cmd.CommandText));
    }

    // TagWith của EF Core thành dòng "-- ..." ở đầu CommandText. Với Dapper, tự đặt dòng đó.
    static string TagCua(string sql) =>
        sql.StartsWith("-- ") ? sql[3..sql.IndexOf('\n')].TrimEnd('\r') : "(khong tag)";
}

sealed class DonHang
{
    public long DonHangId { get; set; }
    public DateTime NgayTao { get; set; }
    public int KhachHangId { get; set; }
    public byte TrangThai { get; set; }
    public decimal TongTien { get; set; }
}

sealed class BanHangDb(string chuoiKetNoi, IInterceptor interceptor) : DbContext
{
    public DbSet<DonHang> DonHang => Set<DonHang>();
    protected override void OnConfiguring(DbContextOptionsBuilder b) =>
        b.UseSqlServer(chuoiKetNoi).AddInterceptors(interceptor);
    protected override void OnModelCreating(ModelBuilder m)
    {
        m.Entity<DonHang>().ToTable("DonHang", "dbo").HasKey(d => new { d.NgayTao, d.DonHangId });
        m.Entity<DonHang>().Property(d => d.NgayTao).HasColumnType("datetime2(0)");
        m.Entity<DonHang>().Property(d => d.TongTien).HasColumnType("decimal(18, 2)");
    }
}

Chạy bằng dotnet run TruyVanCham.cs trên .NET SDK 10.0.401, runtime 10.0.12, laptop Intel Core Ultra 5 125U đang chạy việc khác; số chỉ dùng để so trước và sau. #:property PublishAot=false cần cho EF Core như ở phần 2.

7. Checklist: khi một API đột nhiên chậm

  1. Ghi số trước khi kết luận: endpoint, từ lúc nào, p50, p95, tỷ lệ lỗi, so với cùng giờ tuần trước.
  2. Đọc loại lỗi: timeout (SqlException -2), hết connection pool, deadlock (1205), hay lỗi nghiệp vụ.
  3. Xem CPU, I/O, bộ nhớ máy SQL. Tăng tuyến tính theo lưu lượng nghĩa là một câu tốn cố định mỗi lần gọi.
  4. Chụp sys.dm_exec_requests: câu nào, bao nhiêu request, status, wait_type, có bị chặn, có memory grant.
  5. Lấy chênh lệch sys.dm_os_wait_stats trong 60 giây; đọc cả wait vắng mặt.
  6. Mở Query Store cho câu đó: các kế hoạch, giờ biên dịch theo giờ địa phương, số liệu theo giờ, dòng Aborted.
  7. Đặt giờ đổi kế hoạch cạnh lịch sự kiện: deploy, bảo trì, nạp dữ liệu, failover, khách hay job mới.
  8. Đọc kế hoạch: ParameterCompiledValue so với giá trị đang chạy, Number of Rows Read. Đo trong SSMS với SET ARITHABORT OFF.
  9. Giảm nhẹ bằng cách hoàn tác được, tác động hẹp: ép kế hoạch tốt sau khi đọc nó với giá trị lớn nhất. Không DBCC FREEPROCCACHE.
  10. Sửa gốc trên bản sao, thử giá trị lớn nhất và một giá trị điển hình theo cả hai thứ tự biên dịch.
  11. Triển khai, xem force_failure_count, gỡ ép, theo dõi lần biên dịch sau đợt bảo trì kế tiếp.

Những chỗ hay hiểu sai

  • "is_forced_plan = 1 nghĩa là kế hoạch đó đang chạy." Lần ép có thể thất bại NO_PLAN mà cột vẫn là 1. Xem force_failure_count.
  • "Muốn đọc ngược thì khóa chỉ mục phải DESC." Kế hoạch đọc ngược chỉ mục tăng dần, không Sort. Giữ khóa thì SWITCH và các câu khác không đổi.
  • "Chỉ mục phủ chữa parameter sniffing cho mọi câu." Chỉ cho đúng câu này: thêm AND TrangThai <> 5 là kế hoạch đổi.

Kết luận

Ép kế hoạch tắt sự cố trong một phút nhưng có thể hết tác dụng mà không báo khi chỉ mục đổi. Chỉ mục khớp đúng câu hỏi làm kế hoạch hết nhạy với tham số, cho đúng câu đó.

Trong dự án .NET của bạn:

  • Thêm DbCommandInterceptor ghi log câu EF Core vượt ngưỡng kèm tag và tham số, override cả sync lẫn async; với Dapper, dùng span SQL của OpenTelemetry.
  • Ghi histogram thời gian theo tag bằng System.Diagnostics.Metrics, xuất qua AddMeter("BanHang.Db"), cảnh báo khi p95 gấp 3 lần cùng giờ 4 tuần trước.
  • Đưa thay đổi chỉ mục và script staging của SWITCH vào cùng một migration, thử hai thứ tự biên dịch trên bản restore trước khi deploy.
  • Cài ba truy vấn Query Store vào SQL Server Agent; xem force_failure_count sau mỗi lần đổi chỉ mục.

Đọc tiếp

Nguồn

Đọc tiếp