Questions on ublksrv/ublkdrv communication

[mememnt]

Hello!
I'm looking into this project as a part of my thesis, and I find it very fascinating.
However, I do have some questions, so I'll post them here and welcome any assistance.
Additionally, I should point out that I'm far from a "kernel expert," so please be patient!

Let's say that I run ./ublk add -t loop -f <file>.
In the messages shown bellow I have kept only the logs before io_uring_submit_and_wait_timeout() in ublksrv_process_io(), and the the log message in ublksrv_handle_cqe() because I want to understand exactly what sqes we are submitting and what responses we get via cqe.
So the messages are like:

dev0-q0: to_submit 128 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 96 cmd_op 32 target 0 event 0) stopping 0
dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 96 cmd_op 0 target 1 event 0) stopping 0
dev0-q0: to_submit 1 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 97 cmd_op 32 target 0 event 0) stopping 0    
dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 97 cmd_op 0 target 1 event 0) stopping 0  //=> read request from target
dev0-q0: to_submit 1 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 0 cmd_op 32 target 0 event 0) stopping 0  
dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 0 cmd_op 0 target 1 event 0) stopping 0  //=> read request from target
dev0-q0: to_submit 1 inflight 128/0 stopping 0
dev0-q0: to_submit 0 inflight 128/0 stopping 0
dev0-q0: enter idle 0
dev0-q0: to_submit 0 inflight 128/0 stopping 0

Can anyone guide me through these requests?
I get that the first message is before the first submission to the ring. We submit q_depth sqes to inform the driver about our buffers etc. Driver runs q_depth times the case [UBLK_IO_FETCH_REQ] in ublk_ch_uring_cmd(). Then it initiates the /dev/ublkbN and now we are ready to receive read/write requests.

I don't get why we return from the io_uring_submit_and_wait_timeout() if there is no read/write request yet from user.
I was expecting that after the first submission with the q_depth sqes, ublksrv will wait until a user performs a read/write request. Then driver will take care of the request from the block layer in the ublk_queue_rq() and eventually complete a cqe to notify ublksrv.

Also from the messages above I get that there are two requests to the target for read. Why? Why do we "hit" the target if there is no user that read/writes to the target yet?

Thank you.

[ming1]

Hello!

Hello! I'm looking into this project as a part of my thesis, and I find it very fascinating. However, I do have some questions, so I'll post them here and welcome any assistance. Additionally, I should point out that I'm far from a "kernel expert," so please be patient!

ublksrv is one userspace, and interface doc can be found in

https://docs.kernel.org/block/ublk.html

Also the following introduction slide may be helpful for you too:

https://github.com/ming1/ubdsrv/blob/master/doc/ublk_intro.pdf

Let's say that I run ./ublk add -t loop -f <file>. In the messages shown bellow I have kept only the logs before io_uring_submit_and_wait_timeout() in ublksrv_process_io(), and the the log message in ublksrv_handle_cqe() because I want to understand exactly what sqes we are submitting and what responses we get via cqe. So the messages are like:

dev0-q0: to_submit 128 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 96 cmd_op 32 target 0 event 0) stopping 0

cmd_op 32 is UBLK_IO_FETCH_REQ, tag 96 is used, which means the
UBLK_IO_FETCH_REQ request is completed from ublk driver, so one
io command is coming.

dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 96 cmd_op 0 target 1 event 0) stopping 0
dev0-q0: to_submit 1 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 97 cmd_op 32 target 0 event 0) stopping 0
dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 97 cmd_op 0 target 1 event 0) stopping 0 //=> read request from target

The 2nd 4k READ io completed, which is triggered by above io command
tag 97.

dev0-q0: to_submit 1 inflight 128/0 stopping 0
ublksrv_handle_cqe: res 0 (qid 0 tag 0 cmd_op 32 target 0 event 0) stopping 0
dev0-q0: to_submit 1 inflight 127/0 stopping 0
ublksrv_handle_cqe: res 4096 (qid 0 tag 0 cmd_op 0 target 1 event 0) stopping 0 //=> read request from target

