diff --git a/doc/osdtrace.md b/doc/osdtrace.md index 0050306..4b50aa0 100644 --- a/doc/osdtrace.md +++ b/doc/osdtrace.md @@ -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 @@ -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: @@ -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 @@ -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 @@ -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 diff --git a/src/osdtrace.cc b/src/osdtrace.cc index 5335f2c..d980adc 100644 --- a/src/osdtrace.cc +++ b/src/osdtrace.cc @@ -597,7 +597,7 @@ 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, @@ -605,7 +605,7 @@ void print_subop_w(osd_op_t &op, int osd_id) { 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); } @@ -623,7 +623,7 @@ 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, @@ -631,7 +631,7 @@ void print_op_w(osd_op_t &op, int osd_id) { 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); } diff --git a/tests/lib/verify-trace-output.sh b/tests/lib/verify-trace-output.sh index 40043df..543de25 100644 --- a/tests/lib/verify-trace-output.sh +++ b/tests/lib/verify-trace-output.sh @@ -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 @@ -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). @@ -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. @@ -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 @@ -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 @@ -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