search

axboe / liburing

Library providing helpers for the Linux kernel io_uring support
MIT License
2.7k stars 393 forks source link

`io_uring_peek_batch_cqe` does not populate `cqe` over FFI consistently! #1159

Open YoSTEALTH opened 1 month ago

YoSTEALTH commented 1 month ago

After couple months of segfaults(over interpreter) narrowed the bug down to io_uring_peek_batch_cqe not populating cqe consistently. The first loop always runs fine after its anyone's guess as to when it will segfault from not populating cqe


while counter := ((io_uring_submit(ring) if io_uring_sq_ready(ring) else 0) + counter - cq_ready):

    # get count of how many event(s) are ready and fill `cqe`
    while not (cq_ready := io_uring_peek_batch_cqe(ring, cqe, counter)):
        io_uring_wait_cqe_nr(ring, cqe, 1)  # wait for at least `1` event to be ready.

    for i in range(cq_ready):
        # do stuff ...
axboe commented 1 month ago

What's the sequence that reproduces it? I have no issues here, and since it's not a header function, we should be running the exact same thing.

I am, once again, suspicious of the other code! But if you can boil it down to something that reproduces it reliably for you, then it'd be easier to take a look at. You can also try and re-compile liburing and add:

assert(i == count);

to src/queue.c:io_uring_peek_batch_cqe() before where it does

return count;

as that should be the only way that we'd ever return a value that doesn't match what we already looped and filled it with. In diff form, it'd look like:

diff --git a/src/queue.c b/src/queue.c
index c4360614ecf3..b74f984fa631 100644
--- a/src/queue.c
+++ b/src/queue.c
@@ -1,6 +1,7 @@
 /* SPDX-License-Identifier: MIT */
 #define _POSIX_C_SOURCE 200112L

+#include <assert.h>
 #include "lib.h"
 #include "syscall.h"
 #include "liburing.h"
@@ -182,6 +183,7 @@ again:
        for (;head != last; head++, i++)
            cqes[i] = &ring->cq.cqes[(head & mask) << shift];

+       assert(count == i);
        return count;
    }
axboe commented 1 month ago

Oh, and you'd need to configure liburing as:

$ ./configure --use-libc

for that to work.

YoSTEALTH commented 1 month ago

Its happens over FFI though! So in C I am sure there isn't an issues with it.

I have changed the code to use io_uring_for_each_cqe vs io_uring_peek_batch_cqe and it doesn't segfault, though its not perfect yet.

while counter := ((io_uring_submit(ring) if io_uring_sq_ready(ring) else 0) + counter - cq_ready):

    # get count of how many event(s) are ready and fill `cqe`
    while not (cq_ready := io_uring_cq_ready(ring)):
        io_uring_wait_cqe_nr(ring, cqe, 1)  # wait for at least `1` event to be ready.

    io_uring_for_each_cqe(ring, cqe)

    for i in range(cq_ready):
        # do stuff ...

You can see it effect this library https://github.com/YoSTEALTH/Shakti

axboe commented 1 month ago

I have changed the code to use io_uring_for_each_cqe vs io_uring_peek_batch_cqe and it doesn't segfault, though its not perfect yet.

That doesn't really help me, as I'd be interested in figuring out if there is an issue with io_uring_peek_batch_cqe(). If you could try what I suggested, that'd be awesome, thanks!

YoSTEALTH commented 1 month ago

Added that C code and compiled, getting:

In file included from queue.c:4:                                                         
queue.c: In function ‘io_uring_peek_batch_cqe’:                                          
queue.c:186:22: warning: comparison of integer expressions of different signedness: ‘unsigned int’ and ‘int’ [-Wsign-compare]                                                     
  186 |         assert(count == i);                                                      
      |                      ^~

Not sure if you wanting me to run some test file!. Running python test code, back to segfault.

YoSTEALTH commented 1 month ago

io_uring_for_each_cqe kinda works! But there are certain time where cqe doesn't get populated as well. Its just running bunch of io_uring_prep_nop. I am not sure how to reproduce this in C its clearly C data not reaching Python side (sometimes).

As for the wrapper, there isn't much to it:

cdef class io_uring_cqe:
    cdef __io_uring_cqe* ptr

it just a pointer and Liburing does all the assigning memory, data, removal.

YoSTEALTH commented 1 month ago

Not sure why but io_uring_peek_cqe(ring, cqe) returns 4294967285 vs 0 on success and -EAGAIN on failure

YoSTEALTH commented 1 month ago

Finally!!! after 2 whole months of dealing with segfault, solution was to use different Liburing functions?!

    while counter := ((io_uring_submit(ring) if io_uring_sq_ready(ring) else 0)+counter-cq_ready):
        cq_ready = 0
        while io_uring_peek_cqe(ring, cqe) == -EAGAIN:
            io_uring_wait_cqe_nr(ring, cqe, 1)  # wait for at least `1` event to be ready.

        for index in range(io_uring_for_each_cqe(ring, cqe)):
            # do stuff ...

Not sure why io_uring_peek_batch_cqe was glitching out like that. Sure needs an investigation.

Today was the last day I could work on fixing this bug, glad I burnt the midnight oil to get er done :)

axboe commented 1 month ago

Not sure why but io_uring_peek_cqe(ring, cqe) returns 4294967285 vs 0 on success and -EAGAIN on failure

4294967285 is -EAGAIN, it sounds like a casting issue on your side where it becomes unsigned.

YoSTEALTH commented 1 month ago

Not sure what was happening with 4294967285 same code working fine now, maybe a glitch in the matrix.

Real issues is to figure out whats happening with io_uring_peek_batch_cqe, I must have compiled (gcc, clang) near to thousand times, many different codes, I had over 10GB+ core dump files ...

axboe commented 1 month ago

Looking at your earlier segfaults, are you sure it isn't some random memory issues you are seeing? Eg a bug in the other code, or something like that. They don't look related to liburing, but they do look like use-after-free issues, or double frees.

axboe commented 1 month ago

io_uring_for_each_cqe kinda works! But there are certain time where cqe doesn't get populated as well.

Things like that make me very suspicious, because while the peek batch API is probably not that widely used, io_uring_for_each_cqe() certainly is. And I find it very hard to believe there's a bug in that.

YoSTEALTH commented 1 month ago

Looking at your earlier segfaults, are you sure it isn't some random memory issues you are seeing? Eg a bug in the other code, or something like that. They don't look related to liburing, but they do look like use-after-free issues, or double frees.

These could certainly be true, I could have goofed somewhere! For now same code io_uring_peek_cqe & io_uring_for_each_cqe works, and io_uring_peek_batch_cqe is a glitch.

Things like that make me very suspicious

This is actually my fault, I was calling io_uring_for_each_cqe without calling io_uring_peek_cqe first, thus the weirdness.

YoSTEALTH commented 1 month ago

O, I forgot to mention.

In my code I have it so sqe->user_data can not be set to 0, if so it will raise error.

While using cq_ready = io_uring_peek_batch_cqe(...) many times I noticed cq_ready would return value like 10 later processing cqe[i].user_data only say 5 of those 10 would have valid user_data and rest would be 0.

Either cq_ready would give higher ready cqe count while in reality only few were ready, or all ready cqe weren't inserted into array?

Another problem was when I would io_uring_cq_advance(ring, cq_ready) this would segfault, maybe because cq_ready was trying to free more cqe than actually available?

axboe commented 1 month ago

I still think this is exceedingly likely an issue in your code or interface. Given that there are demonstrable signedness issues etc, I have to say I don't have a lot of faith in the stability of it.

In terms of completions, you can do:

# echo 1 > /sys/kernel/debug/tracing/events/io_uring/enable

and then view a trace with:

# cat /sys/kernel/debug/tracing/trace

which will tell you what completions came in.

io_uring_cq_advance() only adds an integer to the shared CQ ring head, there's no way that can segfault unless you overwrote some memory, for example.

YoSTEALTH commented 1 month ago

Ok, trying with trace enabled.

For both same exact code, only thing changed are:

Segfault:

    # event manager
    while counter := ((io_uring_submit(ring) if io_uring_sq_ready(ring) else 0)+counter-cq_ready):
        # get count of how many event(s) are ready and fill `cqe`
        while not (cq_ready := io_uring_peek_batch_cqe(ring, cqe, counter)):
            io_uring_wait_cqe_nr(ring, cqe, 1)  # wait for at least `1` event to be ready.

        for index in range(cq_ready):
            res, user_data = cqe.get_index(index)
            if (ptr := <PyObject*><uintptr_t>user_data) is NULL:
                raise RuntimeError('`engine()` - received `NULL` from `user_data`')
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 34/34   #P:24
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
         python3-8831    [001] .....  4383.112306: io_uring_create: ring 000000001a5a30d7, fd 3 sq size 1024, cq size 2048, flags 0x10000
         python3-8831    [001] .....  4383.112357: io_uring_submit_req: ring 000000001a5a30d7, req 00000000d8323653, user_data 0x72576c6665c0, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112359: io_uring_queue_async_work: ring 000000001a5a30d7, request 00000000d8323653, user_data 0x72576c6665c0, opcode NOP, flags 0x40010, normal queue, work 00000000f99d6224
         python3-8831    [001] .....  4383.112405: io_uring_submit_req: ring 000000001a5a30d7, req 000000008934bb66, user_data 0x72576c666500, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112406: io_uring_queue_async_work: ring 000000001a5a30d7, request 000000008934bb66, user_data 0x72576c666500, opcode NOP, flags 0x40010, normal queue, work 00000000135de4eb
         python3-8831    [001] .....  4383.112406: io_uring_submit_req: ring 000000001a5a30d7, req 0000000026f87a3a, user_data 0x72576c5f0dc0, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112407: io_uring_queue_async_work: ring 000000001a5a30d7, request 0000000026f87a3a, user_data 0x72576c5f0dc0, opcode NOP, flags 0x40010, normal queue, work 00000000070c4c78
         python3-8831    [001] .....  4383.112407: io_uring_submit_req: ring 000000001a5a30d7, req 000000004e1b7af5, user_data 0x72576c5f0460, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112407: io_uring_queue_async_work: ring 000000001a5a30d7, request 000000004e1b7af5, user_data 0x72576c5f0460, opcode NOP, flags 0x40010, normal queue, work 0000000022d91cea
         python3-8831    [001] .....  4383.112407: io_uring_submit_req: ring 000000001a5a30d7, req 000000009ac3c392, user_data 0x72576c5f0fa0, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112408: io_uring_queue_async_work: ring 000000001a5a30d7, request 000000009ac3c392, user_data 0x72576c5f0fa0, opcode NOP, flags 0x40010, normal queue, work 00000000508922c1
         python3-8831    [001] .....  4383.112408: io_uring_submit_req: ring 000000001a5a30d7, req 00000000cc5b0bf8, user_data 0x72576c5f1000, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112408: io_uring_queue_async_work: ring 000000001a5a30d7, request 00000000cc5b0bf8, user_data 0x72576c5f1000, opcode NOP, flags 0x40010, normal queue, work 00000000e31f5469
         python3-8831    [001] .....  4383.112408: io_uring_submit_req: ring 000000001a5a30d7, req 00000000dbbc1472, user_data 0x72576c5f1060, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112409: io_uring_queue_async_work: ring 000000001a5a30d7, request 00000000dbbc1472, user_data 0x72576c5f1060, opcode NOP, flags 0x40010, normal queue, work 000000006dcad57f
         python3-8831    [001] .....  4383.112409: io_uring_submit_req: ring 000000001a5a30d7, req 000000009b5895d6, user_data 0x72576c5f10c0, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112409: io_uring_queue_async_work: ring 000000001a5a30d7, request 000000009b5895d6, user_data 0x72576c5f10c0, opcode NOP, flags 0x40010, normal queue, work 0000000090a2d9f8
         python3-8831    [001] .....  4383.112411: io_uring_submit_req: ring 000000001a5a30d7, req 0000000096f98703, user_data 0x72576c4a6500, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112411: io_uring_queue_async_work: ring 000000001a5a30d7, request 0000000096f98703, user_data 0x72576c4a6500, opcode NOP, flags 0x40010, normal queue, work 000000001313aa14
         python3-8831    [001] .....  4383.112411: io_uring_submit_req: ring 000000001a5a30d7, req 00000000e4e79765, user_data 0x72576c4a6560, opcode NOP, flags 0x10, sq_thread 0
         python3-8831    [001] .....  4383.112411: io_uring_queue_async_work: ring 000000001a5a30d7, request 00000000e4e79765, user_data 0x72576c4a6560, opcode NOP, flags 0x40010, normal queue, work 000000008b7003de
         python3-8831    [001] .....  4383.112415: io_uring_cqring_wait: ring 000000001a5a30d7, min_events 1
    iou-wrk-8831-8833    [009] ...1.  4383.112478: io_uring_complete: ring 000000001a5a30d7, req 00000000d8323653, user_data 0x72576c6665c0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112485: io_uring_complete: ring 000000001a5a30d7, req 000000008934bb66, user_data 0x72576c666500, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112486: io_uring_complete: ring 000000001a5a30d7, req 0000000026f87a3a, user_data 0x72576c5f0dc0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112487: io_uring_complete: ring 000000001a5a30d7, req 000000004e1b7af5, user_data 0x72576c5f0460, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112488: io_uring_complete: ring 000000001a5a30d7, req 000000009ac3c392, user_data 0x72576c5f0fa0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112489: io_uring_complete: ring 000000001a5a30d7, req 00000000cc5b0bf8, user_data 0x72576c5f1000, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112490: io_uring_complete: ring 000000001a5a30d7, req 00000000dbbc1472, user_data 0x72576c5f1060, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112492: io_uring_complete: ring 000000001a5a30d7, req 000000009b5895d6, user_data 0x72576c5f10c0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112493: io_uring_complete: ring 000000001a5a30d7, req 0000000096f98703, user_data 0x72576c4a6500, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-8831-8833    [009] ...1.  4383.112493: io_uring_complete: ring 000000001a5a30d7, req 00000000e4e79765, user_data 0x72576c4a6560, result 0, cflags 0x0 extra1 0 extra2 0
         python3-8831    [001] .....  4383.112493: io_uring_task_work_run: tctx 00000000b66e999c, count 6, loops 1
         python3-8831    [001] .....  4383.112495: io_uring_task_work_run: tctx 00000000b66e999c, count 4, loops 1

