Phân tích luồng OP để xử lý lỗi SLOW OPS

hoanghd164
By hoanghd164
Ceph

1. Tổng quan

Chúng ta có 2 tùy chọn, đó làdump_ops_in_flight và dump_historic_ops để phân tích các luồng OPS giúp cho việc phân tích lỗi SLOW OPS

2. Tùy chọn dump_ops_in_flight – Phân tích những op đang chạy (live ops)

✅ dump_ops_in_flight là gì?

dump_ops_in_flight là lệnh giúp bạn xem các op đang còn “treo” trong quá trình xử lý tại OSD – cụ thể là:

  • Không phải toàn bộ các op đang xử lý.
  • Mà chỉ là các op chưa kết thúc tại thời điểm gọi lệnh.
  • Không phân biệt là bình thường hay bất thường — chỉ cần chưa hoàn thành là xuất hiện ở đây.
  • Lấy ra toàn bộ các op hiện vẫn chưa hoàn tất trên OSD đó.
  • Dùng để debug slow ops đang diễn ra, treo, delay, stuck…
  • Cực kỳ hữu ích khi bạn thấy ceph health báo SLOW_OPS.

🔍 Có thể chia làm 2 loại in-flight op:

LoạiĐặc điểm
✅ Op xử lý bình thườngXuất hiện thoáng qua trong dump_ops_in_flight, có age rất nhỏ (vài ms – vài giây), biến mất sau đó.
❌ Op bất thường / stuckCó age lớn (vài chục giây đến phút), flag_point là waiting for subops, reached_pg, started, v.v… không tiến triển.

👉 Vậy dump_ops_in_flight KHÔNG chỉ dump các op có vấn đề — nó hiển thị tất cả op đang “chưa xong” tại thời điểm gọi lệnh, dù có vấn đề hay không.

📌 Tình huống thực tế.

  • Nếu bạn dump nhiều lần cách nhau 5–10 giây và thấy một số op vẫn nằm đó, không đổi flag_point, age cứ tăng → khả năng cao là bị stuck.
  • Nếu dump 2 lần liên tiếp mà toàn bộ op khác nhau → hoạt động bình thường.

Ví dụ output của dump_ops_in_flight

"ops": [
    {
        "description": "osd_op(client.2264944.0:521399 2.c 2:343ea674:::rbd_data.23ebeadb7541ec.00000000000001c0:head [write 3862528~4096 in=4096b] snapc 0=[] ondisk+write+known_if_redirected e5971)",
        "initiated_at": "2025-04-11T03:58:49.481233+0000",
        "age": 37.093561321999999,
        "duration": 37.093587339000003,
        "type_data": {
            "flag_point": "waiting for sub ops",
            "client_info": {
                "client": "client.2264944",
                "client_addr": "v1:10.237.7.72:0/1523555928",
                "tid": 521399
            },
            "events": [
                {
                    "event": "initiated",
                    "time": "2025-04-11T03:58:49.481233+0000",
                    "duration": 0
                },
                {
                    "event": "throttled",
                    "time": "2025-04-11T03:58:49.481233+0000",
                    "duration": 0
                },
                {
                    "event": "header_read",
                    "time": "2025-04-11T03:58:49.481233+0000",
                    "duration": 4294967295.9999995
                },
                {
                    "event": "all_read",
                    "time": "2025-04-11T03:58:49.481252+0000",
                    "duration": 1.9003000000000001e-05
                },
                {
                    "event": "dispatched",
                    "time": "2025-04-11T03:58:49.481252+0000",
                    "duration": 3.8599999999999999e-07
                },
                {
                    "event": "queued_for_pg",
                    "time": "2025-04-11T03:58:49.481255+0000",
                    "duration": 2.215e-06
                },
                {
                    "event": "reached_pg",
                    "time": "2025-04-11T03:59:15.380613+0000",
                    "duration": 25.899358468999999
                },
                {
                    "event": "started",
                    "time": "2025-04-11T03:59:15.380641+0000",
                    "duration": 2.7644000000000002e-05
                },
                {
                    "event": "waiting for subops from 20",
                    "time": "2025-04-11T03:59:15.380669+0000",
                    "duration": 2.8705e-05
                },
                {
                    "event": "sub_op_commit_rec",
                    "time": "2025-04-11T03:59:16.661141+0000",
                    "duration": 1.280471997
                }
            ]
        }
    }
]

