[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