Skip to content

libbpf-tools/netstacklat: Add tool to track latency in ingress network - #5550

Open
simosund wants to merge 5 commits into
iovisor:masterfrom
simosund:netstacklat
Open

libbpf-tools/netstacklat: Add tool to track latency in ingress network#5550
simosund wants to merge 5 commits into
iovisor:masterfrom
simosund:netstacklat

Conversation

@simosund

Copy link
Copy Markdown

Description

This PR adds the netstacklat (network stack latency) tool from bpf-examples. Adding netstacklat to libbpf-tools would make it more easily distributable while also complementing the current collection of libbpf-tools. This is a follow-up to issue #5510, which indicated there was some interest for adding netstacklat.

netstacklat summarizes how long packets (or more accurately, SKBs) have spent in the ingress network stack at several different points and reports the latency distribution as histograms. This can be useful to detect latency issues stemming from slow paths through the network stack or applications failing to read new socket data in a timely manner. netstacklat is also designed to be compatible with ebpf_exporter, making it possible to export the measurements to Prometheus.

While tcppktlat and softirq -d can be used for some similar purposes as netstacklat, netstacklat is more focused on measuring the latency for individual SKBs and provides a different set of capabilities compared to those prior tools. tcppktlat only measures the latency between data arriving and being read from TCP sockets (similar to the difference between netstacklat's tcp-socket-enqueued and tcp-socket-read), while netstacklat instead measures the total time each individual SKB has spent up both those and other points (including points in the IP and UDP stack as well). The net_rx distribution from softirq also covers time spent on processing SKB's in the ingress stack, but each measurement there will include the entire napi_poll() duration, which may process multiple SKBs at a time. netstacklat instead gives the per-SKB latency, offers a more granular breakdown of latency at different layers of the ingress stack, and can track the additional delay until it applications actually read the SKB payload.

We have published an academic paper describing the tool, evaluating its performance in a testbed, and sharing some brief results from a fleet-wide deployment at Cloudflare. This also covered in a more summarized manner in this RHRQ magazine article.

Why this approach

The central idea behind netstacklat (originally proposed by @netoptimizer) is to use the software timestamp from SOF_TIMESTAMPING_RX_SOFTWARE that the kernel sets for each SKB (sk_buff->tstamp) to determine the delay since the kernel started processing the SKB at later points (as illustrated in the figure below). This allows us to very efficiently determine the latency for each SKB without having to manage and lookup any external per-SKB state. By aggregating the latency measurements in-kernel, we also avoid a lot of the overhead (both in terms of performance and amount of output) that is associated with reporting each individual measurement, making it much more feasible to continuously run in production than tools like pwru and retis (which are great complementary tools to dig down into any latency issues identified by netstacklat).

netstacklat_design

Changes to histogram printing

netstacklat was designed to also work together with ebpf_exporter to export metrics to Prometheus. As a result of this, netstacklat uses a slightly different histogram format than other libbpf-tools. Briefly put, we use log2 histograms with right-closed bins instead of left-closed bins to work together with Prometheus' less-than-or-equal (le) format for histograms. On the eBPF side, we essentially compute the bin index as ceil(log2(val)) instead of floor(log2(val))).

To support our slightly different histogram binning, I've taken the liberty to generalize the logic for printing histograms in libbpf-tools, and in the process also made some minor functional changes that I think improves the output of current libbpf-tools. The first two commits describe the functional changes. The third commit generalizes and refactors the histogram printing logic, allowing it to be reused for netstacklat but without any further functional changes for existing tools. As part of the generalization I also added support for custom formatting of the bin labels. netstacklat needs to cover a very wide range (from 10s of nanoseconds to full seconds), where I find it much easier to interpret e.g. "537ms -> 1.07s" than "536870913 -> 1073741824" nanoseconds.

Let me know if you prefer me to break up the histogram printing changes in a separate PR, or just not meddle with the common histogram printing at all (just keep separate logic for histogram printing in netstacklat.c?). I'm open for any ideas on how to best make netstacklat's histogram structure work in libbpf-tools.


Checklist

  • Commit prefix matches changed area (e.g., tools/toolname:, libbpf-tools/toolname:, src/cc:, docs:, build:, tests/python:)
  • Commit body explains why this change is needed

For new tools only

  • Explains why this tool is needed and what existing tools cannot cover this use case
    • Explanation can be found in this PR description as well as the commit adding the tool
  • Includes at least one real production use case
    • netstacklat has been deployed at Cloudflare to monitor latency within the local host before nginx processes incoming requests. This case is described in more detail in our paper and more briefly summarized in this RHRQ article. You can also find example use cases in this blog post and the netstacklat_examples.txt, although those are artificially set up for demonstration purposes and do not correspond to real production use cases.
  • Man page (man/man8/) with an OVERHEAD section
  • Example output file (*_example.txt)
  • README.md entry added
    • There does not appear to be any entries for prior libbpf-tools in the README
  • Smoke test added to tests/python/test_tools_smoke.py
    • This does not seem relevant for libbpf-tools.

About AI Code Review: This project uses GitHub Copilot to assist with code review.
If a Copilot review is added, treat its feedback as you would any reviewer comment — you can
agree, disagree (with explanation), or ask questions. The maintainer makes all final decisions.

print_linear_hist() already skips printing out both leading and
trailing empty histogram bins. However, print_log2_hist() only skips
trailing empty bins, but prints out all leading empty bins, which can
lead to unecessarily long output. Update print_log2_hist() to skip the
leading empty bins in the same way as print_linear_hist().

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>
print_linear_hist() currently only prints the lower edge of each
bin. This makes it unclear what range of values each bin covers unless
step == 1 (like for runqlen, the original user). This is especially
problematic as print_linear_hist() skips all empty bins, so the width
of the bin cannot be inferred from the next printed bin edge.

To make the output of print_linear_hist() clearer for the general case
where bin widths are greater than one, print out the bin range in the
same manner as done by print_log2_hist(). In the edge case that
step == 1, only print the sole value covered by the bin as output like
"0 -> 0" is needlessly complex for that case. As part of this change,
adjust the spacing and output width to be consistent with
print_log2_hist().

There are currently two users of print_linear_hist(), runqlen and
cpufreq. Before this change, their output could look like follows:

$ runqlen
Sampling run queue length... Hit Ctrl-C to end.
^C
     runqlen       : count     distribution
        0          : 8115     |****************************************|
        1          : 7592     |*************************************   |
        2          : 735      |***                                     |
        3          : 97       |                                        |
        4          : 5        |                                        |

$ cpufreq
Sampling CPU freq system-wide & by process. Ctrl-C to end.
^C
...
     syswide       : count     distribution
        800        : 1240     |*************                           |
        3600       : 3720     |****************************************|
        3800       : 3720     |****************************************|
        4000       : 1240     |*************                           |

For cpufreq it is not possible for the user to tell what range of
values the first printed bin covers. Is it values up to 800?  Values
between 800 and 3600? Correctly interpreting that the bin covers
800-999Mhz requires knowing that cpufreq internally uses a 200Mhz step
size.

After the change, the output may instead look like:

$ runqlen
Sampling run queue length... Hit Ctrl-C to end.
^C
     runqlen             : count    distribution
              0          : 25827    |****************************************|
              1          : 24881    |**************************************  |
              2          : 858      |*                                       |
              3          : 43       |                                        |
              4          : 5        |                                        |
              8          : 1        |                                        |
              10         : 1        |                                        |

$ cpufreq
Sampling CPU freq system-wide & by process. Ctrl-C to end.
^C
...
     syswide             : count    distribution
       800 -> 999        : 1404     |******                                  |
      2000 -> 2199       : 1404     |******                                  |
      4000 -> 4199       : 8424     |****************************************|

runqlen maintains a concise single-value representation, while cpufreq
now provides unambiguous bin ranges. The output is also more
consistent with that of the more common print_log2_hist().

For reference, the output from print_log2_hist() may look like:

$ biolatency
Tracing block device I/O... Hit Ctrl-C to end.
^C

     usecs               : count    distribution
        16 -> 31         : 1        |                                        |
        32 -> 63         : 7        |****                                    |
        64 -> 127        : 25       |****************                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 1        |                                        |
       512 -> 1023       : 8        |*****                                   |
      1024 -> 2047       : 60       |****************************************|
      2048 -> 4095       : 9        |******                                  |

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>
There is currently two different histogram printing
functions (print_log2_hist() and print_linear_hist()) with largely
similar code except for how the bin edges are calculated. Add a
general print_hist() function to reduce code duplication and support
printing of arbitrary histogram schemes. Refactor print_log2_hist()
and print_linear_hist() as thin wrappers around print_hist().

To support arbitrary histogram schemes, make print_hist() accept a
function to calculate the left bin edge for each histogram bin as a
parameter. Infer that the bin's right edge is one less than the left
edge of the next bin.

To support flexible printing of bin edges, make print_hist() accept a
formatting function as a parameter. This can, for instance, be useful
to provide more easily interpretable output for very large values,
e.g. "2^31" or "2.1G" instead of "2147483648". If no formatter is
provided, fall back to formatting the bin edges as integers (same as
before).

As the maximum width of the printed bin edges can no longer be
determined from the maximum (non-empty) bin index, check the maximum
width that any of the printed labels will have instead. To keep the
alignment consistent with the prior print_log2_hist(), reuse the same
general alignment logic. If all edge labels can fit in 10 or less
characters, pad all to 10 characters, otherwise pad to 20 characters.

The output of print_linear_hist() and print_log2_hist() remains
identical.

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>
Add the netstacklat (network stack latency) tool. netstacklat
summarizes how long packets (SKBs) have spent in the ingress network
stack at various points using histograms. This can be useful to
detect latency issues stemming from slow paths through the network
stack or applications failing to read new socket data in a timely
manner.

netstacklat shares some similarities with tcppktlat and the softirqs -d
(for net_rx). Compared to tcppktlat, netstacklat monitors the total time
each SKB have spent in the network stack at several points rather than
the delay between some data arriving at a TCP socket and being
read (roughly similar to the difference between netstacklat's
tcp-socket-enqueued and tcp-socket-read probe points). Compared to
softirq, netstacklat provides the per SKB delays rather than the time
for full softirqs to run to completion (which may e.g. process
multiple SKBs), and can break down the latency for different parts of
the network stack.

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>
Add a manpage for libbpf-tools/netstacklat. Follow the overall
structure from the biolatency man page, but add some sections specific
to netstacklat (probe points, limitations, and usage with
ebpf_exporter).

Also a netstacklat_examples.txt, demonstrating how netstacklat can be
used with different options to identify host latency in different
parts of the network stack.

Signed-off-by: Simon Sundberg <simon.sundberg@kau.se>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant