Re: [PATCH] cfq: fix starvation of asynchronous writes

From: Jens Axboe
Date: Fri Sep 23 2016 - 12:12:04 EST

On 09/22/2016 08:10 PM, Jens Axboe wrote:
On 09/22/2016 06:59 PM, Glauber Costa wrote:
While debugging timeouts happening in my application workload
(ScyllaDB), I have
observed calls to open() taking a long time, ranging everywhere from 2
seconds -
the first ones that are enough to time out my application - to more
than 30

The problem seems to happen because XFS may block on pending metadata
under certain circumnstances, and that's confirmed with the following
taken by the offcputime tool (iovisor/bcc):

ffffffffb90c57b1 finish_task_switch
ffffffffb97dffb5 schedule
ffffffffb97e310c schedule_timeout
ffffffffb97e1f12 __down
ffffffffb90ea821 down
ffffffffc046a9dc xfs_buf_lock
ffffffffc046abfb _xfs_buf_find
ffffffffc046ae4a xfs_buf_get_map
ffffffffc046babd xfs_buf_read_map
ffffffffc0499931 xfs_trans_read_buf_map
ffffffffc044a561 xfs_da_read_buf
ffffffffc0451390 xfs_dir3_leaf_read.constprop.16
ffffffffc0452b90 xfs_dir2_leaf_lookup_int
ffffffffc0452e0f xfs_dir2_leaf_lookup
ffffffffc044d9d3 xfs_dir_lookup
ffffffffc047d1d9 xfs_lookup
ffffffffc0479e53 xfs_vn_lookup
ffffffffb925347a path_openat
ffffffffb9254a71 do_filp_open
ffffffffb9242a94 do_sys_open
ffffffffb9242b9e sys_open
ffffffffb97e42b2 entry_SYSCALL_64_fastpath
00007fb0698162ed [unknown]

Inspecting my run with blktrace, I can see that the xfsaild kthread
exhibit very
high "Dispatch wait" times, on the dozens of seconds range and
consistent with
the open() times I have saw in that run.

Still from the blktrace output, we can after searching a bit, identify
request that wasn't dispatched:

8,0 11 152 81.092472813 804 A WM 141698288 + 8 <-
(8,1) 141696240
8,0 11 153 81.092472889 804 Q WM 141698288 + 8
8,0 11 154 81.092473207 804 G WM 141698288 + 8
8,0 11 206 81.092496118 804 I WM 141698288 + 8 (
22911) [xfsaild/sda1]
<==== 'I' means Inserted (into the IO scheduler)
8,0 0 289372 96.718761435 0 D WM 141698288 + 8
(15626265317) [swapper/0]
<==== Only 15s later the CFQ scheduler dispatches the request

As we can see above, in this particular example CFQ took 15 seconds to
this request. Going back to the full trace, we can see that the
xfsaild queue
had plenty of opportunity to run, and it was selected as the active
queue many
times. It would just always be preempted by something else (example):

8,0 1 0 81.117912979 0 m N cfq1618SN /
8,0 1 0 81.117913419 0 m N cfq1618SN / add_to_rr
8,0 1 0 81.117914044 0 m N cfq1618SN / preempt
8,0 1 0 81.117914398 0 m N cfq767A / slice
expired t=1
8,0 1 0 81.117914755 0 m N cfq767A / resid=40
8,0 1 0 81.117915340 0 m N / served:
vt=1948520448 min_vt=1948520448
8,0 1 0 81.117915858 0 m N cfq767A / sl_used=1
disp=0 charge=0 iops=1 sect=0

where cfq767 is the xfsaild queue and cfq1618 corresponds to one of
the ScyllaDB
IO dispatchers.

The requests preempting the xfsaild queue are synchronous requests.
That's a
characteristic of ScyllaDB workloads, as we only ever issue O_DIRECT
While it can be argued that preempting ASYNC requests in favor of SYNC
is part
of the CFQ logic, I don't believe that doing so for 15+ seconds is

Moreover, unless I am misunderstanding something, that breaks the
set by the "fifo_expire_async" tunable, which in my system is set to the

Looking at the code, it seems to me that the issue is that after we make
an async queue active, there is no guarantee that it will execute any

When the queue itself tests if it cfq_may_dispatch() it can bail if it
sees SYNC
requests in flight. An incoming request from another queue can also
preempt it
in such situation before we have the chance to execute anything (as
seen in the
trace above).

This patch sets the must_dispatch flag if we notice that we have requests
that are already fifo_expired. This flag is always cleared after
cfq_dispatch_request() returns from cfq_dispatch_requests(), so it
won't pin
the queue for subsequent requests (unless they are themselves expired)

Care is taken during preempt to still allow rt requests to preempt us

Testing my workload with this patch applied produces much better results.
From the application side I see no timeouts, and the open() latency
generated by systemtap looks much better, with the worst outlier at

Good analysis and the fix looks nice and clean. I'll take a closer look
tomorrow. Thanks!

Looks like a good patch to me. I've queued it up, thanks Glauber.

Jens Axboe