IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

Hi,

I have started to use io_uring with kernel 5.11.16 and libev 4.33.

Actually, I did significantly change libev code mostly to use liburing
instead of replacing most of its boilerplace code for my prototype.

There is no SQPOLL thread in my setup. io_uring initialisation is as
plain as it can be:

ecb_cold
static int
iouring_internal_init (EV_P)
{
  struct io_uring_params params = { 0 };

  if (!have_monotonic) /* cannot really happen, but what if!! */
    return -1;

  if (io_uring_queue_init_params(iouring_entries, &iouring_ring,
&params) < 0)
    return -1;

  return 0;
}

I use io_uring for polling O_NONBLOCK TCP sockets.

For the most part, io_uring works as expected EXCEPT for this scenario:

I want to update the polling mask from POLLIN to POLLIN|POLLOUT.

To achieve that, I do submit to SQEs:

inline_speed
void *
iouring_build_user_data(char type, int fd, uint32_t egen)
{
    return (void *)((uint32_t)fd | ((__u64)(egen && 0x00ffffff) << 32 )
|
                    ((__u64)type << 56));
}

inline_speed
void
iouring_decode_user_data(uint64_t data, char *type, int *fd, uint32_t
*egen)
{
  *type = data >> 56;
  *fd   = data & 0xffffffffU;
  *egen = (data >> 32) & 0x00ffffffU;
}

          struct io_uring_sqe *sqe = iouring_sqe_get (EV_A);
          printf("%d %d remove %d %u\n", oev, nev, fd, (uint32_t)anfds
[fd].egen);
          io_uring_prep_poll_remove(sqe,
iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
//          io_uring_sqe_set_data(sqe,
iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));

          /* increment generation counter to avoid handling old events
*/
          ++anfds [fd].egen;

          struct io_uring_sqe *sqe = iouring_sqe_get (EV_A);
          io_uring_prep_poll_add(sqe, fd, (nev & EV_READ ? POLLIN : 0)
| (nev & EV_WRITE ? POLLOUT : 0));
          io_uring_sqe_set_data(sqe,
iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
printf("%d %d add %d %u\n", oev, nev, fd, (uint32_t)anfds [fd].egen);

Followed by a io_uring_enter() call buried in liburing code to submit the 2 sqes at the same time:

inline_speed
int
iouring_enter (EV_P_ ev_tstamp timeout)
{
  int res;
  struct __kernel_timespec ts;
  struct io_uring_cqe *cqe_ptr;
  EV_TS_SET(ts, timeout);
  EV_RELEASE_CB;

  res = io_uring_wait_cqe_timeout(&iouring_ring, &cqe_ptr, &ts);

  EV_ACQUIRE_CB;

  return res;
}

On the CQE processing side, I have the following trace:

// fd is hardcoded to filter out all the calls working fine
if (fd == 85)
            printf("85 gen %d res %d\n", (uint32_t)gen, res);

Here is the output:
85 gen 1 res 195
0 1 add 85 1

// Those 2 sqes are submitted at the same time
1 3 remove 85 1
1 3 add 85 2

85 gen 1 res -125
85 gen 1 res 4

When I receive '85 gen 1 res 4', it is discarded because gen 1 poll
request has been cancelled. The code will process gen 2 cqes from
there.

My '1 3 add 85 2' sqe has been silently discarded. After 1 minute of
unexpected fd inactivity, I try to remove my gen 2 POLL request and it
result to a cqe reporting an ENOENT error.

1. 195 is the cqe result for a successful IORING_OP_POLL_ADD
submission. I only check the POLLIN|POLLOUT bits. What is the meaning
of the other bits?

2. I don't understand what I am looking at. Why am I receiving a
completion notification for a POLL request that has just been
cancelled? What is the logic behind silently discarding a
IORING_OP_POLL_ADD sqe meant to replace an existing one?

3. As I am writing this email, I have just noticed that it was possible
to update an existing POLL entry with IORING_OP_POLL_REMOVE through
io_uring_prep_poll_update(). Is this what I should do to eliminate my
problems? What are the possible race conditions scenarios that I should
be prepared to handle by using io_uring_prep_poll_update() (ie:
completion of the poll entry to update while my process is inside
io_uring_enter() to update it...)?

thx a lot for your guidance in my io_uring journey!
Olivier

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

On Tue, 2021-05-04 at 14:06 -0400, Olivier Langlois wrote:
> 
> 1. 195 is the cqe result for a successful IORING_OP_POLL_ADD
> submission. I only check the POLLIN|POLLOUT bits. What is the meaning
> of the other bits?

I did answer myself for question #1:

fs/io_uring.c:
static void io_poll_complete(struct io_kiocb *req, __poll_t mask, int
error)
{
        struct io_ring_ctx *ctx = req->ctx;

        io_poll_remove_double(req);
        req->poll.done = true;
        io_cqring_fill_event(req, error ? error : mangle_poll(mask));
        io_commit_cqring(ctx);
}

include/linux/poll.h:
#define __MAP(v, from, to) \
        (from < to ? (v & from) * (to/from) : (v & from) / (from/to))

static inline __u16 mangle_poll(__poll_t val)
{
        __u16 v = (__force __u16)val;
#define M(X) __MAP(v, (__force __u16)EPOLL##X, POLL##X)
        return M(IN) | M(OUT) | M(PRI) | M(ERR) | M(NVAL) |
                M(RDNORM) | M(RDBAND) | M(WRNORM) | M(WRBAND) |
                M(HUP) | M(RDHUP) | M(MSG);
#undef M
}

=195
=0xC3
=1100 0011
// from bits/poll.h:
=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND

The fd for which I get this result is a TCP socket on which the
WebSocket protocol over SSL is implemented.

Does anyone knows if WebSocket and/or TLS/SSL protocols are using TCP
out-of-band?

AFAIK (but I don't much), they don't...

Or maybe Linux poll implementation simply turns on these bits all the
time...

Bottomline, it is unrelated with io_uring but help for my 2 other
questions is still welcomed.

Greetings,
> 
> 2. I don't understand what I am looking at. Why am I receiving a
> completion notification for a POLL request that has just been
> cancelled? What is the logic behind silently discarding a
> IORING_OP_POLL_ADD sqe meant to replace an existing one?
> 
> 3. As I am writing this email, I have just noticed that it was possible
> to update an existing POLL entry with IORING_OP_POLL_REMOVE through
> io_uring_prep_poll_update(). Is this what I should do to eliminate my
> problems? What are the possible race conditions scenarios that I should
> be prepared to handle by using io_uring_prep_poll_update() (ie:
> completion of the poll entry to update while my process is inside
> io_uring_enter() to update it...)?
> 
> thx a lot for your guidance in my io_uring journey!
> Olivier
> 
> 

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Pavel Begunkov]

On 5/4/21 7:06 PM, Olivier Langlois wrote:
> Hi,
> 
> I have started to use io_uring with kernel 5.11.16 and libev 4.33.
> 
> Actually, I did significantly change libev code mostly to use liburing
> instead of replacing most of its boilerplace code for my prototype.
> 
> There is no SQPOLL thread in my setup. io_uring initialisation is as
> plain as it can be:
> 
> ecb_cold
> static int
> iouring_internal_init (EV_P)
> {
>   struct io_uring_params params = { 0 };
> 
>   if (!have_monotonic) /* cannot really happen, but what if!! */
>     return -1;
> 
>   if (io_uring_queue_init_params(iouring_entries, &iouring_ring,
> &params) < 0)
>     return -1;
> 
>   return 0;
> }
> 
> I use io_uring for polling O_NONBLOCK TCP sockets.
> 
> For the most part, io_uring works as expected EXCEPT for this scenario:
> 
> I want to update the polling mask from POLLIN to POLLIN|POLLOUT.
> 
> To achieve that, I do submit to SQEs:
> 
> inline_speed
> void *
> iouring_build_user_data(char type, int fd, uint32_t egen)
> {
>     return (void *)((uint32_t)fd | ((__u64)(egen && 0x00ffffff) << 32 )
> |
>                     ((__u64)type << 56));
> }
> 
> inline_speed
> void
> iouring_decode_user_data(uint64_t data, char *type, int *fd, uint32_t
> *egen)
> {
>   *type = data >> 56;
>   *fd   = data & 0xffffffffU;
>   *egen = (data >> 32) & 0x00ffffffU;
> }
> 
>           struct io_uring_sqe *sqe = iouring_sqe_get (EV_A);
>           printf("%d %d remove %d %u\n", oev, nev, fd, (uint32_t)anfds
> [fd].egen);
>           io_uring_prep_poll_remove(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> //          io_uring_sqe_set_data(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> 
>           /* increment generation counter to avoid handling old events
> */
>           ++anfds [fd].egen;
> 
>           struct io_uring_sqe *sqe = iouring_sqe_get (EV_A);
>           io_uring_prep_poll_add(sqe, fd, (nev & EV_READ ? POLLIN : 0)
> | (nev & EV_WRITE ? POLLOUT : 0));
>           io_uring_sqe_set_data(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> printf("%d %d add %d %u\n", oev, nev, fd, (uint32_t)anfds [fd].egen);
> 
> Followed by a io_uring_enter() call buried in liburing code to submit the 2 sqes at the same time:
> 
> inline_speed
> int
> iouring_enter (EV_P_ ev_tstamp timeout)
> {
>   int res;
>   struct __kernel_timespec ts;
>   struct io_uring_cqe *cqe_ptr;
>   EV_TS_SET(ts, timeout);
>   EV_RELEASE_CB;
> 
>   res = io_uring_wait_cqe_timeout(&iouring_ring, &cqe_ptr, &ts);
> 
>   EV_ACQUIRE_CB;
> 
>   return res;
> }
> 
> On the CQE processing side, I have the following trace:
> 
> // fd is hardcoded to filter out all the calls working fine
> if (fd == 85)
>             printf("85 gen %d res %d\n", (uint32_t)gen, res);
> 
> Here is the output:
> 85 gen 1 res 195
> 0 1 add 85 1
> 
> // Those 2 sqes are submitted at the same time
> 1 3 remove 85 1
> 1 3 add 85 2
> 
> 85 gen 1 res -125
> 85 gen 1 res 4
> 
> When I receive '85 gen 1 res 4', it is discarded because gen 1 poll
> request has been cancelled. The code will process gen 2 cqes from
> there.
> 
> My '1 3 add 85 2' sqe has been silently discarded. After 1 minute of
> unexpected fd inactivity, I try to remove my gen 2 POLL request and it
> result to a cqe reporting an ENOENT error.
> 
> 1. 195 is the cqe result for a successful IORING_OP_POLL_ADD
> submission. I only check the POLLIN|POLLOUT bits. What is the meaning
> of the other bits?
> 
> 2. I don't understand what I am looking at. Why am I receiving a
> completion notification for a POLL request that has just been
> cancelled? What is the logic behind silently discarding a
> IORING_OP_POLL_ADD sqe meant to replace an existing one?

I'm lost in your message, so let's start with simple reasons. All
requests post one CQE (almost true), including poll_remove requests.

io_uring_prep_poll_remove(sqe, iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
// io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));

If poll remove and poll requests have identical user_data, as in
the second (commented?) line you'll get two CQEs with that user_data.

Did you check return value (in CQE) of poll remove? I'd recommend
set its user_data to something unique. Did you consider that it
may fail?
 
> 3. As I am writing this email, I have just noticed that it was possible
> to update an existing POLL entry with IORING_OP_POLL_REMOVE through
> io_uring_prep_poll_update(). Is this what I should do to eliminate my
> problems? What are the possible race conditions scenarios that I should
> be prepared to handle by using io_uring_prep_poll_update() (ie:
> completion of the poll entry to update while my process is inside
> io_uring_enter() to update it...)?

Update is preferable, but it's Linux kernel 5.13.
Both remove and update may fail. e.g. with -EALREADY

-- 
Pavel Begunkov

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

Hi Pavel,

On Wed, 2021-05-05 at 18:56 +0100, Pavel Begunkov wrote:
> On 5/4/21 7:06 PM, Olivier Langlois wrote:
> > 
> > 
> > 2. I don't understand what I am looking at. Why am I receiving a
> > completion notification for a POLL request that has just been
> > cancelled? What is the logic behind silently discarding a
> > IORING_OP_POLL_ADD sqe meant to replace an existing one?
> 
> I'm lost in your message, so let's start with simple reasons. All
> requests post one CQE (almost true), including poll_remove requests.
> 
> io_uring_prep_poll_remove(sqe, iouring_build_user_data(IOURING_POLL,
> fd, anfds [fd].egen));
> // io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL, fd,
> anfds [fd].egen));
> 
> If poll remove and poll requests have identical user_data, as in
> the second (commented?) line you'll get two CQEs with that user_data.
> 
> Did you check return value (in CQE) of poll remove? I'd recommend
> set its user_data to something unique. Did you consider that it
> may fail?

Your comments does help me to see clearer!

You are correct that setting the poll remove user_data is not done.
(hence the commented out statement for that purpose but I must have
entertain the idea to set it at some point to see what good it would
do)

The reason being that I do not care about whether or not it succeeds
because the very next thing that I do is to rearm the poll for the same
fd with a different event mask.

Beside, the removed poll original sqe is reported back as ECANCELED (-
125):
85 gen 1 res -125

This appear to be the code returned in io_poll_remove_one()

Does the poll remove operation generates 2 cqes?
1 for the canceled sqe and and 1 for the poll remove sqe itself?

I am not too sure what good setting a distinct user_data to the poll
remove sqe could do but I will definitely give it a shot to perhaps see
clearer.

Note that the poll remove sqe and the following poll add sqe don't have
exactly the same user_data.

I have this statement in between:
/* increment generation counter to avoid handling old events */
          ++anfds [fd].egen;

poll remove cancel the previous poll add having gen 1 in its user data.
the next poll add has it user_data storing gen var set to 2:

1 3 remove 85 1
1 3 add 85 2

85 gen 1 res -125
85 gen 1 res 4

I'll try to be more succinct this time.

If the poll add sqe having gen 1 in its user_data is cancelled, how can
its completion can be reported in the very next cqe?

and I never hear back about the poll add gen 2 sqe...

I'll try to get more familiar with the fs/io_uring.c code but it feels
like it could be some optimization done where because the cancelled
poll result is available while inside io_uring_enter(), instead of
discarding it to immediately rearm it for the new poll add request,
io_uring_enter() instead decide to return it back to reply to the gen 2
request but it forgets to update the user_data field before doing so...

Maybe what is confusing is that the heading "1 3" in my traces is the
EV_READ EV_WRITE bitmask which values are:

EV_READ  = 1
EV_WRITE = 2

while

POLLIN  = 1
POLLOUT = 4

So my poll add gen 1 request was for be notified for POLLIN. This is
what I got with the question #1 "195" result.

Therefore the:
85 gen 1 res 4

can only be for my poll add gen 2 requesting for POLLIN|POLLOUT. Yet,
it is reported with the previous request user_data...

I feel the mystery is almost solved with your help... I'll continue my
investigation and I'll report back if I finally solve the mystery.
>  
> > 3. As I am writing this email, I have just noticed that it was
> > possible
> > to update an existing POLL entry with IORING_OP_POLL_REMOVE through
> > io_uring_prep_poll_update(). Is this what I should do to eliminate my
> > problems? What are the possible race conditions scenarios that I
> > should
> > be prepared to handle by using io_uring_prep_poll_update() (ie:
> > completion of the poll entry to update while my process is inside
> > io_uring_enter() to update it...)?
> 
> Update is preferable, but it's Linux kernel 5.13.
> Both remove and update may fail. e.g. with -EALREADY
> 
I am just about to install 5.12 on my system and this and the new
multishot poll feature makes me already crave 5.13!

Greetings,
Olivier

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

On Wed, 2021-05-05 at 23:17 -0400, Olivier Langlois wrote:
> Note that the poll remove sqe and the following poll add sqe don't have
> exactly the same user_data.
> 
> I have this statement in between:
> /* increment generation counter to avoid handling old events */
>           ++anfds [fd].egen;
> 
> poll remove cancel the previous poll add having gen 1 in its user data.
> the next poll add has it user_data storing gen var set to 2:
> 
> 1 3 remove 85 1
> 1 3 add 85 2
> 
> 85 gen 1 res -125
> 85 gen 1 res 4
> 
Good news!

I have used the io_uring tracepoints and they confirm that io_uring
works as expected:

For the above printfs, I get the following perf traces:

 11940.259 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
0xffff9d3c4368c000, opcode: 7, force_nonblock: 1)
 11940.270 Execution SVC/134675 io_uring:io_uring_complete(ctx:
0xffff9d3c4368c000, user_data: 4294967382, res: -125)
 11940.272 Execution SVC/134675 io_uring:io_uring_complete(ctx:
0xffff9d3c4368c000)
 11940.275 Execution SVC/134675 io_uring:io_uring_file_get(ctx:
0xffff9d3c4368c000, fd: 86)
 11940.277 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
0xffff9d3c4368c000, opcode: 6, user_data: 4294967382, force_nonblock:
1)
 11940.279 Execution SVC/134675 io_uring:io_uring_complete(ctx:
0xffff9d3c4368c000, user_data: 4294967382, res: 4)