The 3rd 4k READ io, same with above, io command tag is 0.

dev0-q0: to_submit 1 inflight 128/0 stopping 0
dev0-q0: to_submit 0 inflight 128/0 stopping 0
dev0-q0: enter idle 0
dev0-q0: to_submit 0 inflight 128/0 stopping 0

Can anyone guide me through these requests? I get that the first message is before the first submission to the ring. We submit `q_depth` sqes to inform the driver about our buffers etc. Driver runs `q_depth` times the `case [UBLK_IO_FETCH_REQ]` in `ublk_ch_uring_cmd()`. Then it initiates the `/dev/ublkbN` and now we are ready to receive read/write requests.

I don't get why we return from the `io_uring_submit_and_wait_timeout()` if there is no read/write request yet from user. I was expecting that after the first submission with the `q_depth` sqes, ublksrv will wait until a user performs a read/write request. Then driver will take care of the request from the block layer in the `ublk_queue_rq()` and eventually complete a cqe to notify ublksrv.

io_uring_submit_and_wait_timeout() returns after 10sec timeout, even though
there is nothing to handle, it is just for handle queue idle.

Also from the messages above I get that there are two requests to the target for read. Why? Why do we "hit" the target if there is no user that read/writes to the target yet?

Since you are running ublksrv as root user, kernel will read the 1st 4k for
parsing disk partition.

But there are 3 4k READs, I guess there maybe someone which read data
in background, maybe systemd, ...

In my environment, I can just see one 4k READ when starting ublk loop.

If you install bpftrace, the following script can help you find who
are reading from ublk disk:

#!/usr/bin/bpftrace

#ifndef BPFTRACE_HAVE_BTF
#include <linux/blkdev.h>
#include <linux/blk-mq.h>
#endif

BEGIN
{
printf("Tracing ublk rq order... Hit Ctrl-C to end.\n");
}

kprobe:ublk_queue_rq
{
$bd = (struct blk_mq_queue_data *)arg1;
$r = (struct request *)(((struct blk_mq_queue_data *)arg1)->rq);

printf("%lu %16s %d %d %s: %s q_id %d last %d offset %llx len %lu %s\n",
    nsecs / 1000,  comm, pid, cpu, ksym(reg("ip")),
    $r->q->disk->disk_name, $r->mq_hctx->queue_num,
    $bd->last, $r->__sector, $r->__data_len >> 9, kstack);

}

[mememnt]

ublksrv is one userspace, and interface doc can be found in

https://docs.kernel.org/block/ublk.html

Also the following introduction slide may be helpful for you too:

https://github.com/ming1/ubdsrv/blob/master/doc/ublk_intro.pdf

Thank you for point it out, but I have read all the ublksrv/ublkdrv specific documentation and I have passed the last month or so read the code both in ublksrv and ublkdrv.

So based on what you are saying I can guess that the "flow" has as:

1. dev0-q0: to_submit 128 inflight 128/0 stopping 0 => Server submits q_depth sqes to ublkdrv
2. ublksrv_handle_cqe: res 0 (qid 0 tag 96 cmd_op 32 target 0 event 0) stopping 0 => One read request is completed, driver informs server to handle the request
3. dev0-q0: to_submit 1 inflight 127/0 stopping 0 => Server submits sqe to the target for read.
4. ublksrv_handle_cqe: res 4096 (qid 0 tag 96 cmd_op 0 target 1 event 0) stopping 0 => target replies
5. dev0-q0: to_submit 1 inflight 128/0 stopping 0 => Server submits sqe to driver to commit the result and inform the driver that the the corresponding ublk_io is available again [UBLK_IO_COMMIT_AND_FETCH_REQ].

And steps 2-5, are happening 3 times, for 3 read requests that we are not quite sure from where they came from [maybe systemd]. Right?

I don't get why we return from the io_uring_submit_and_wait_timeout() if there is no read/write request yet from user. I was expecting that after the first submission with the q_depth sqes, ublksrv will wait until a user performs a read/write request. Then driver will take care of the request from the block layer in the ublk_queue_rq() and eventually complete a cqe to notify ublksrv.