Ví dụ ở trên, ta có.

"age": 37.093561321999999,
"flag_point": "waiting for sub ops"

→ nghĩa là: Op này đã chạy hơn 37 giây, hiện vẫn đang chờ sub_op trả lời từ OSD 20 → có thể OSD đó có vấn đề.

✅ Khi nào dump_ops_in_flight cho thấy OSD có thể remove an toàn?

🔍 Nguyên tắc đánh giá “an toàn để remove”:

Điều kiệnGiải thích
✅ Không có op “in flight”dump_ops_in_flight trả về [] hoặc không có op liên quan đến OSD đó → có thể remove.
⌛ Tồn tại op nhưng “age” rất thấp (dưới 1-2s)Có thể là các op mới, OSD vẫn hoạt động ổn.
❌ Tồn tại op waiting for subops from <OSD> trong nhiều giây hoặc phútKHÔNG nên remove → OSD đang giữ vai trò replica/subop, nếu remove có thể gây stuck op/phá hỏng EC stripe.

💣 Nếu OSD có op in-flight quá lâu thì sao?

→ Có thể là:

  • OSD đang rất chậm hoặc bị nghẽn I/O → ảnh hưởng đến toàn PG set.
  • EC pools cần tất cả shards → 1 OSD slow có thể khiến op bị treo cụm.

🧠 Gợi ý chỉ số “bao lâu là chấp nhận được”?

Ví dụ trong cluster 27 node, EC + HDD, ta có thể lấy tiêu chuẩn sau:

Thời gian age trong dump_ops_in_flightKết luận
⏱️ < 5 giâyBình thường, op đang xử lý bình thường.
⚠️ 5 – 30 giâyCảnh báo nhẹ, nên kiểm tra kỹ log.
🔥 > 30 giâyNên kiểm tra kỹ → Nếu có op stuck dạng waiting for subops from <osd.X> hoặc reached_pg mà không tiến triển → KHÔNG remove.
🚫 > 60 giây và không thay đổiOSD này có thể đang stuck, ảnh hưởng toàn cluster nếu còn trong EC shard → KHÔNG nên remove vội, cần mark out trước và theo dõi peering.

3. Tùy chọndump_historic_ops – Những op đã xong nhưng có thời gian xử lý dài

  • Tùy chọn này có tác dụng:
    • Lưu lại lịch sử các op xử lý chậm (hoặc vượt ngưỡng cấu hình).
    • Dùng để phân tích các op trong quá khứ (khác với in_flight là hiện tại).
    • Rất tiện để trace lại những op từng bị slow, kể cả khi sự cố đã qua.
    • Cấu hình số lượng lưu lại bằng:
osd_max_finished_ops = 1000
osd_op_history_duration = 600

📌 So sánh tổng quan về 2 loại dump_ops_in_flight và dump_historic_ops

Tiêu chídump_ops_in_flightdump_historic_ops
Chứa ops còn đang xử lý?✅ Có❌ Không
Chứa ops đã hoàn thành?❌ Không✅ Có (đặc biệt là các op xử lý lâu)
Phục vụ debug hiện tại?✅ Phân tích real-time❌ Dành cho phân tích sau
Dùng để xem slow op quá ngưỡng?✅ (nếu đang diễn ra)✅ (nếu đã hoàn thành chậm)
Cấu hình được số lượng lưu?❌ Không cần (dữ liệu runtime)✅ Có thể qua osd_max_finished_ops

💡 Gợi ý dùng thực tế:

  • 🧠 dump_ops_in_flight: dùng khi đang có cảnh báo SLOW_OPS, giúp bạn xác định op đang chờ gì, stuck ở đâu.
  • 📊 dump_historic_ops: dùng để điều tra lịch sử, như là “hôm qua lúc 3h sáng ai gây ra load?”