So, it seems the compiler is playing games on me. It prints the correct
gen 2 value but is passing 1 to io_uring_sqe_set_data()...

I'll try to turn optimization off to see if it helps.

thx a lot again for your exceptional work!

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

On Thu, 2021-05-06 at 04:42 -0400, Olivier Langlois wrote:
> On Wed, 2021-05-05 at 23:17 -0400, Olivier Langlois wrote:
> > Note that the poll remove sqe and the following poll add sqe don't
> > have
> > exactly the same user_data.
> > 
> > I have this statement in between:
> > /* increment generation counter to avoid handling old events */
> >           ++anfds [fd].egen;
> > 
> > poll remove cancel the previous poll add having gen 1 in its user
> > data.
> > the next poll add has it user_data storing gen var set to 2:
> > 
> > 1 3 remove 85 1
> > 1 3 add 85 2
> > 
> > 85 gen 1 res -125
> > 85 gen 1 res 4
> > 
> Good news!
> 
> I have used the io_uring tracepoints and they confirm that io_uring
> works as expected:
> 
> For the above printfs, I get the following perf traces:
> 
>  11940.259 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
> 0xffff9d3c4368c000, opcode: 7, force_nonblock: 1)
>  11940.270 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> 0xffff9d3c4368c000, user_data: 4294967382, res: -125)
>  11940.272 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> 0xffff9d3c4368c000)
>  11940.275 Execution SVC/134675 io_uring:io_uring_file_get(ctx:
> 0xffff9d3c4368c000, fd: 86)
>  11940.277 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
> 0xffff9d3c4368c000, opcode: 6, user_data: 4294967382, force_nonblock:
> 1)
>  11940.279 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> 0xffff9d3c4368c000, user_data: 4294967382, res: 4)
> 
> So, it seems the compiler is playing games on me. It prints the correct
> gen 2 value but is passing 1 to io_uring_sqe_set_data()...
> 
> I'll try to turn optimization off to see if it helps.
> 
> thx a lot again for your exceptional work!
> 
> 
The more I fool around trying to find the problem, the more I think
that my problem is somewhere in the liburing (v2.0) code because of a
possibly missing memory barrier.