io_uring_submit_and_wait_timeout() returns after 10sec timeout, even though there is nothing to handle, it is just for handle queue idle.

I think you mean after 20 sec right? UBLKSRV_IO_IDLE_SECS which is 20.

If you install bpftrace, the following script can help you find who are reading from ublk disk:

#!/usr/bin/bpftrace

#ifndef BPFTRACE_HAVE_BTF #include <linux/blkdev.h> #include <linux/blk-mq.h> #endif

BEGIN { printf("Tracing ublk rq order... Hit Ctrl-C to end.\n"); }

kprobe:ublk_queue_rq { $bd = (struct blk_mq_queue_data *)arg1; $r = (struct request *)(((struct blk_mq_queue_data *)arg1)->rq);

printf("%lu %16s %d %d %s: %s q_id %d last %d offset %llx len %lu %s\n",
    nsecs / 1000,  comm, pid, cpu, ksym(reg("ip")),
    $r->q->disk->disk_name, $r->mq_hctx->queue_num,
    $bd->last, $r->__sector, $r->__data_len >> 9, kstack);

}

Thank you for this tip! I'll try it!

[ming1]

ublksrv is one userspace, and interface doc can be found in
https://docs.kernel.org/block/ublk.html
Also the following introduction slide may be helpful for you too:
https://github.com/ming1/ubdsrv/blob/master/doc/ublk_intro.pdf

Thank you for point it out, but I have read all the ublksrv/ublkdrv specific documentation and I have passed the last month or so read the code both in ublksrv and ublkdrv.

So based on what you are saying I can guess that the "flow" has as:

1. dev0-q0: to_submit 128 inflight 128/0 stopping 0  => Server submits q_depth sqes to ublkdrv

2. ublksrv_handle_cqe: res 0 (qid 0 tag 96 cmd_op 32 target 0 event 0) stopping 0  => One read request is completed, driver informs server to handle the request

No, it isn't correct, it is just that one application is reading /dev/ublkbN,
so ublk driver completes one io command for notifying ublksrv to
handle this read request.

3. dev0-q0: to_submit 1 inflight 127/0 stopping 0  => Server submits sqe to the **target** for read.

4. ublksrv_handle_cqe: res 4096 (qid 0 tag 96 cmd_op 0 target 1 event 0) stopping 0  => target replies

5. dev0-q0: to_submit 1 inflight 128/0 stopping 0  => Server submits sqe to driver to commit the result and inform the driver that the the corresponding `ublk_io` is available again [UBLK_IO_COMMIT_AND_FETCH_REQ].

Except for 2#, the others are correct.

And steps 2-5, are happening 3 times, for 3 read requests that we are not quite sure from where they came from [maybe systemd]. Right?

The 1st 4k READ is from kernel for reading disk partition table, the other two
aren't sure since I can't observe it in my environment. The other two can
be figured out easily by the bpftrace script I provided.

I don't get why we return from the io_uring_submit_and_wait_timeout() if there is no read/write request yet from user. I was expecting that after the first submission with the q_depth sqes, ublksrv will wait until a user performs a read/write request. Then driver will take care of the request from the block layer in the ublk_queue_rq() and eventually complete a cqe to notify ublksrv.

io_uring_submit_and_wait_timeout() returns after 10sec timeout, even though there is nothing to handle, it is just for handle queue idle.

I think you mean after 20 sec right? UBLKSRV_IO_IDLE_SECS which is 20.

Yeah, you are right.

If you install bpftrace, the following script can help you find who are reading from ublk disk:
#!/usr/bin/bpftrace
#ifndef BPFTRACE_HAVE_BTF #include <linux/blkdev.h> #include <linux/blk-mq.h> #endif
BEGIN { printf("Tracing ublk rq order... Hit Ctrl-C to end.\n"); }
kprobe:ublk_queue_rq { $bd = (struct blk_mq_queue_data *)arg1; $r = (struct request *)(((struct blk_mq_queue_data *)arg1)->rq);

printf("%lu %16s %d %d %s: %s q_id %d last %d offset %llx len %lu %s\n",
    nsecs / 1000,  comm, pid, cpu, ksym(reg("ip")),
    $r->q->disk->disk_name, $r->mq_hctx->queue_num,
    $bd->last, $r->__sector, $r->__data_len >> 9, kstack);

}

