Skip to main content

Reading a report

At the end of ntprof record, and with ntprof report, each group of commands gets a summary. For 4 KiB random reads over NVMe/RDMA at queue depth 1, both sides recorded and joined:

== read 4KiB nvme6n1: 3066 commands sampled (from about 13.3k commands/s), all with the target's side
  latency (us): mean 72.77, p50 69.54, p99 80.30, p99.9 81.83
  stage                                   mean us  share   avg QD
  host block layer                           0.49     1%     0.01
  host driver (nvme-rdma)                    1.26     2%     0.02
  network (RDMA, NICs, wire)                10.03    14%     0.13  ###
  target driver (nvmet-rdma)                 1.02     1%     0.01
  storage (target block layer, drive)       59.97    82%     0.80  ####################
  largest: storage (target block layer, drive), 82 % of the latency
  • The header names the group (I/O type, size, namespace), how many commands were sampled, the command rate estimated from them, and whether every sampled command was joined with its target side.
  • latency is the end-to-end latency of the sampled commands, from the block request's start to its completion.
  • stage: the five stages in path order. The driver rows name the module, and the network row the transport.
  • mean us and share: each stage's mean time and its share of the mean latency. The stages add up to the end to end.
  • avg QD: the mean number of commands in the stage, by Little's law (command rate × mean time). Summed over the stages, it is the number of commands in flight in the kernel.
  • largest: the stage with the largest share.

Without the target's records (the host's file alone), the host's receive path is a row of its own, and the network and the whole target are one row, "network and target (not recorded)".

Components​

--detail adds a table that splits each stage into its components, in path order, with the number of commands, the mean, the occupancy (L) and p50 / p99. This is a 128 KiB random write over NVMe/RDMA at queue depth 1:

  components, in path order (L: commands in each, by Little's law)
  component                                     n      mean       L       p50       p99   (us)
  host block layer, submission               2213      0.20    0.00      0.20      0.26
  host driver, submission                    2213      2.05    0.02      2.04      2.33
  network: wire and NICs (computed)          2213     25.31    0.24     25.28     26.15
    data transfer (RDMA, at the target)      2213     15.78    0.15     15.77     16.13
  network: target receive path               2213      0.28    0.00      0.26      0.53
  target driver, submission                  2213      8.55    0.08      8.56      8.88
  storage: target block layer and drive      2213     39.01    0.38     38.72     41.92
    target block layer, submission           2213      2.02    0.02      2.02      2.16
    drive                                    2213     36.87    0.36     36.57     39.79
    target block layer, completion           2213      0.12    0.00      0.12      0.13
  target driver, completion                  2213      0.45    0.00      0.43      0.59
  network: host receive path                 2213      0.23    0.00      0.22      0.30
  host driver, completion                    2213      0.00    0.00      0.00      0.00
  host block layer, completion               2213      0.70    0.01      0.71      0.90
    handoff to nvme_complete_rq              2213      0.65    0.01      0.66      0.85
  end to end                                 2213     76.78    0.74     76.52     79.90

Each component's name starts with its stage; "submission" is the way down, "completion" the way back up. An indented row is a part of the row above it: the drive and the target's block layer within storage, the time from the parsed completion to nvme_complete_rq within the host block layer's completion, and over NVMe/RDMA, the data transfer within the network. Of this write's 76.8 µs, the drive took 36.9 µs and fetching the data over the network (its RDMA READ) 15.8 µs.

Cases that need a second look​

  • A large TCP read's data shows up in the host driver. The host receives a read's data after the first C2H data PDU arrives; that copy is in "host driver, completion". A 128 KiB read over NVMe/TCP at queue depth 1 spent 44.2 µs in the host driver, 41.1 µs of it there: about 26 µs waiting for the rest of the data to arrive through TCP (the target had handed all of it to its socket within 13 µs of starting to send), and about 15 µs of the host's own work after the last bytes arrived.
  • A large TCP write's data shows up in the target driver. A write too large for the command capsule is solicited by R2T, and the target receives its data while the host sends it. That time is in "target driver, submission", not in the network.
  • Large TCP transfers vary between connections. Their network and driver times depend on the CPUs the connection lands on, by up to about 20 % end to end from one nvme connect to the next.
  • The network is partly computed. "network: wire and NICs (computed)" is the host's wait minus the target's residence: the wire, the NICs and the network-stack work that neither driver sees. The two receive paths are measured. Over loopback the computed part is close to 0 and can be slightly negative.
  • Under load, the RDMA data transfer includes waiting. A read's transfer runs from posting the RDMA WRITE to the target handling its send completion, so a target that polls its completions late adds to it.
  • At high queue depth, ntprof's end to end is below fio's latency. Commands that completed in the kernel wait in the application's completion queue (io_uring) until the application reaps them; ntprof does not count that. The avg QD column shows it: for 4 KiB random reads over NVMe/TCP from one fio job at queue depth 32, ntprof counted 27.5 commands in the kernel.
  • Compare storage times only at the same drive state. A drive that has taken random writes can read 128 KiB more slowly than right after a sequential fill; measure the drive alone at the same time when you compare.

JSON and CSV​

-j FILE writes the same report as JSON. The top level holds "tool": "ntprof", the name and kernel of the machine that recorded (keys host and kernel; for ntprof report, the host's), the sampling period (sample_every), the throughput (from ntprof record only), and groups. Each group holds its type, bytes and session, its record counts (records, joined, ...), its command rate (rate_per_s), and:

  • components, keyed by component, each with its stage, its description (the name --detail prints), its occupancy, and a summary in nanoseconds (n, mean_ns, min_ns, max_ns, and the quantiles from p10_ns to p99.9_ns);
  • stages, the same summary for each stage, keyed host_block_layer, host_driver, network, target_driver and storage.

A component's stage is one of these five keys, or end_to_end for the end-to-end latency, or network_and_target for the host-only row. ntprof dump FILE... prints the raw records as CSV, one row per command and side, with every timestamp.