The function that I do use to submit the sqes is
io_uring_wait_cqe_timeout().

My problem did appear when I did replace libev original boilerplate
code for liburing (v2.0) used for filling and submitting the sqes.

Do you remember when you pointed out that I wasn't setting the
user_data field for my poll remove request in:

io_uring_prep_poll_remove(sqe,
iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
//          io_uring_sqe_set_data(sqe,
iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));

?

The last call to remove the non-existant 'add 85 2' is replied by
ENOENT by io_uring and this was caught by an assert in my case
IOURING_POLL cqe handler.

  iouring_decode_user_data(cqe->user_data, &type, &fd, &gen);

  switch (type) {

This is impossible to end up there because if you do not explicitly set
user_data, io_uring_prep_rw() is setting it to 0.

In order for my assert to be hit, user_data would have to be set with
the commented out io_uring_sqe_set_data(), and it happens to also be
the value of the previously sent sqe user_data...

I did replace the code above with:

io_uring_prep_poll_remove(sqe,
iouring_build_user_data(IOURING_POLL_ADD, fd, anfds [fd].egen));
io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL_REMOVE,
fd, anfds [fd].egen));

and my assert for cqe->res != -ENOENT has stopped being hit.

There is clearly something messing with the sqe user_data communication
between user and kernel and I start to suspect that this might be
somewhere inside io_uring_wait_cqe_timeout()...

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Pavel Begunkov]

On 5/6/21 4:46 PM, Olivier Langlois wrote:
> On Thu, 2021-05-06 at 04:42 -0400, Olivier Langlois wrote:
>> On Wed, 2021-05-05 at 23:17 -0400, Olivier Langlois wrote:
>>> Note that the poll remove sqe and the following poll add sqe don't
>>> have
>>> exactly the same user_data.
>>>
>>> I have this statement in between:
>>> /* increment generation counter to avoid handling old events */
>>>           ++anfds [fd].egen;
>>>
>>> poll remove cancel the previous poll add having gen 1 in its user
>>> data.
>>> the next poll add has it user_data storing gen var set to 2:
>>>
>>> 1 3 remove 85 1
>>> 1 3 add 85 2
>>>
>>> 85 gen 1 res -125
>>> 85 gen 1 res 4
>>>
>> Good news!
>>
>> I have used the io_uring tracepoints and they confirm that io_uring
>> works as expected:
>>
>> For the above printfs, I get the following perf traces:
>>
>>  11940.259 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
>> 0xffff9d3c4368c000, opcode: 7, force_nonblock: 1)
>>  11940.270 Execution SVC/134675 io_uring:io_uring_complete(ctx:
>> 0xffff9d3c4368c000, user_data: 4294967382, res: -125)
>>  11940.272 Execution SVC/134675 io_uring:io_uring_complete(ctx:
>> 0xffff9d3c4368c000)
>>  11940.275 Execution SVC/134675 io_uring:io_uring_file_get(ctx:
>> 0xffff9d3c4368c000, fd: 86)
>>  11940.277 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
>> 0xffff9d3c4368c000, opcode: 6, user_data: 4294967382, force_nonblock:
>> 1)
>>  11940.279 Execution SVC/134675 io_uring:io_uring_complete(ctx:
>> 0xffff9d3c4368c000, user_data: 4294967382, res: 4)
>>
>> So, it seems the compiler is playing games on me. It prints the correct
>> gen 2 value but is passing 1 to io_uring_sqe_set_data()...
>>
>> I'll try to turn optimization off to see if it helps.
>>
>> thx a lot again for your exceptional work!
>>
>>
> The more I fool around trying to find the problem, the more I think
> that my problem is somewhere in the liburing (v2.0) code because of a
> possibly missing memory barrier.
> 
> The function that I do use to submit the sqes is
> io_uring_wait_cqe_timeout().
> 
> My problem did appear when I did replace libev original boilerplate
> code for liburing (v2.0) used for filling and submitting the sqes.
> 
> Do you remember when you pointed out that I wasn't setting the
> user_data field for my poll remove request in:
> 
> io_uring_prep_poll_remove(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> //          io_uring_sqe_set_data(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> 
> ?
> 
> The last call to remove the non-existant 'add 85 2' is replied by
> ENOENT by io_uring and this was caught by an assert in my case
> IOURING_POLL cqe handler.
> 
>   iouring_decode_user_data(cqe->user_data, &type, &fd, &gen);
> 
>   switch (type) {
> 
> This is impossible to end up there because if you do not explicitly set
> user_data, io_uring_prep_rw() is setting it to 0.
> 
> In order for my assert to be hit, user_data would have to be set with
> the commented out io_uring_sqe_set_data(), and it happens to also be
> the value of the previously sent sqe user_data...
> 
> I did replace the code above with:
> 
> io_uring_prep_poll_remove(sqe,
> iouring_build_user_data(IOURING_POLL_ADD, fd, anfds [fd].egen));
> io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL_REMOVE,
> fd, anfds [fd].egen));
> 
> and my assert for cqe->res != -ENOENT has stopped being hit.
> 
> There is clearly something messing with the sqe user_data communication
> between user and kernel and I start to suspect that this might be
> somewhere inside io_uring_wait_cqe_timeout()...

What's your kernel? IORING_FEAT_EXT_ARG?

e.g. ring->features & IORING_FEAT_EXT_ARG

Because:

/*
 * Like io_uring_wait_cqe(), except it accepts a timeout value as well. Note
 * that an sqe is used internally to handle the timeout. For kernel doesn't
 * support IORING_FEAT_EXT_ARG, applications using this function must never
 * set sqe->user_data to LIBURING_UDATA_TIMEOUT!
 *
 * For kernels without IORING_FEAT_EXT_ARG (5.10 and older), if 'ts' is
 * specified, the application need not call io_uring_submit() before
 * calling this function, as we will do that on its behalf. From this it also
 * follows that this function isn't safe to use for applications that split SQ
 * and CQ handling between two threads and expect that to work without
 * synchronization, as this function manipulates both the SQ and CQ side.
 *
 * For kernels with IORING_FEAT_EXT_ARG, no implicit submission is done and
 * hence this function is safe to use for applications that split SQ and CQ
 * handling between two threads.
 */


-- 
Pavel Begunkov

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Olivier Langlois]

On Thu, 2021-05-06 at 11:46 -0400, Olivier Langlois wrote:
> On Thu, 2021-05-06 at 04:42 -0400, Olivier Langlois wrote:
> > On Wed, 2021-05-05 at 23:17 -0400, Olivier Langlois wrote:
> > > Note that the poll remove sqe and the following poll add sqe don't
> > > have
> > > exactly the same user_data.
> > > 
> > > I have this statement in between:
> > > /* increment generation counter to avoid handling old events */
> > >           ++anfds [fd].egen;
> > > 
> > > poll remove cancel the previous poll add having gen 1 in its user
> > > data.
> > > the next poll add has it user_data storing gen var set to 2:
> > > 
> > > 1 3 remove 85 1
> > > 1 3 add 85 2
> > > 
> > > 85 gen 1 res -125
> > > 85 gen 1 res 4
> > > 
> > Good news!
> > 
> > I have used the io_uring tracepoints and they confirm that io_uring
> > works as expected:
> > 
> > For the above printfs, I get the following perf traces:
> > 
> >  11940.259 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
> > 0xffff9d3c4368c000, opcode: 7, force_nonblock: 1)
> >  11940.270 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> > 0xffff9d3c4368c000, user_data: 4294967382, res: -125)
> >  11940.272 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> > 0xffff9d3c4368c000)
> >  11940.275 Execution SVC/134675 io_uring:io_uring_file_get(ctx:
> > 0xffff9d3c4368c000, fd: 86)
> >  11940.277 Execution SVC/134675 io_uring:io_uring_submit_sqe(ctx:
> > 0xffff9d3c4368c000, opcode: 6, user_data: 4294967382, force_nonblock:
> > 1)
> >  11940.279 Execution SVC/134675 io_uring:io_uring_complete(ctx:
> > 0xffff9d3c4368c000, user_data: 4294967382, res: 4)
> > 
> > So, it seems the compiler is playing games on me. It prints the
> > correct
> > gen 2 value but is passing 1 to io_uring_sqe_set_data()...
> > 
> > I'll try to turn optimization off to see if it helps.
> > 
> > thx a lot again for your exceptional work!
> > 
> > 
> The more I fool around trying to find the problem, the more I think
> that my problem is somewhere in the liburing (v2.0) code because of a
> possibly missing memory barrier.
> 
> The function that I do use to submit the sqes is
> io_uring_wait_cqe_timeout().
> 
> My problem did appear when I did replace libev original boilerplate
> code for liburing (v2.0) used for filling and submitting the sqes.
> 
> Do you remember when you pointed out that I wasn't setting the
> user_data field for my poll remove request in:
> 
> io_uring_prep_poll_remove(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> //          io_uring_sqe_set_data(sqe,
> iouring_build_user_data(IOURING_POLL, fd, anfds [fd].egen));
> 
> ?
> 
> The last call to remove the non-existant 'add 85 2' is replied by
> ENOENT by io_uring and this was caught by an assert in my case
> IOURING_POLL cqe handler.
> 
>   iouring_decode_user_data(cqe->user_data, &type, &fd, &gen);
> 
>   switch (type) {
> 
> This is impossible to end up there because if you do not explicitly set
> user_data, io_uring_prep_rw() is setting it to 0.
> 
> In order for my assert to be hit, user_data would have to be set with
> the commented out io_uring_sqe_set_data(), and it happens to also be
> the value of the previously sent sqe user_data...
> 
> I did replace the code above with:
> 
> io_uring_prep_poll_remove(sqe,
> iouring_build_user_data(IOURING_POLL_ADD, fd, anfds [fd].egen));
> io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL_REMOVE,
> fd, anfds [fd].egen));
> 
> and my assert for cqe->res != -ENOENT has stopped being hit.
> 
> There is clearly something messing with the sqe user_data communication
> between user and kernel and I start to suspect that this might be
> somewhere inside io_uring_wait_cqe_timeout()...
> 
> 
All is good. After looking under every possible rock, I have finally
found my problem and it has been under my nose during all that time. It
was right in the code that I did share in my original post:

inline_speed
void *
iouring_build_user_data(char type, int fd, uint32_t egen)
{
    return (void *)((uint32_t)fd | ((__u64)(egen && 0x00ffffff) << 32 )
|
                    ((__u64)type << 56));
}

It is the the usage of the boolean && operator instead of using the
bitwise one...

Hopefully, I didn't annoy too much the list members...

The whole saga did at least allow me to become much more knowledgeable
about the amazing io_uring API.

I'm looking forward contributing it sometime in a near future.

thx,
Olivier

Re: IORING_OP_POLL_ADD/IORING_OP_POLL_REMOVE questions

[Pavel Begunkov]

On 5/6/21 4:17 AM, Olivier Langlois wrote:
> Hi Pavel,
> 
> On Wed, 2021-05-05 at 18:56 +0100, Pavel Begunkov wrote:
>> On 5/4/21 7:06 PM, Olivier Langlois wrote:
>>>
>>>
>>> 2. I don't understand what I am looking at. Why am I receiving a
>>> completion notification for a POLL request that has just been
>>> cancelled? What is the logic behind silently discarding a
>>> IORING_OP_POLL_ADD sqe meant to replace an existing one?
>>
>> I'm lost in your message, so let's start with simple reasons. All
>> requests post one CQE (almost true), including poll_remove requests.
>>
>> io_uring_prep_poll_remove(sqe, iouring_build_user_data(IOURING_POLL,
>> fd, anfds [fd].egen));
>> // io_uring_sqe_set_data(sqe, iouring_build_user_data(IOURING_POLL, fd,
>> anfds [fd].egen));
>>
>> If poll remove and poll requests have identical user_data, as in
>> the second (commented?) line you'll get two CQEs with that user_data.
>>
>> Did you check return value (in CQE) of poll remove? I'd recommend
>> set its user_data to something unique. Did you consider that it
>> may fail?
> 
> Your comments does help me to see clearer!
> 
> You are correct that setting the poll remove user_data is not done.
> (hence the commented out statement for that purpose but I must have
> entertain the idea to set it at some point to see what good it would
> do)
> 
> The reason being that I do not care about whether or not it succeeds
> because the very next thing that I do is to rearm the poll for the same
> fd with a different event mask.
> 
> Beside, the removed poll original sqe is reported back as ECANCELED (-
> 125):
> 85 gen 1 res -125

That's why I mentioned setting user_data, so can distinguish cqes.

> This appear to be the code returned in io_poll_remove_one()
> 
> Does the poll remove operation generates 2 cqes?
> 1 for the canceled sqe and and 1 for the poll remove sqe itself?

No, only one.

> 
> I am not too sure what good setting a distinct user_data to the poll
> remove sqe could do but I will definitely give it a shot to perhaps see
> clearer.

again to be able to distinguish cqes, at least for debugging,
but I don't see how it can be not racy without it.

> Note that the poll remove sqe and the following poll add sqe don't have
> exactly the same user_data.

Right, I noticed. Was concerned about gen1 poll and its poll
remove.

 
> I have this statement in between:
> /* increment generation counter to avoid handling old events */
>           ++anfds [fd].egen;
> 
> poll remove cancel the previous poll add having gen 1 in its user data.
> the next poll add has it user_data storing gen var set to 2:
> 
> 1 3 remove 85 1
> 1 3 add 85 2
> 
> 85 gen 1 res -125
> 85 gen 1 res 4
> 
> I'll try to be more succinct this time.
> 
> If the poll add sqe having gen 1 in its user_data is cancelled, how can
> its completion can be reported in the very next cqe?
> 
> and I never hear back about the poll add gen 2 sqe...