Thank you for this tip! I'll try it!

BTW, after install bpftrace package, you have to install kernel-devel, or
'make install' under kernel source tree will install header too.

Thanks,

[mememnt]

Hello @ming1. Running the given bpftrace program and ./ublk add -t loop -f <file> the output is:

Attaching 2 probes...                                                                                                        
Tracing ublk rq order... Hit Ctrl-C to end.                                                                                           
705749041     kworker/1:1H 69 1 ublk_queue_rq:  q_id 0 last 1 offset 0 len 0                                                          
        ublk_queue_rq+1                                                                                                               
        blk_mq_dispatch_rq_list+519                                                                                                   
        blk_mq_do_dispatch_sched+795                                                                                                  
        __blk_mq_sched_dispatch_requests+236                                                                                          
        blk_mq_sched_dispatch_requests+48                                                                                             
        __blk_mq_run_hw_queue+52                                                                                                      
        process_one_work+455                                                                                                          
        worker_thread+77                                                                                                              
        kthread+233                                                                                                                   
        ret_from_fork+34                                                                                                              
                                                                                                                                      
705812467     kworker/1:1H 69 1 ublk_queue_rq:  q_id 0 last 1 offset 0 len 0                                                          
        ublk_queue_rq+1                                                                                                               
        blk_mq_dispatch_rq_list+519                                                                                                   
        blk_mq_do_dispatch_sched+795        
        __blk_mq_sched_dispatch_requests+236
        blk_mq_sched_dispatch_requests+48
        __blk_mq_run_hw_queue+52
        process_one_work+455
        worker_thread+77
        kthread+233
        ret_from_fork+34

705845966     kworker/1:1H 69 1 ublk_queue_rq:  q_id 0 last 1 offset 0 len 0 
        ublk_queue_rq+1
        blk_mq_dispatch_rq_list+519
        blk_mq_do_dispatch_sched+795
        __blk_mq_sched_dispatch_requests+236
        blk_mq_sched_dispatch_requests+48
        __blk_mq_run_hw_queue+52
        process_one_work+455
        worker_thread+77
        kthread+233
        ret_from_fork+34

The process with PID=69 is kblockd, which is the kernel's block IO task. I'm not sure what exactly is the purpose of this task and why it performs 3 reads every time I'm running ./ublk add -t loop -f <file>.

Also I have noticed that each time I'm running let say echo "hello" > /dev/ublkb0, kblockd performs again a read before the write. For instance the above command will give an output of:

1750666110     kworker/0:1H 42 0 ublk_queue_rq:  q_id 0 last 1 offset 0 len 0                                                         
        ublk_queue_rq+1                                                                                                               
        blk_mq_dispatch_rq_list+519                                                                                                   
        blk_mq_do_dispatch_sched+795                                                                                                  
        __blk_mq_sched_dispatch_requests+236                                                                                          
        blk_mq_sched_dispatch_requests+48                                                                                             
        __blk_mq_run_hw_queue+52                                                                                                      
        process_one_work+455                                                                                                          
        worker_thread+77                                                                                                              
        kthread+233                                                                                                                   
        ret_from_fork+34                                                                                                              
                                                                                                                                      
1750685849             bash 510 0 ublk_queue_rq:  q_id 0 last 1 offset 0 len 0                                                        
       ublk_queue_rq+1                                                                                                         
        blk_mq_dispatch_rq_list+519                                                                                                   
        blk_mq_do_dispatch_sched+795                                                                                                  
        __blk_mq_sched_dispatch_requests+236
        blk_mq_sched_dispatch_requests+48
        __blk_mq_run_hw_queue+52
        blk_mq_sched_insert_requests+107
        blk_mq_flush_plug_list+289
        __blk_flush_plug+258
        blk_finish_plug+37
        generic_writepages+87
        do_writepages+188
        filemap_fdatawrite_wbc+95 
        __filemap_fdatawrite_range+88
        filemap_write_and_wait_range+51
        blkdev_put+220
        blkdev_close+22
        __fput+145
        task_work_run+92
        exit_to_user_mode_prepare+461
        syscall_exit_to_user_mode+23
        do_syscall_64+70
        entry_SYSCALL_64_after_hwframe+99

