Re: [PATCH 2/2] io_uring: add memory barrier to synchronize io_kiocb's result and iopoll_completed

[Jens Axboe <axboe@kernel.dk>]

On 6/15/20 9:35 AM, Jens Axboe wrote:
> On 6/15/20 9:32 AM, Xiaoguang Wang wrote:
>> hi,
>>
>>> On 6/15/20 8:48 AM, Xiaoguang Wang wrote:
>>>> hi,
>>>>
>>>>> On 6/15/20 3:24 AM, Xiaoguang Wang wrote:
>>>>>> In io_complete_rw_iopoll(), stores to io_kiocb's result and iopoll
>>>>>> completed are two independent store operations, to ensure that once
>>>>>> iopoll_completed is ture and then req->result must been perceived by
>>>>>> the cpu executing io_do_iopoll(), proper memory barrier should be used.
>>>>>>
>>>>>> And in io_do_iopoll(), we check whether req->result is EAGAIN, if it is,
>>>>>> we'll need to issue this io request using io-wq again. In order to just
>>>>>> issue a single smp_rmb() on the completion side, move the re-submit work
>>>>>> to io_iopoll_complete().
>>>>>
>>>>> Did you actually test this one?
>>>> I only run test cases in liburing/test in a vm.
>>>>
>>>>>
>>>>>> @@ -1736,11 +1748,20 @@ static void io_iopoll_complete(struct io_ring_ctx *ctx, unsigned int *nr_events,
>>>>>>    {
>>>>>>    	struct req_batch rb;
>>>>>>    	struct io_kiocb *req;
>>>>>> +	LIST_HEAD(again);
>>>>>> +
>>>>>> +	/* order with ->result store in io_complete_rw_iopoll() */
>>>>>> +	smp_rmb();
>>>>>>    
>>>>>>    	rb.to_free = rb.need_iter = 0;
>>>>>>    	while (!list_empty(done)) {
>>>>>>    		int cflags = 0;
>>>>>>    
>>>>>> +		if (READ_ONCE(req->result) == -EAGAIN) {
>>>>>> +			req->iopoll_completed = 0;
>>>>>> +			list_move_tail(&req->list, &again);
>>>>>> +			continue;
>>>>>> +		}
>>>>>>    		req = list_first_entry(done, struct io_kiocb, list);
>>>>>>    		list_del(&req->list);
>>>>>>    
>>>>>
>>>>> You're using 'req' here before you initialize it...
>>>> Sorry, next time when I submit patches, I'll construct test cases which
>>>> will cover my codes changes.
>>>
>>> I'm surprised the compiler didn't complain, or that the regular testing
>>> didn't barf on it.
>> I'm also surprised, will try to find the reason.
>> And indeed the iopoll test case failed, but below command displayed nothing:
>> [lege@localhost test]$ sudo ./iopoll
>> Then I considered this test case pass wrongly.
>>
>> dmesg show errors:
>> [  127.806945] ==================================================================
>> [  127.806983] BUG: KASAN: use-after-free in io_iopoll_complete+0xbb/0x980
>> [  127.806989] Read of size 4 at addr ffff8886e3e98808 by task io_uring-sq/1643
>>
>> [  127.806999] CPU: 16 PID: 1643 Comm: io_uring-sq Not tainted 5.7.0+ #501
>> [  127.807013] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.11.1-0-g0551a4be2c-prebuilt.qemu-project.org 04/01/2014
>> [  127.807021] Call Trace:
>> [  127.807040]  dump_stack+0x75/0xa0
>> [  127.807047]  ? io_iopoll_complete+0xbb/0x980
>> [  127.807062]  print_address_description.constprop.6+0x1a/0x220
>> [  127.807086]  ? _raw_write_lock_irqsave+0xd0/0xd0
>> [  127.807092]  ? io_free_req_many.part.79+0x208/0x2a0
>> [  127.807107]  ? __rcu_read_unlock+0x37/0x200
>> [  127.807112]  ? io_iopoll_complete+0xbb/0x980
>> [  127.807117]  ? io_iopoll_complete+0xbb/0x980
>> [  127.807122]  kasan_report.cold.9+0x1f/0x42
>> [  127.807128]  ? io_iopoll_complete+0xbb/0x980
>> [  127.807133]  io_iopoll_complete+0xbb/0x980
>> [  127.807138]  ? io_timeout_fn+0x140/0x140
>> [  127.807150]  ? __switch_to+0x2e9/0x5a0
>> [  127.807157]  io_iopoll_getevents+0x287/0x310
>> [  127.807163]  ? io_iopoll_complete+0x980/0x980
>> [  127.807172]  ? finish_wait+0xcb/0xf0
>> [  127.807179]  io_sq_thread+0x1c1/0x600
>> [  127.807185]  ? __ia32_sys_io_uring_enter+0x450/0x450
>> [  127.807194]  ? preempt_count_add+0x77/0xd0
>> [  127.807200]  ? _raw_spin_lock_irqsave+0x84/0xd0
>> [  127.807206]  ? _raw_write_lock_irqsave+0xd0/0xd0
>> [  127.807210]  ? finish_wait+0xf0/0xf0
>> [  127.807215]  ? preempt_count_sub+0x18/0xc0
>> [  127.807224]  ? __kthread_parkme+0xaf/0xd0
>> [  127.807231]  ? __ia32_sys_io_uring_enter+0x450/0x450
>> [  127.807235]  kthread+0x1e4/0x210
>> [  127.807241]  ? kthread_create_on_node+0xa0/0xa0
>> [  127.807246]  ret_from_fork+0x22/0x30
> 
> There you go, so it did fail, just didn't register as a failure. I should
> probably add a dmesg check for the liburing tests, and fail a test if
> we trigger a WARNING or BUG condition. I'll look into that.

I pushed a commit to liburing so that it should now catch dmesg
errors logged while running a test.

-- 
Jens Axboe