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

[Jens Axboe <axboe@kernel.dk>]

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
>> seconds.
>>
>> The problem seems to happen because XFS may block on pending metadata
>> updates
>> under certain circumnstances, and that's confirmed with the following
>> backtrace
>> 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
>> the
>> 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
>> [xfsaild/sda1]
>>   8,0   11      154    81.092473207   804  G  WM 141698288 + 8
>> [xfsaild/sda1]
>>   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
>> dispatch
>> 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 /
>> insert_request
>>   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
>> requests.
>> 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
>> anyone's
>> goal.
>>
>> Moreover, unless I am misunderstanding something, that breaks the
>> expectation
>> set by the "fifo_expire_async" tunable, which in my system is set to the
>> default.
>>
>> 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
>> request.
>>
>> 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
>> regardless.
>>
>> Testing my workload with this patch applied produces much better results.
>> From the application side I see no timeouts, and the open() latency
>> histogram
>> generated by systemtap looks much better, with the worst outlier at
>> 131ms:
>
> 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