I'm not sure why it does so. If you have any explanation I'll will like to hear it!

Also, if you have any other bpftrace program that you use, and helps you understand better the whole procedure you can share it if you like!

Thanks!

[ming1]

OK, tracing ublk_queue_rq() is useless here, please use the following script
and start it by "./submit.bt ublk 4"

=======submit.bt==========

#!/usr/bin/bpftrace

#ifndef BPFTRACE_HAVE_BTF
#include <linux/blkdev.h>
#endif

kprobe:submit_bio
/strncmp(((struct bio *)arg0)->bi_bdev->bd_disk->disk_name, str($1), $2) == 0/
{
$bio = (struct bio *)arg0;
$gd = (struct gendisk *)$bio->bi_bdev->bd_disk;

    if ($bio->bi_opf & 1) {
            $rw = "write"
    } else {
            $rw = "read"
    }
    @submit_bio[kstack, $gd->disk_name, $rw, comm, tid] = count();

}

[mememnt]

With the new script the output is:

root@debian:~/bpftrace# ./submit_bio.bt ublk 4                                                                                        
Attaching 1 probe...                                                                                                                  
^C                                                                                                                                    
                                                                                                                                      
@submit_bio[                                                                                                                          
    submit_bio+1                                                                                                                      
    block_read_full_folio+573                                                                                                         
    filemap_read_folio+64                                                                                                             
    do_read_cache_folio+117                                                                                                           
    read_part_sector+50                                                                                                               
    adfspart_check_ICS+59                                                                                                             
    bdev_disk_changed+437                                                                                                             
    blkdev_get_whole+122                                                                                                              
    blkdev_get_by_dev.part.0+366                                                                                                      
    disk_scan_partitions+89                                                                                                           
    device_add_disk+907                                                                                                               
    ublk_ctrl_uring_cmd+712                                                                                                           
    io_uring_cmd+148
    io_issue_sqe+413
    io_wq_submit_work+137
    io_worker_handle_work+461
    io_wqe_worker+274
    ret_from_fork+34
, ublkb0, read, iou-wrk-1571, 1585]: 1
@submit_bio[                     
    submit_bio+1
    block_read_full_folio+573
    filemap_read_folio+64
    do_read_cache_folio+117
    read_part_sector+50
    amiga_partition+69
    bdev_disk_changed+437
    blkdev_get_whole+122
    blkdev_get_by_dev.part.0+366
    disk_scan_partitions+89
    device_add_disk+907
    ublk_ctrl_uring_cmd+712
    io_uring_cmd+148
    io_issue_sqe+413
    io_wq_submit_work+137
    io_worker_handle_work+461
    io_wqe_worker+274
    ret_from_fork+34
, ublkb0, read, iou-wrk-1571, 1585]: 1
@submit_bio[                     
    submit_bio+1
    block_read_full_folio+573
    filemap_read_folio+64
    do_read_cache_folio+117
    read_part_sector+50
    ultrix_partition+57
    bdev_disk_changed+437
    blkdev_get_whole+122
    blkdev_get_by_dev.part.0+366
    disk_scan_partitions+89
    device_add_disk+907
    ublk_ctrl_uring_cmd+712
    io_uring_cmd+148
    io_issue_sqe+413
    io_wq_submit_work+137
    io_worker_handle_work+461
    io_wqe_worker+274
    ret_from_fork+34
, ublkb0, read, iou-wrk-1571, 1585]: 1

So it seems that it an io_uring worker [I suppose this is the iou-wrk] that does the 3 reads. I'm not sure for what reason exactly. As I see from the backtrace the only difference is in one function (ultrix_partition, amiga_partition and adfspart_check_ICS).