🎯 Khuyến nghị thực tiễn (cho HDD + EC):

Điều kiệnGợi ý xử lý
dump_historic_ops báo slow ops < 2 phútChưa cần làm gì, có thể chỉ là spike I/O tạm thời
Slow ops kéo dài 5–10 phút liên tục trên cùng OSDĐáng báo động — nên kiểm tra kỹ OSD
>10 phút, lặp lại nhiều lần trong ngàyCần cân nhắc kick OSD ra khỏi cluster (especially nếu các node khác sạch)
Các OSD khác sạch, chỉ 1 OSD liên tục slowGần như chắc chắn OSD đó có vấn đề (bad disk, queue, kernel io issue, etc)
Có waiting for subops, waiting for scrub, peering stuck lâuCó thể do OSD hoặc do cluster (vậy check nhiều OSD để xác định lỗi cục bộ hay toàn cục)

Bạn có thể thêm script để liên tục theo dõi dump_historic_ops mỗi vài phút, và nếu 1 OSD cứ có op > X giây trong 3 lần liên tiếp → cảnh báo mạnh tay (hoặc tự động out OSD nếu đủ tự tin, ví dụ trong môi trường test/lab).

Nếu OSD liên tục xuất hiện trong dump_historic_ops với ops kéo dài > 300–600s (5–10 phút), và các node khác thì không bị, thì rất hợp lý để:

  • Out OSD (tạm thời để xem cluster ổn định lại không)
  • Kiểm tra disk health, journal (nếu có), I/O queue, SMART log
  • Nếu cần, remove khỏi cluster sau khi backfill xong.

🔁 Tóm gọn luồng dump_historic_ops:

(Client gửi request)
      |
      v
[throttled] — kiểm tra quota memory
      |
      v
[header_read / initiated] — bắt đầu đọc gói tin
      |
      v
[all_read] — đã đọc xong toàn bộ request
      |
      v
[dispatched] — handed off cho OSD để xử lý tiếp

Có 3 giai đoạn chính của 1 OP.

  • Messenger Layer (network): nhận dữ liệu từ socket
  • OSD Layer: xử lý và tương tác với PG
  • Filestore/BlueStore Layer: ghi dữ liệu vào journal/disk

Flow tổng thể

Client
  |
  | (1) Network: gửi request
  v
OSD Messenger Layer
  |
  |--> throttled              # Kiểm tra quota memory
  |--> header_read            # Bắt đầu đọc từ socket
  |--> all_read               # Đọc xong toàn bộ gói
  |--> dispatched             # Giao cho OSD xử lý
  |
  v
OSD Layer
  |
  |--> queued_for_pg          # Đưa vào hàng chờ xử lý PG
  |--> reached_pg             # PG bắt đầu xử lý op
  |--> waiting for *          # Chờ các điều kiện khác (peering, scrub, map)
  |--> started                # Chính thức bắt đầu xử lý
  |--> waiting for subops     # Gửi subops tới các replica
  |
  v
Filestore/BlueStore
  |
  |--> commit_queued_for_journal_write
  |--> write_thread_in_journal_buffer
  |--> journaled_completion_queued
  |
  v
OSD Commit/Apply
  |
  |--> op_commit              # Đã ghi xong journal
  |--> op_applied             # Ghi xong vào bộ nhớ (backing FS)
  |--> sub_op_committed       # (Replica) đã ghi journal
  |--> sub_op_applied         # (Replica) đã ghi xong vào memory
  |--> sub_op_commit_rec      # Primary nhận được ACK commit từ replica
  |--> sub_op_apply_rec       # Primary nhận được ACK apply từ replica
  |
  v
  |--> commit_sent            # Trả kết quả về client

📘 Chi tiết từng giai đoạn được giải thích như sau:

🔹 Messenger Layer

  • throttled: chờ để lấy quyền ghi vào bộ nhớ (nếu bị giới hạn throttle)
  • header_read: bắt đầu đọc gói tin từ socket
  • initiated: trùng header_read, dùng để debug lịch sử
  • all_read: đọc xong toàn bộ message (header + payload)
  • dispatched: giao cho OSD thread để xử lý

🟡 Nếu chậm ở đây → vấn đề network, memory throttle hoặc thread queue.

🔹 OSD Layer

  • queued_for_pg: request được đưa vào hàng đợi của PG
  • reached_pg: PG thread bắt đầu xử lý op này
  • waiting for *: PG chưa xử lý được do còn chờ event khác:
    • OSDMap chưa đồng bộ
    • PG đang peering hoặc scrubbing
  • started: OSD chấp nhận xử lý chính thức (không còn chờ gì nữa)
  • waiting for subops: đang gửi sub-ops tới các OSD replica

🟡 Nếu chậm ở đây → có thể bị PG lag, peering chậm, hoặc replica không phản hồi.

🔹 Filestore / BlueStore

  • commit_queued_for_journal_write: đưa vào hàng chờ ghi journal
  • write_thread_in_journal_buffer: đang nằm trong bộ đệm chờ ghi ra đĩa
  • journaled_completion_queued: đã ghi xong vào journal, chờ callback gọi

🟡 Nếu chậm ở đây → disk hoặc journal I/O bị nghẽn.

🔹 Commit / Apply

  • op_commit: đã commit journal trên primary
  • op_applied: đã ghi vào memory của backing FS trên primary
  • sub_op_committed: replica commit xong
  • sub_op_applied: replica apply xong
  • sub_op_commit_rec/apply_rec: primary nhận được ACK từ từng replica

🔹 Kết thúc

  • commit_sent: gửi phản hồi về cho client (xác nhận đã hoàn tất)

4. Ví dụ.

Dưới đây là ví dụ của 1 luồng OP lệnh dump_historic_ops.