This one sounds like that "85 gen 1 res 4"
is actually gen2 but with screwed user_data. I'd rather
double check that you set it right, and don't race
with multiple threads.

FWIW, submission queue filling is not synchronised by
liburing, users should do that.

> 
> I'll try to get more familiar with the fs/io_uring.c code but it feels
> like it could be some optimization done where because the cancelled
> poll result is available while inside io_uring_enter(), instead of
> discarding it to immediately rearm it for the new poll add request,
> io_uring_enter() instead decide to return it back to reply to the gen 2
> request but it forgets to update the user_data field before doing so...

There definitely may be a bug, but it's much more likely
lurking in your code.

> Maybe what is confusing is that the heading "1 3" in my traces is the
> EV_READ EV_WRITE bitmask which values are:
> 
> EV_READ  = 1
> EV_WRITE = 2
> 
> while
> 
> POLLIN  = 1
> POLLOUT = 4
> 
> So my poll add gen 1 request was for be notified for POLLIN. This is
> what I got with the question #1 "195" result.
> 
> Therefore the:
> 85 gen 1 res 4
> 
> can only be for my poll add gen 2 requesting for POLLIN|POLLOUT. Yet,
> it is reported with the previous request user_data...
> 
> I feel the mystery is almost solved with your help... I'll continue my
> investigation and I'll report back if I finally solve the mystery.
>>  
>>> 3. As I am writing this email, I have just noticed that it was
>>> possible
>>> to update an existing POLL entry with IORING_OP_POLL_REMOVE through
>>> io_uring_prep_poll_update(). Is this what I should do to eliminate my
>>> problems? What are the possible race conditions scenarios that I
>>> should
>>> be prepared to handle by using io_uring_prep_poll_update() (ie:
>>> completion of the poll entry to update while my process is inside
>>> io_uring_enter() to update it...)?
>>
>> Update is preferable, but it's Linux kernel 5.13.
>> Both remove and update may fail. e.g. with -EALREADY
>>
> I am just about to install 5.12 on my system and this and the new
> multishot poll feature makes me already crave 5.13!

-- 
Pavel Begunkov