Furthermore, do you have any idea what is this is read stands for, when I run echo "something" > /dev/ublkb0?
The trace is:

root@debian:~/bpftrace# ./submit_bio.bt ublk 4                                                                                
Attaching 1 probe...                                                                                                                  
^C                                                                                                                                    
                                                                                                                                      
@submit_bio[                                                                                                                          
    submit_bio+1                                                                                                                      
    __block_write_full_page+505                                                                                                       
    __writepage+25                                                                                                                    
    write_cache_pages+387                                                                                                             
    generic_writepages+123                                                                                                            
    do_writepages+192                                                                                                                 
    filemap_fdatawrite_wbc+95                                                                                                         
    __filemap_fdatawrite_range+88                                                                                                     
    filemap_write_and_wait_range+51                                                                                                   
    blkdev_put+220                                                                                                                    
    blkdev_close+22                                                                                                                   
    __fput+145                                                                                                                        
    task_work_run+89                                                                                                                  
    exit_to_user_mode_prepare+440 
    syscall_exit_to_user_mode+23
    do_syscall_64+103
    entry_SYSCALL_64_after_hwframe+99
, ublkb0, write, bash, 1660]: 1
@submit_bio[
    submit_bio+1
    __bh_read+43
    __block_write_begin_int+1305
    block_write_begin+78
    generic_perform_write+208
    __generic_file_write_iter+209 
    blkdev_write_iter+273
    vfs_write+580
    ksys_write+107
    do_syscall_64+91
    entry_SYSCALL_64_after_hwframe+99
, ublkb0, read, bash, 1660]: 1

[ming1]

Yeah, the three read is for checking partition table:

(ultrix_partition, amiga_partition and adfspart_check_ICS).

[mememnt]

It is expected behavior, so just fine.

In my test vm, only efi_partition gets checked, so just one extra read.

OK got it!

And do you know what this read stands, for every time I'm writing something to ublkbN? As I showed in the second trace output in my previous message?

[ming1]

After you wrote something to disk, systemd/udev will be triggered to re-read partition table given the table may be changed.

[ming1]

This same behavior can be observed on any disk.

[mememnt]

I'm not sure that this is the reason we see a read and a write.
If you add a nsecs in @submit_bio[] you will see that the read operation is happening before the write. So I don't think that this has anything to do with systemd/udev reading the partition tables.

root@debian:~/bpftrace# bpftrace submit_bio.bt ublk 4                                                                                                                              
Attaching 1 probe...                                                                                                                                                                          
^C                                                                                                                                                                                            

@submit_bio[
    submit_bio+1
    __bh_read+43
    __block_write_begin_int+1305
    block_write_begin+78
    generic_perform_write+208
    __generic_file_write_iter+209
    blkdev_write_iter+273
    vfs_write+580
    ksys_write+107
    do_syscall_64+91
    entry_SYSCALL_64_after_hwframe+99
, ublkb0, read, bash, 5215, 17206244201]: 1
@submit_bio[
    submit_bio+1
    __block_write_full_page+505
    __writepage+25
    write_cache_pages+387
    generic_writepages+123
    do_writepages+192
    filemap_fdatawrite_wbc+95
    __filemap_fdatawrite_range+88
    filemap_write_and_wait_range+51
    blkdev_put+220
    blkdev_close+22
    __fput+145
    task_work_run+89
    exit_to_user_mode_prepare+440
    syscall_exit_to_user_mode+23
    do_syscall_64+103
    entry_SYSCALL_64_after_hwframe+99
, ublkb0, write, bash, 5215, 17206244958]: 1

Write => 17206244958, read => 17206244201.

My take is this read has something to do with the page cache. Maybe it fetches blocks from disk to the cache, then writes to them and then it flashes the page to the disk, so we are seeing the write.

[ming1]

yeah, the read is part of read-modify-write, since the minimized unit of block
write/read is sector. When you write data which size is less than one sector,
data in this sector has to be read to buffer first.