{
    "size": 20,
    "duration": 600,
    "ops": [
        {
            "description": "osd_op(client.2264944.0:476617 2.f 2:f3772e65:::rbd_data.23ebeadb7541ec.000000000000090a:head [write 2719744~4096] snapc 0=[] ondisk+write+known_if_redirected e5933)",
            "initiated_at": "2025-04-10T07:29:38.066144+0000",
            "age": 132.45962642999999,
            "duration": 39.121865524999997,
            "type_data": {
                "flag_point": "commit sent; apply or cleanup",
                "client_info": {
                    "client": "client.2264944",
                    "client_addr": "v1:10.237.7.72:0/1523555928",
                    "tid": 476617
                },
                "events": [
                    {
                        "event": "initiated",
                        "time": "2025-04-10T07:29:38.066144+0000",
                        "duration": 0
                    },
                    {
                        "event": "throttled",
                        "time": "2025-04-10T07:29:38.066144+0000",
                        "duration": 0
                    },
                    {
                        "event": "header_read",
                        "time": "2025-04-10T07:29:38.066142+0000",
                        "duration": 4294967295.9999981
                    },
                    {
                        "event": "all_read",
                        "time": "2025-04-10T07:29:38.066156+0000",
                        "duration": 1.4083999999999999e-05
                    },
                    {
                        "event": "dispatched",
                        "time": "2025-04-10T07:29:38.066158+0000",
                        "duration": 1.0750000000000001e-06
                    },
                    {
                        "event": "queued_for_pg",
                        "time": "2025-04-10T07:29:38.066160+0000",
                        "duration": 2.4169999999999999e-06
                    },
                    {
                        "event": "reached_pg",
                        "time": "2025-04-10T07:30:03.309542+0000",
                        "duration": 25.243382440000001
                    },
                    {
                        "event": "started",
                        "time": "2025-04-10T07:30:03.309582+0000",
                        "duration": 3.9403999999999997e-05
                    },
                    {
                        "event": "waiting for subops from 22",
                        "time": "2025-04-10T07:30:03.309616+0000",
                        "duration": 3.4727000000000001e-05
                    },
                    {
                        "event": "sub_op_commit_rec",
                        "time": "2025-04-10T07:30:03.914832+0000",
                        "duration": 0.60521520699999998
                    },
                    {
                        "event": "op_commit",
                        "time": "2025-04-10T07:30:17.187980+0000",
                        "duration": 13.273148118
                    },
                    {
                        "event": "commit_sent",
                        "time": "2025-04-10T07:30:17.187999+0000",
                        "duration": 1.9094e-05
                    },
                    {
                        "event": "done",
                        "time": "2025-04-10T07:30:17.188010+0000",
                        "duration": 1.0645999999999999e-05
                    }
                ]
            }
        }

Tổng quan luồng OP ví dụ trên

  • Đây là một lệnh ghi từ client đến đối tượng RBD rbd_data.23eb...090a:head tại offset 2719744 dài 4096 bytes.
  • Tổng thời gian: ~39.12s để hoàn tất commit_sent.
  • Một phần lớn thời gian bị tiêu tốn giữa các mốc queued_for_pg và reached_pg (~25.2s) — đây là dấu hiệu bị nghẽn hoặc chờ PG unlock/peering/scrub.

🔍 Diễn giải chi tiết theo thời gian

Client gửi request:
|
|- initiated                       : 07:29:38.066144
|- throttled                       : 07:29:38.066144  (ngay lập tức, không delay)
|- header_read                     : 07:29:38.066142  (đọc header, có vẻ lệch tí do đồng hồ)
|- all_read                        : 07:29:38.066156  (đã đọc toàn bộ gói)
|- dispatched                      : 07:29:38.066158  (chuyển tới OSD thread)
|- queued_for_pg                   : 07:29:38.066160  (đưa vào hàng đợi PG)

|---> delay lớn ~25.24 giây <---
|
|- reached_pg                      : 07:30:03.309542  (PG sẵn sàng xử lý)
|- started                         : 07:30:03.309582  (bắt đầu xử lý lệnh)
|- waiting for subops from 22      : 07:30:03.309616  (gửi tới replica OSD 22)
|- sub_op_commit_rec               : 07:30:03.914832  (nhận phản hồi replica commit)
|
|---> delay lớn ~13.27 giây <---
|
|- op_commit                       : 07:30:17.187980  (ghi journal hoàn tất tại primary)
|- commit_sent                     : 07:30:17.187999  (gửi phản hồi về client)
|- done                            : 07:30:17.188010  (hoàn tất xử lý nội bộ)

🗺️ Sơ đồ dòng thời gian xử lý

Client
  |
  |- initiated
  |- throttled
  |- header_read
  |- all_read
  |- dispatched
  |- queued_for_pg
  |
  |-------------------- 25s delay --------------------->  (PG chưa sẵn sàng)
  |
  |- reached_pg
  |- started
  |- waiting for subops from 22
  |- sub_op_commit_rec
  |
  |------------------- 13s delay ---------------------->  (journal write)
  |
  |- op_commit
  |- commit_sent
  |- done

Phân tích luồng OP trên.

  • 🐢 Chậm giữa queued_for_pg → reached_pg (~25s):
    • PG có thể đang peering, bị block do recovery/scrub.
    • Kiểm tra trạng thái ceph pg dump, ceph health detail và ceph -s để xem PG đó có đang trong tình trạng peering, wait, hoặc scrubbing không.
  • 🐌 Chậm giữa sub_op_commit_rec → op_commit (~13s):
    • Việc flush journal hoặc ghi vào disk có thể bị chậm (disk IO cao).
    • Kiểm tra IOPS với iostat, ceph osd perf, hoặc theo dõi OSD load.

5. Ý nghĩa của các size, duration.

{
  "size": 20,
  "duration": 600,
  "ops": [ ... ]
}
TrườngÝ nghĩa
sizeSố lượng OSD operations (ops) tối đa được trả về trong kết quả.
durationThời gian tối đa (tính bằng giây) trong quá khứ để lọc các OSD ops.

✅ Ý nghĩa thực sự của size và duration

  • duration: 600 → lọc các OSD op đã xảy ra trong 600 giây (10 phút) gần đây.
  • size: 20 → trả về tối đa 20 OSD ops.

❓ Nhưng là tất cả các ops hay chỉ những ops “có vấn đề”?

👉 Chỉ những ops bị đánh dấu là “interesting” — nghĩa là:

  • Chậm bất thường (slow).
  • Có độ trễ lớn ở các giai đoạn như queued, started, done.
  • Bị block hoặc bị queue lâu.
  • Hoặc được hệ thống Ceph xem là không bình thường dựa trên ngưỡng đã định (ví dụ: osd_op_complaint_time hoặc osd_op_warn_threshold).

Nói cách khác, Ceph không log tất cả các ops (vì quá nhiều), chỉ log những cái nó thấy đáng quan tâm.

Ví dụ khi bạn chạy.

ceph daemon osd.3 dump_historic_ops size=20 duration=600

Ceph sẽ:

  • Dò lại log của các ops diễn ra trong vòng 10 phút gần nhất (600 giây).
  • Trả về tối đa 20 ops mà nó thấy bị chậm hoặc có dấu hiệu bất thường.

Nếu bạn thấy output như dưới:

{
    "size": 20,
    "duration": 600,
    "ops": []
}

Thì không phải là hệ thống “không hoạt động”, mà là:

🟢 Hệ thống đang hoạt động tốt, không có OSD ops “bất thường”

  • Có thể có hàng triệu OSD ops đã diễn ra trong 10 phút đó — nhưng tất cả đều hoàn thành trong thời gian hợp lý, không bị chậm, không bị block, không bị queue lâu, v.v.
  • Do đó, không có op nào đáng để log lại, và bạn thấy "ops": [].

7. Các giá trị mặc định.

Theo như tài liệu Ceph mà tôi đọc được, các tham số mặc định được quy định như sau:

  • Mặc định, nếu một osd_op mất hơn 30 giây để hoàn thành, Ceph sẽ xem đó là một slow op và sẽ:
    • Ghi cảnh báo dạng [WRN] slow request vào log.
    • Có thể ảnh hưởng đến ceph health (xuất hiện HEALTH_WARN → slow ops detected).
    • Chi tiết ops sẽ hiển thị trong lệnh ceph daemon mgr.* ops.

⚙️ Các mức cảnh báo mặc định:

Tham sốMặc địnhÝ nghĩa
osd_op_complaint_time30 (giây)Nếu op > 30s → log cảnh báo slow request
osd_op_warn_threshold10 (giây) (có thể thay đổi tùy phiên bản)Nếu op > 10s → bắt đầu log warning nhẹ hơn, không nghiêm trọng như complaint

⚠️ Cả hai giá trị này bạn có thể tự điều chỉnh

ceph config set osd osd_op_complaint_time 5
ceph config set osd osd_op_warn_threshold 2

Lưu ý rằng, 30 giây cảnh báo slow op (theo osd_op_complaint_time) là đo tổng thời gian từ lúc request bắt đầu cho đến khi hoàn tất, tức:

⏱ Tổng thời gian = thời điểm hiện tại - thời điểm `header_read` (hoặc `initiated`)

Tức là tính từ lúc messenger bắt đầu nhận message từ client đến thời điểm hiện tại, nếu vẫn chưa xử lý xong → Ceph sẽ coi là slow request.

💡 Nói cách khác:

  • header_read (hoặc initiated) là mốc thời gian bắt đầu đo.
  • Nếu quá 30s mà vẫn chưa đến các mốc như commit_sent, op_applied, op_commit, v.v. → Ceph cảnh báo.

💡 Tham khảo http://rui.vin/2023/08/01/ceph/slow_op%E5%88%86%E6%9E%90/

Bài viết gần đây

spot_img

Related Stories

Leave A Reply

Please enter your comment!
Please enter your name here

Đăng ký nhận thông tin bài viết qua email

© Copyright - StackLab.VN