Re: [PATCH RFC 6/8] SUNRPC: Reduce rpciod workqueue contention

[Tim Menninger <tmenninger@everpuredata.com>]

Thanks. I did some more testing with v2 and collected the requested
information.

> 1. Does v2 of the series behave the same way? v2 dropped the
>    patch that ran the first RPC states in the submitter's
>    context, so the rpciod traffic pattern differs from v1.
>    The same smt -> cache_shard -> smt toggle on v2 would tell
>    us whether that matters.

The v2 series behaves similarly insofar as some runs see ~15 GB/s and
other runs see ~45 GB/s, but the low-throughput state no longer appears
to be directly controlled by the rpciod affinity scope.

I have started runs with both smt and cache_shard, and with both scopes
I have seen all three of:

    1. start and remain at ~45 GB/s
    2. start and remain at ~15 GB/s
    3. start at ~45 GB/s, then abruptly drop to ~15 GB/s

I have not found a discernible pattern for how long a run remains at
~45 GB/s before dropping.

cache_shard does still seem somewhat more likely to give me a ~45 GB/s
run, particularly as uptime increases, but unlike v1 I can reproduce
both good and bad runs with either scope. The deterministic live
smt -> cache_shard -> smt behavior I reported for v1 is no longer
present in v2.

So the low-throughput state remains with v2, but it no longer seems to be
from the SMT affinity change alone.

All captures below are from separate runs with the scope set as indicated.

> 2. How are the RDMA device's completion interrupts placed?
>    Please share, on a bad run:
>
>    * /proc/interrupts lines for the device's completion vectors
>    * the smp_affinity_list for each of those IRQs
>    * whether irqbalance is running, and whether you've pinned
>      the IRQs by hand

There are two ConnectX-7 devices:

    mlx5_0 port 1 ==> ens3np0
    mlx5_1 port 1 ==> ens6np0

at PCI addresses 0000:2a:00.0 and 0000:ab:00.0 respectively.

The substantial completion traffic in these captures is on
0000:2a:00.0. Its mlx5 completion IRQs are individually affinitized to
CPUs. For example:

    mlx5_comp0   -> CPU 0
    mlx5_comp1   -> CPU 1
    ...
    mlx5_comp23  -> CPU 23
    mlx5_comp24  -> CPU 48
    ...
    mlx5_comp47  -> CPU 71
    mlx5_comp48  -> CPU 24
    ...
    mlx5_comp62  -> CPU 38

The affinity mapping was the same in the good and bad captures I took.

I have not manually pinned any IRQs, and irqbalance is inactive.

I have the complete /proc/interrupts and smp_affinity_list captures
available if there are particular vectors or deltas that would be useful
to see.

> 3. Where is CPU time going on a bad run versus a good one?
>    A short capture of each would help:
>    perf record -a -g -- sleep 10
>    perf report --sort comm,cpu --stdio | head -80
>    In particular I'm interested in which CPUs the kworker
>    threads for rpciod and the ib-comp-wq threads run on under
>    each scope.

The perf results aren't showing anything useful yet. With the requested
--sort comm,cpu, the top of the report is dominated by perf itself. Without
that sort, the top entries are things like cpuidle_enter_state and
cpuidle_enter.

I'll keep working on the perf capture and follow up if/when I get something
useful, but I didn't want to hold up the rest of this on that.

> 4. tools/workqueue/wq_monitor.py rpciod, sampled for a few
>    seconds under each scope, would show whether the pools are
>    evenly loaded.

I captured rpciod monitoring data from four v2 runs. Here are windows from
each.

cache_shard good (~46 GB/s):
                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        27613426     3    534.5       - 1699488      16       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        27817822     5    537.3       - 1713539      16       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        28027937     2    540.1       - 1728063      16       0 

cache_shard bad (~15 GB/s):
                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        71754056     2    932.1       - 4767531       0       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        71825047     0    933.9       - 4771333       0       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        71901102     3    935.8       - 4775677       0       0 

smt good (~46 GB/s):
                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        17036137     2    144.9       - 4993757       0       0

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        17220514     0    146.8       - 5064827       0       0

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod        17397194     3    148.8       - 5132231       0       0

smt bad (~26 GB/s):
                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod         4937072     1     43.2       - 1407321       0       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod         5037193     4     44.0       - 1432686       0       0 

                     total  infl  CPUtime CPUitsv CMW/RPR  mayday rescued
    rpciod         5138509     4     44.8       - 1458079       0       0 

> 5. The workload itself: thread count, I/O size and direction,
>    number of mounts and RDMA connections, and the mount
>    options (nconnect in particular).

Workload:
    elbencho --iter 1 --threads 160 --files 16 --size 256G \
        --block 1m --dropcache --iodepth 64 --direct --read \
        --lat --latpercent --log 1 ...

Mount options:
    /home/ir/exapurity from 10.71.61.129:/exapurity
     Flags:	rw,relatime,vers=4.1,rsize=524288,wsize=524288,namlen=255,hard,fatal_neterrors=none,proto=tcp,nconnect=16,timeo=600,retrans=2,sec=sys,clientaddr=10.230.36.66,local_lock=none,write=eager,addr=10.71.61.129

It's pNFS over RDMA with one client, one MDS, one DS.

This is a pNFS flexfiles workload. The MDS connection is TCP, and I see
16 RDMA rpc_xprt instances for the data-server traffic during these
tests.

> 6. The base kernel the series was applied to, and the RDMA
>    device and driver.

For all of the data above, I applied the full v2 series on top of:

    940de590b839 Merge tag 'hardening-v7.3-rc2' of git://git.kernel.org/pub/scm/linux/kernel/git/kees/linux

The RDMA hardware is NVIDIA/Mellanox ConnectX-7 (MT2910, PCI ID
15b3:1021), using mlx5_core/mlx5_ib.

For the active interface:

    driver: mlx5_core
    version: 7.3.0-rc1-mainline-bad-v2+
    firmware-version: 28.47.2682 (MT_0000000838)
    bus-info: 0000:2a:00.0