Skip to content

refactor(osdtrace): remove BlueStore sub-latencies from output #175

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
taodd merged 1 commit into from
Aug 13, 2026
+27 −58
Merged

refactor(osdtrace): remove BlueStore sub-latencies from output #175

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
42 changes: 8 additions & 34 deletions doc/osdtrace.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -185,9 +185,9 @@ sudo ./osdtrace -p 12345 -i dwarf.json --skip-version-check
```
osd 1 pg 20.138 op_r size 8192 client 169954691 tid 150680 object benchmark_data_host_3093113_object10 osd_ops [read] throttle_lat 2 recv_lat 11 dispatch_lat 12 queue_lat 41 osd_lat 35 bluestore_lat 231 op_lat 332
osd 38 pg 20.14f op_r size 4096 client 169954691 tid 150884 object benchmark_data_host_3093113_object47 osd_ops [read] throttle_lat 2 recv_lat 10 dispatch_lat 12 queue_lat 45 osd_lat 40 bluestore_lat 334 op_lat 443
osd 38 pg 20.16b op_w size 12288 client 179589331 tid 24057 object benchmark_data_host_3093113_object52 osd_ops [write] throttle_lat 2 recv_lat 26 dispatch_lat 15 queue_lat 57 osd_lat 187 peers [(34, 8079), (40, 5065)] bluestore_lat 10639 (prepare 107 aio_wait 0 (aio_size 0) seq_wait 6 kv_commit 10525) op_lat 10966
osd 38 pg 20.0 subop_w size 17067 client 179589331 tid 24056 object benchmark_data_host_3093113_object52 txn_ops [write,setattrs] throttle_lat 0 recv_lat 56 dispatch_lat 12 queue_lat 42 osd_lat 50 bluestore_lat 11737 (prepare 68 aio_wait 0 (aio_size 0) seq_wait 8 kv_commit 11660) subop_lat 11943
osd 1 pg 164.2 subop_w size 780 client 174758496 tid 4640511 object - txn_ops [touch,write] throttle_lat 0 recv_lat 4 dispatch_lat 2 queue_lat 160 osd_lat 25 bluestore_lat 2988 (prepare 31 aio_wait 0 (aio_size 0) seq_wait 7 kv_commit 2949) subop_lat 3301
osd 38 pg 20.16b op_w size 12288 client 179589331 tid 24057 object benchmark_data_host_3093113_object52 osd_ops [write] throttle_lat 2 recv_lat 26 dispatch_lat 15 queue_lat 57 osd_lat 187 peers [(34, 8079), (40, 5065)] bluestore_lat 10639 op_lat 10966
osd 38 pg 20.0 subop_w size 17067 client 179589331 tid 24056 object benchmark_data_host_3093113_object52 txn_ops [write,setattrs] throttle_lat 0 recv_lat 56 dispatch_lat 12 queue_lat 42 osd_lat 50 bluestore_lat 11737 subop_lat 11943
osd 1 pg 164.2 subop_w size 780 client 174758496 tid 4640511 object - txn_ops [touch,write] throttle_lat 0 recv_lat 4 dispatch_lat 2 queue_lat 160 osd_lat 25 bluestore_lat 2988 subop_lat 3301
```

### Operation Types
Expand Down Expand Up @@ -225,11 +225,6 @@ it, not when it carried a payload. Class methods that only touch omap — RGW's
| **osd_lat** | OSD processing time | μs | All ops |
| **peers** | Replica wait times | [(osd, μs), ...] | op_w only |
| **bluestore_lat** | Total BlueStore time | μs | All ops |
| **prepare** | Transaction prep | μs | Write ops |
| **aio_wait** | Async I/O wait | μs | Write ops |
| **aio_size** | Async I/O size | bytes | Write ops |
| **seq_wait** | Sequencer wait | μs | Write ops |
| **kv_commit** | KV store commit | μs | Write ops |
| **op_lat / subop_lat** | Total end-to-end latency | μs | All ops |

Note:
Expand All @@ -242,7 +237,7 @@ first entered into the OSD to the time when OSD has done processing and reply to
Let's analyze a write operation in detail:

```
osd 38 pg 20.16b op_w size 12288 client 179589331 tid 24057 object benchmark_data_host_3093113_object52 osd_ops [write] throttle_lat 2 recv_lat 26 dispatch_lat 15 queue_lat 57 osd_lat 187 peers [(34, 8079), (40, 5065)] bluestore_lat 10639 (prepare 107 aio_wait 0 (aio_size 0) seq_wait 6 kv_commit 10525) op_lat 10966
osd 38 pg 20.16b op_w size 12288 client 179589331 tid 24057 object benchmark_data_host_3093113_object52 osd_ops [write] throttle_lat 2 recv_lat 26 dispatch_lat 15 queue_lat 57 osd_lat 187 peers [(34, 8079), (40, 5065)] bluestore_lat 10639 op_lat 10966
```

### Stage-by-Stage Breakdown
Expand Down Expand Up @@ -290,29 +285,8 @@ osd 38 pg 20.16b op_w size 12288 client 179589331 tid 24057 object benchmark_dat

**bluestore_lat: 10639μs (10.6ms)** - Total BlueStore processing

For write operations this is broken down into:

**prepare: 107μs**
- Transaction preparation
- Allocating space, building write operations
- Generally low overhead

**aio_wait: 0μs**
- Async I/O completion wait time
- Time waiting for disk I/O (for data writes)
- aio_size: 0 bytes (no deferred writes in this case)

**seq_wait: 6μs**
- Sequencer wait time
- Ordering needed for concurrent operations happens on same PG
- Usually very low

**kv_commit: 10525μs (10.5ms)**
- Flush data to main device and metadata to rocksdb
- **Often the dominant latency component**
- Affected by disk performance, write amplification, compaction

**Total BlueStore: 10.6ms** (dominated by kv_commit)
The operation output reports only the overall BlueStore latency. Use
BlueStore probe mode when individual internal operations need to be analyzed.

#### 4. Total Operation Latency

Expand All @@ -333,9 +307,9 @@ throttle_lat 5000 recv_lat 120000 dispatch_lat 20 ...

#### Storage Bottleneck
```
osd_lat 50 bluestore_lat 2500000 (prepare 100 aio_wait 0 kv_commit 2480000) ...
osd_lat 50 bluestore_lat 2500000 ...
```
- High bluestore_lat, especially kv_commit
- High bluestore_lat
- **Solution:** Check disk performance, reduce write amplification, tune RocksDB

