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.
É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ủaSWITCHphải đổi theo. - Ngay khi chỉ mục đổi, lần ép kế hoạch cũ thất bại
NO_PLANmà ứ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.DonHang
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
FULLghi 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ỗ; xemsys.dm_db_log_space_usagetrước khi chạy. tempdb:SORT_IN_TEMPDB = ONcần chỗ cỡ kích thước chỉ mục.- Khóa:
ONLINE = ONvẫn giữSrất ngắn lúc đầu vàSch-Mrất ngắn lúc cuối.Sch-Mchờ 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_PRIORITYchoCREATE INDEXchỉ 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_Ngay
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 4187
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
Bảng số liệu
| Plan 5521 (sự cố) | Plan 3907 (đang ép) | Chỉ mục phủ | |
|---|---|---|---|
| Khách 42, 300.000 đơn | 12 | 156 | 3 |
| Khách 7315, 20 đơn | 46.000 | 78 | 9 |
| Khách 18420, 50 đơn | 44.000 | 164 | 10 |
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 Agent
-- 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.cs
#: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
- 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.
- Đọc loại lỗi: timeout (
SqlException-2), hết connection pool, deadlock (1205), hay lỗi nghiệp vụ. - 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.
- Chụp
sys.dm_exec_requests: câu nào, bao nhiêu request,status,wait_type, có bị chặn, có memory grant. - Lấy chênh lệch
sys.dm_os_wait_statstrong 60 giây; đọc cả wait vắng mặt. - 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. - Đặ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.
- Đọc kế hoạch:
ParameterCompiledValueso với giá trị đang chạy, Number of Rows Read. Đo trong SSMS vớiSET ARITHABORT OFF. - 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. - 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.
- 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 = 1nghĩa là kế hoạch đó đang chạy." Lần ép có thể thất bạiNO_PLANmà cột vẫn là 1. Xemforce_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ìSWITCHvà 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 <> 5là 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
DbCommandInterceptorghi 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 quaAddMeter("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
SWITCHvà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_countsau mỗi lần đổi chỉ mục.
Đọc tiếp
- Phần 2: ép kế hoạch và tìm nguyên nhân gốc và Phần 1: từ cảnh báo đến kế hoạch thủ phạm.
- SLO và cảnh báo burn rate: cảnh báo độ trễ theo SLO, để suy giảm như sự cố này không lọt qua ngưỡng tuyệt đối.
Nguồn
- CREATE INDEX: ONLINE, DROP_EXISTING, statistics on partitioned indexes
- KB 2965553: decreased performance with TOP, MAX, MIN on partitioned tables
- Craig Freedman: Partitioned indexes in SQL Server 2008
- Editions and supported features of SQL Server 2019
- sys.query_store_plan
- Automatic tuning
- Interceptors - EF Core