No problems:

    # event manager
    while counter := ((io_uring_submit(ring) if io_uring_sq_ready(ring) else 0)+counter-cq_ready):
        cq_ready = 0
        if io_uring_peek_cqe(ring, cqe) == -EAGAIN:
            io_uring_wait_cqe_nr(ring, cqe, 1)  # wait for at least `1` event to be ready.

        for index in range(io_uring_for_each_cqe(ring, cqe)):
            res, user_data = cqe.get_index(index)
            if (ptr := <PyObject*><uintptr_t>user_data) is NULL:
                raise RuntimeError('`engine()` - received `NULL` from `user_data`')
            cq_ready += 1
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 33/33   #P:24
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
         python3-9116    [019] .....  4526.441262: io_uring_create: ring 000000002032cb5a, fd 3 sq size 1024, cq size 2048, flags 0x10000
         python3-9116    [019] .....  4526.441325: io_uring_submit_req: ring 000000002032cb5a, req 0000000032288e5f, user_data 0x71785ba665c0, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441327: io_uring_queue_async_work: ring 000000002032cb5a, request 0000000032288e5f, user_data 0x71785ba665c0, opcode NOP, flags 0x40010, normal queue, work 00000000b6665afe
         python3-9116    [019] .....  4526.441371: io_uring_submit_req: ring 000000002032cb5a, req 000000006190a3eb, user_data 0x71785ba66500, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441371: io_uring_queue_async_work: ring 000000002032cb5a, request 000000006190a3eb, user_data 0x71785ba66500, opcode NOP, flags 0x40010, normal queue, work 00000000ab7055aa
         python3-9116    [019] .....  4526.441372: io_uring_submit_req: ring 000000002032cb5a, req 00000000086a43f0, user_data 0x71785b9f0dc0, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441372: io_uring_queue_async_work: ring 000000002032cb5a, request 00000000086a43f0, user_data 0x71785b9f0dc0, opcode NOP, flags 0x40010, normal queue, work 0000000017f0a9ea
         python3-9116    [019] .....  4526.441372: io_uring_submit_req: ring 000000002032cb5a, req 00000000042a093c, user_data 0x71785b9f0460, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441372: io_uring_queue_async_work: ring 000000002032cb5a, request 00000000042a093c, user_data 0x71785b9f0460, opcode NOP, flags 0x40010, normal queue, work 00000000d429ca3b
         python3-9116    [019] .....  4526.441373: io_uring_submit_req: ring 000000002032cb5a, req 000000007097a369, user_data 0x71785b9f0fa0, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441373: io_uring_queue_async_work: ring 000000002032cb5a, request 000000007097a369, user_data 0x71785b9f0fa0, opcode NOP, flags 0x40010, normal queue, work 00000000cdf133ed
         python3-9116    [019] .....  4526.441373: io_uring_submit_req: ring 000000002032cb5a, req 00000000069f27ce, user_data 0x71785b9f1000, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441373: io_uring_queue_async_work: ring 000000002032cb5a, request 00000000069f27ce, user_data 0x71785b9f1000, opcode NOP, flags 0x40010, normal queue, work 00000000ac14df27
         python3-9116    [019] .....  4526.441374: io_uring_submit_req: ring 000000002032cb5a, req 00000000382bb775, user_data 0x71785b9f1060, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441374: io_uring_queue_async_work: ring 000000002032cb5a, request 00000000382bb775, user_data 0x71785b9f1060, opcode NOP, flags 0x40010, normal queue, work 0000000020ed3eeb
         python3-9116    [019] .....  4526.441374: io_uring_submit_req: ring 000000002032cb5a, req 00000000f59b29d9, user_data 0x71785b9f10c0, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441374: io_uring_queue_async_work: ring 000000002032cb5a, request 00000000f59b29d9, user_data 0x71785b9f10c0, opcode NOP, flags 0x40010, normal queue, work 000000008d6e0cbe
         python3-9116    [019] .....  4526.441376: io_uring_submit_req: ring 000000002032cb5a, req 000000006b26aef7, user_data 0x71785b8a6500, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441376: io_uring_queue_async_work: ring 000000002032cb5a, request 000000006b26aef7, user_data 0x71785b8a6500, opcode NOP, flags 0x40010, normal queue, work 0000000004825a78
         python3-9116    [019] .....  4526.441376: io_uring_submit_req: ring 000000002032cb5a, req 000000008326ecfe, user_data 0x71785b8a6560, opcode NOP, flags 0x10, sq_thread 0
         python3-9116    [019] .....  4526.441376: io_uring_queue_async_work: ring 000000002032cb5a, request 000000008326ecfe, user_data 0x71785b8a6560, opcode NOP, flags 0x40010, normal queue, work 00000000a2ab8519
         python3-9116    [019] .....  4526.441379: io_uring_cqring_wait: ring 000000002032cb5a, min_events 1
    iou-wrk-9116-9118    [012] ...1.  4526.441415: io_uring_complete: ring 000000002032cb5a, req 0000000032288e5f, user_data 0x71785ba665c0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441422: io_uring_complete: ring 000000002032cb5a, req 000000006190a3eb, user_data 0x71785ba66500, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441423: io_uring_complete: ring 000000002032cb5a, req 00000000086a43f0, user_data 0x71785b9f0dc0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441424: io_uring_complete: ring 000000002032cb5a, req 00000000042a093c, user_data 0x71785b9f0460, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441425: io_uring_complete: ring 000000002032cb5a, req 000000007097a369, user_data 0x71785b9f0fa0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441426: io_uring_complete: ring 000000002032cb5a, req 00000000069f27ce, user_data 0x71785b9f1000, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441426: io_uring_complete: ring 000000002032cb5a, req 00000000382bb775, user_data 0x71785b9f1060, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441427: io_uring_complete: ring 000000002032cb5a, req 00000000f59b29d9, user_data 0x71785b9f10c0, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441428: io_uring_complete: ring 000000002032cb5a, req 000000006b26aef7, user_data 0x71785b8a6500, result 0, cflags 0x0 extra1 0 extra2 0
    iou-wrk-9116-9118    [012] ...1.  4526.441429: io_uring_complete: ring 000000002032cb5a, req 000000008326ecfe, user_data 0x71785b8a6560, result 0, cflags 0x0 extra1 0 extra2 0
         python3-9116    [019] .....  4526.441433: io_uring_task_work_run: tctx 000000009c113459, count 10, loops 1