#### Replication Issues
Expand Down
8 changes: 4 additions & 4 deletions src/osdtrace.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -597,15 +597,15 @@ void print_subop_w(osd_op_t &op, int osd_id) {
"object %s txn_ops %s "
"throttle_lat %lld recv_lat %lld dispatch_lat %lld "
"queue_lat %lld osd_lat %lld "
"bluestore_lat %lld (prepare %lld aio_wait %lld (aio_size %d) seq_wait %lld kv_commit %lld) "
"bluestore_lat %lld "
"subop_lat %lld\n",
osd_id, op.pg.m_pool, pgid.c_str(),
op.wb, op.client_id, op.req_id,
object_name.c_str(),
detail_ops.c_str(),
op.throttle_lat, op.recv_lat, op.dispatch_lat,
op.queue_lat, op.osd_lat,
op.bs_lat, op.bs_prepare_lat, op.bs_aio_wait_lat, op.aio_size, op.bs_pg_seq_lat, op.bs_kv_commit_lat,
op.bs_lat,
op.op_lat);
print_delayed_info(op);
}
Expand All @@ -623,15 +623,15 @@ void print_op_w(osd_op_t &op, int osd_id) {
"object %s osd_ops %s "
"throttle_lat %lld recv_lat %lld dispatch_lat %lld "
"queue_lat %lld osd_lat %lld peers [(%d, %lld), (%d, %lld)] "
"bluestore_lat %lld (prepare %lld aio_wait %lld (aio_size %d) seq_wait %lld kv_commit %lld) "
"bluestore_lat %lld "
"op_lat %lld\n",
osd_id, op.pg.m_pool, pgid.c_str(),
op.wb, op.client_id, op.req_id,
object_name.c_str(),
detail_ops.c_str(),
op.throttle_lat, op.recv_lat, op.dispatch_lat,
op.queue_lat, op.osd_lat, op.peers[0].peer, op.peers[0].latency, op.peers[1].peer, op.peers[1].latency,
op.bs_lat, op.bs_prepare_lat, op.bs_aio_wait_lat, op.aio_size, op.bs_pg_seq_lat, op.bs_kv_commit_lat,
op.bs_lat,
op.op_lat);
print_delayed_info(op);
}
Expand Down
35 changes: 15 additions & 20 deletions tests/lib/verify-trace-output.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,14 +50,12 @@ TRACE_EXPECTED_IO_SIZE=2097152
#
# subop_w | osd | pool | pg | size | client | tid
# | throttle_lat | recv_lat | dispatch_lat | queue_lat | osd_lat
# | bluestore_lat | prepare_lat | aio_wait_lat | seq_wait_lat
# | kv_commit_lat | subop_lat | object | txn_ops
# | bluestore_lat | subop_lat | object | txn_ops
#
# op_w | osd | pool | pg | size | client | tid
# | throttle_lat | recv_lat | dispatch_lat | queue_lat | osd_lat
# | peer0_id | peer0_lat | peer1_id | peer1_lat
# | bluestore_lat | prepare_lat | aio_wait_lat | seq_wait_lat
# | kv_commit_lat | op_lat | object | osd_ops
# | bluestore_lat | op_lat | object | osd_ops
#
# The object field is "-" when the trace could not capture the object name
# (the relevant capture point was not reached, or the DWARF data predates
Expand All @@ -69,7 +67,7 @@ TRACE_EXPECTED_IO_SIZE=2097152
# peer-latency token (`(-1, 18446743169577026)]`), and a naive `$NF + 0`
# verifier mistakes that for the total op_lat. This parser instead
# matches each op type by exact NF AND by literal field-name landmarks
# (e.g. `$28 == "op_lat"` for op_r, `$26 == "peers"` + `$43 == "op_lat"`
# (e.g. `$28 == "op_lat"` for op_r, `$26 == "peers"` + `$33 == "op_lat"`
# for op_w). Truncated rows fail at least one landmark and are dropped.
# Same logic drops rows with the `[delayed%d ... ]` continuation tokens
# appended (their NF is inflated past the expected count).
Expand Down Expand Up @@ -100,25 +98,24 @@ _osdtrace_rows() {
$7, $9, $11, \
$17, $19, $21, $23, $25, \
$27, $29, $13, $15)
} else if (op == "subop_w" && NF == 39 && \
} else if (op == "subop_w" && NF == 29 && \
$12 == "object" && $14 == "txn_ops" && \
$26 == "bluestore_lat" && $28 == "(prepare" && \
$38 == "subop_lat") {
candidate = sprintf("subop_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$26 == "bluestore_lat" && $28 == "subop_lat") {
candidate = sprintf("subop_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$2, pg[1], pg[2], \
$7, $9, $11, \
$17, $19, $21, $23, $25, \
$27, $29, $31, $35, num($37), $39, $13, $15)
} else if (op == "op_w" && NF == 44 && \
$27, $29, $13, $15)
} else if (op == "op_w" && NF == 34 && \
$12 == "object" && $14 == "osd_ops" && \
$26 == "peers" && $31 == "bluestore_lat" && \
$33 == "(prepare" && $43 == "op_lat") {
candidate = sprintf("op_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$33 == "op_lat") {
candidate = sprintf("op_w|%d|%s|%s|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%d|%s|%s", \
$2, pg[1], pg[2], \
$7, $9, $11, \
$17, $19, $21, $23, $25, \
num($27), num($28), num($29), num($30), \
$32, $34, $36, $40, num($42), $44, $13, $15)
$32, $34, $13, $15)
}
# else: row was truncated, has [delayed...] suffix, or printed
# an op type we do not parse. Dropped silently.
Expand Down Expand Up @@ -251,8 +248,8 @@ _verify_osdtrace_output_impl() {
# Per-op-type field lists, used to populate $row from the parser
# output and to enumerate sub-latency fields for the strict bound.
local -a OP_R_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat)
local -a SUBOP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat prepare_lat aio_wait_lat seq_wait_lat kv_commit_lat)
local -a OP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat prepare_lat aio_wait_lat seq_wait_lat kv_commit_lat)
local -a SUBOP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat)
local -a OP_W_SUBLATS=(throttle_lat recv_lat dispatch_lat queue_lat osd_lat bluestore_lat)

while IFS= read -r line; do
[ -z "$line" ] && continue
Expand All @@ -276,8 +273,7 @@ _verify_osdtrace_output_impl() {
row[size] row[client] row[tid] \
row[throttle_lat] row[recv_lat] row[dispatch_lat] \
row[queue_lat] row[osd_lat] \
row[bluestore_lat] row[prepare_lat] row[aio_wait_lat] \
row[seq_wait_lat] row[kv_commit_lat] row[op_lat] \
row[bluestore_lat] row[op_lat] \
row[object] row[detail_ops] <<< "$line"
subop_w_total=$((subop_w_total + 1))
_osdtrace_check_common || return 1
Expand All @@ -289,8 +285,7 @@ _verify_osdtrace_output_impl() {
row[throttle_lat] row[recv_lat] row[dispatch_lat] \
row[queue_lat] row[osd_lat] \
row[peer0_id] row[peer0_lat] row[peer1_id] row[peer1_lat] \
row[bluestore_lat] row[prepare_lat] row[aio_wait_lat] \
row[seq_wait_lat] row[kv_commit_lat] row[op_lat] \
row[bluestore_lat] row[op_lat] \
row[object] row[detail_ops] <<< "$line"
op_w_total=$((op_w_total + 1))
_osdtrace_check_common || return 1
Expand Down
Loading