[SPDK] Bad tail latency of 'spdk_nvme_qpair_process_completions'

Jing Liu <jingliu.cs at gmail.com>
Newsgroups dev.linux.lists.spdk
Message-ID <CA+0_kCJyhf6qrdHXk2pXFVR0X3B9cUPjN+6oFhx8mfJG4RSdpw@mail.gmail.com>
Hi,

I was using the `perf` tool to test the performance of the 4K sequential
read workload using
the command:

# ./perf -q 1 -s 4096 -w read -L -t 15 -c 1

My device is Intel Optane SSD with SPDK 18.04, the worst-case latency is
about 850us.
Initially, I thought it is due to the device itself. However, it turns out
that the
'spdk_nvme_qpair_process_completions' itself costs that long when I do
detailed timing.

Specifically, what I do is like this:

```
        poll_pre_tick = spdk_get_ticks();
        int num = spdk_nvme_qpair_process_completions(ns_ctx->u.nvme.qpair,
g_max_completions);
        poll_end_tick = spdk_get_ticks();
        uint64_t diff_tick = poll_end_tick - poll_pre_tick;
        if (num> 0 && diff_tick > CHECK_TICK_THR) {
            fprintf(stdout, "======= poll uses tick:%lu us:%f\n",
diff_tick, (double)diff_tick * 1000 * 1000 / g_tsc_rate);
        }
```
And the output is:

```
======= poll uses tick:2585384 us:1231.135238
======= poll uses tick:11154 us:5.311429
======= poll uses tick:12942 us:6.162857
======= poll uses tick:11422 us:5.439048
======= poll uses tick:19602 us:9.334286
======= poll uses tick:10874 us:5.178095
======= poll uses tick:11076 us:5.274286
======= poll uses tick:13210 us:6.290476
======= poll uses tick:10148 us:4.832381
======= poll uses tick:49488 us:23.565714
======= poll uses tick:382400 us:182.095238
.... elimiate some
======= poll uses tick:11268 us:5.365714
======= poll uses tick:68202 us:32.477143
======= poll uses tick:31284 us:14.897143
======= poll uses tick:63888 us:30.422857
======= poll uses tick:13520 us:6.438095
======= poll uses tick:18970 us:9.033333
======= poll uses tick:2808446 us:1337.355238
======= poll uses tick:43882 us:20.896190
======= poll uses tick:55554 us:26.454286
======= poll uses tick:39190 us:18.661905
======= poll uses tick:25210 us:12.004762
======= poll uses tick:11156 us:5.312381
======= poll uses tick:24674 us:11.749524
======= poll uses tick:11962 us:5.696190
======= poll uses tick:40048 us:19.070476
======= poll uses tick:64096 us:30.521905
========================================================

                Latency(us)
Device Information                                     :       IOPS
MB/s    Average        min        max
INTEL SSDPED1D960GAY (PHMB8361000P960EGN  ) from core 0:  153269.20
598.71       6.51       6.15    1351.92
========================================================
Total                                                  :  153269.20
598.71       6.51       6.15    1351.92
```

This is pretty out of expectation since I thought in polling mode, the
device tail is not supposed to be part of the `On-CPU processing` time.
I'm wondering is this symptom reasonable and what could be possible reasons
for this? Why the `polling some bit + perf's callback' uses
that long time?

Thanks,
Jing
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.