Linux IO stack on 5.15 kernel

 
Let see how the Linux IO stack looks on 5.15 kernel.  For this depiction I have use Ubuntu 22.04 desktop with 5.15 kernel

=======================
Lets make a filesystem. 
=======================
root@kundan-virtual-machine:~# mkfs.ext4 /dev/sdb
mke2fs 1.46.5 (30-Dec-2021)
Creating filesystem with 786432 4k blocks and 196608 inodes
Filesystem UUID: d9682545-5aee-44db-ae0d-88514de3bf12
Superblock backups stored on blocks:
        32768, 98304, 163840, 229376, 294912
Allocating group tables: done
Writing inode tables: done
Creating journal (16384 blocks): done
Writing superblocks and filesystem accounting information: done

================
Mount the device 
================
root@kundan-virtual-machine:~# mount /dev/sdb mnt

===================================
Start a routine to issue IOs to the mounted device 
===================================

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
int main()
{
        int fd, ret;
        char buf[20] = {'X','X','X','X','X','X','X','X','X','X','X','X','X','X','X','X','X','X','X','X'};
        fd = open("/mnt/a", O_RDWR|O_SYNC|O_APPEND|O_CREAT);
        write(fd, buf, 20);
        close(fd);
        return 0;
}


==================================
Start function trace and start IOs
==================================
cd /sys/kernel/debug/tracing
cat /dev/null >  trace
echo function > current_tracer
echo 1 > tracing_on
/root/c_prog/a.out 
/root/c_prog/a.out 
/root/c_prog/a.out
/root/c_prog/a.out
/root/c_prog/a.out
/root/c_prog/a.out 
echo 0 > tracing_on
cp trace ~/ext4_write_trace

===================================
Trace the flow from EXT4 write 
VFS     ext4_writepages  mpage_submit_page  ext4_io_submit blk_mq_submit_bio

          a.out-2819    [007] .....  3690.480070: vfs_fsync_range <-ext4_buffered_write_iter
           a.out-2819    [007] .....  3690.480070: ext4_sync_file <-vfs_fsync_range
           a.out-2819    [007] .....  3690.480071: file_write_and_wait_range <-ext4_sync_file
           a.out-2819    [007] .....  3690.480071: filemap_fdatawrite_wbc <-file_write_and_wait_range
           a.out-2819    [007] .....  3690.480071: _raw_spin_lock <-filemap_fdatawrite_wbc
           a.out-2819    [007] .....  3690.480071: wbc_attach_and_unlock_inode <-filemap_fdatawrite_wbc
           a.out-2819    [007] .....  3690.480071: rcu_read_unlock_strict <-wbc_attach_and_unlock_inode
           a.out-2819    [007] .....  3690.480072: do_writepages <-filemap_fdatawrite_wbc
           a.out-2819    [007] .....  3690.480072: ext4_writepages <-do_writepages
           a.out-2819    [007] .....  3690.480072: __cond_resched <-ext4_writepages
           a.out-2819    [007] .....  3690.480072: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480072: ext4_inode_journal_mode <-ext4_writepages
           a.out-2819    [007] .....  3690.480072: ext4_inode_journal_mode <-ext4_writepages
           a.out-2819    [007] .....  3690.480073: ext4_meta_trans_blocks <-ext4_writepages
           a.out-2819    [007] .....  3690.480073: ext4_ext_index_trans_blocks <-ext4_meta_trans_blocks
           a.out-2819    [007] .....  3690.480073: ext4_io_submit_init <-ext4_writepages
           a.out-2819    [007] .....  3690.480073: tag_pages_for_writeback <-ext4_writepages
           a.out-2819    [007] .....  3690.480073: _raw_spin_lock_irq <-tag_pages_for_writeback
           a.out-2819    [007] .....  3690.480074: blk_start_plug <-ext4_writepages
           a.out-2819    [007] .....  3690.480074: ext4_init_io_end <-ext4_writepages
           a.out-2819    [007] .....  3690.480074: kmem_cache_alloc <-ext4_init_io_end
           a.out-2819    [007] .....  3690.480074: __cond_resched <-kmem_cache_alloc
           a.out-2819    [007] .....  3690.480074: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480074: should_failslab <-kmem_cache_alloc
           a.out-2819    [007] .....  3690.480075: mpage_prepare_extent_to_map <-ext4_writepages
           a.out-2819    [007] .....  3690.480075: pagevec_lookup_range_tag <-mpage_prepare_extent_to_map
           a.out-2819    [007] .....  3690.480075: find_get_pages_range_tag <-pagevec_lookup_range_tag
           a.out-2819    [007] .....  3690.480075: rcu_read_unlock_strict <-find_get_pages_range_tag
           a.out-2819    [007] .....  3690.480075: __cond_resched <-mpage_prepare_extent_to_map
           a.out-2819    [007] .....  3690.480075: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480076: wait_on_page_writeback <-mpage_prepare_extent_to_map
           a.out-2819    [007] .....  3690.480076: mpage_process_page_bufs <-mpage_prepare_extent_to_map
           a.out-2819    [007] .....  3690.480076: mpage_submit_page <-mpage_process_page_bufs
           a.out-2819    [007] .....  3690.480076: clear_page_dirty_for_io <-mpage_submit_page
           a.out-2819    [007] .....  3690.480076: page_mapping <-clear_page_dirty_for_io
           a.out-2819    [007] .....  3690.480076: page_mkclean <-clear_page_dirty_for_io
           a.out-2819    [007] .....  3690.480077: page_mapped <-page_mkclean
           a.out-2819    [007] d....  3690.480077: __mod_lruvec_page_state <-mod_lruvec_page_state
           a.out-2819    [007] d....  3690.480077: __mod_lruvec_state <-__mod_lruvec_page_state
           a.out-2819    [007] d....  3690.480077: __mod_node_page_state <-__mod_lruvec_state
           a.out-2819    [007] d....  3690.480077: __mod_memcg_lruvec_state <-__mod_lruvec_state
           a.out-2819    [007] d....  3690.480077: cgroup_rstat_updated <-__mod_memcg_lruvec_state
           a.out-2819    [007] d....  3690.480077: _raw_spin_lock_irqsave <-cgroup_rstat_updated
           a.out-2819    [007] d....  3690.480078: _raw_spin_unlock_irqrestore <-cgroup_rstat_updated
           a.out-2819    [007] d....  3690.480078: rcu_read_unlock_strict <-__mod_lruvec_page_state
           a.out-2819    [007] .....  3690.480078: dec_zone_page_state <-clear_page_dirty_for_io
           a.out-2819    [007] .....  3690.480078: rcu_read_unlock_strict <-clear_page_dirty_for_io
           a.out-2819    [007] .....  3690.480078: ext4_bio_write_page <-mpage_submit_page
   
   a.out-2819    [007] .....  3690.480082: bio_alloc_bioset <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480082: mempool_alloc <-bio_alloc_bioset
           a.out-2819    [007] .....  3690.480082: __cond_resched <-mempool_alloc
           a.out-2819    [007] .....  3690.480082: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480082: mempool_alloc_slab <-mempool_alloc
           a.out-2819    [007] .....  3690.480082: kmem_cache_alloc <-mempool_alloc_slab
           a.out-2819    [007] .....  3690.480082: should_failslab <-kmem_cache_alloc
           a.out-2819    [007] .....  3690.480084: bvec_alloc <-bio_alloc_bioset
           a.out-2819    [007] .....  3690.480084: mempool_alloc <-bvec_alloc
           a.out-2819    [007] .....  3690.480084: __cond_resched <-mempool_alloc
           a.out-2819    [007] .....  3690.480084: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480084: mempool_alloc_slab <-mempool_alloc
           a.out-2819    [007] .....  3690.480084: kmem_cache_alloc <-mempool_alloc_slab
           a.out-2819    [007] .....  3690.480084: should_failslab <-kmem_cache_alloc
           a.out-2819    [007] .....  3690.480085: fscrypt_set_bio_crypt_ctx_bh <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480085: page_mapping <-fscrypt_set_bio_crypt_ctx_bh
           a.out-2819    [007] .....  3690.480086: fscrypt_set_bio_crypt_ctx <-fscrypt_set_bio_crypt_ctx_bh
           a.out-2819    [007] .....  3690.480086: bio_associate_blkg <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480086: kthread_blkcg <-bio_associate_blkg
           a.out-2819    [007] .....  3690.480086: bio_associate_blkg_from_css <-bio_associate_blkg
           a.out-2819    [007] .....  3690.480086: rcu_read_unlock_strict <-bio_associate_blkg_from_css
           a.out-2819    [007] .....  3690.480087: rcu_read_unlock_strict <-bio_associate_blkg
           a.out-2819    [007] .....  3690.480087: bio_associate_blkg_from_css <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480087: rcu_read_unlock_strict <-bio_associate_blkg_from_css
           a.out-2819    [007] .....  3690.480087: rcu_read_unlock_strict <-bio_associate_blkg_from_css
           a.out-2819    [007] .....  3690.480087: bio_add_page <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480087: __bio_try_merge_page <-bio_add_page
           a.out-2819    [007] .....  3690.480088: __bio_add_page <-bio_add_page
           a.out-2819    [007] .....  3690.480088: wbc_account_cgroup_owner <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480088: mem_cgroup_css_from_page <-wbc_account_cgroup_owner
           a.out-2819    [007] .....  3690.480088: unlock_page <-ext4_bio_write_page
           a.out-2819    [007] .....  3690.480088: __pagevec_release <-mpage_prepare_extent_to_map
           a.out-2819    [007] .....  3690.480088: lru_add_drain_cpu <-__pagevec_release
           a.out-2819    [007] .....  3690.480089: release_pages <-__pagevec_release
           a.out-2819    [007] .....  3690.480089: __mem_cgroup_uncharge_list <-release_pages
           a.out-2819    [007] .....  3690.480089: free_unref_page_list <-release_pages
           a.out-2819    [007] .....  3690.480089: mpage_release_unused_pages <-ext4_writepages
           a.out-2819    [007] .....  3690.480089: ext4_io_submit <-ext4_writepages
           a.out-2819    [007] .....  3690.480089: submit_bio <-ext4_io_submit
           a.out-2819    [007] .....  3690.480090: submit_bio_noacct <-submit_bio
           a.out-2819    [007] .....  3690.480090: __submit_bio <-submit_bio_noacct
           a.out-2819    [007] .....  3690.480090: blk_try_enter_queue <-__submit_bio
           a.out-2819    [007] .....  3690.480090: submit_bio_checks <-__submit_bio
           a.out-2819    [007] .....  3690.480091: __cond_resched <-submit_bio_checks
           a.out-2819    [007] .....  3690.480091: rcu_all_qs <-__cond_resched
           a.out-2819    [007] .....  3690.480091: should_fail_bio <-submit_bio_checks
           a.out-2819    [007] .....  3690.480091: bdev_read_only <-submit_bio_checks
           a.out-2819    [007] .....  3690.480091: create_task_io_context <-submit_bio_checks
           a.out-2819    [007] .....  3690.480091: kmem_cache_alloc_node <-create_task_io_context
           a.out-2819    [007] .....  3690.480092: should_failslab <-kmem_cache_alloc_node
           a.out-2819    [007] .....  3690.480092: _raw_spin_lock <-create_task_io_context
           a.out-2819    [007] .....  3690.480092: blk_throtl_bio <-submit_bio_checks
           a.out-2819    [007] .....  3690.480092: rcu_read_unlock_strict <-blk_throtl_bio
           a.out-2819    [007] .....  3690.480093: blk_cgroup_bio_start <-submit_bio_checks
           a.out-2819    [007] .....  3690.480093: cgroup_rstat_updated <-blk_cgroup_bio_start
           a.out-2819    [007] .....  3690.480093: ktime_get <-submit_bio_checks
           a.out-2819    [007] .....  3690.480093: blk_mq_submit_bio <-__submit_bio
           a.out-2819    [007] .....  3690.480093: __blk_queue_split <-blk_mq_submit_bio
           a.out-2819    [007] .....  3690.480094: bio_integrity_prep <-blk_mq_submit_bio
           a.out-2819    [007] .....  3690.480094: blk_attempt_plug_merge <-blk_mq_submit_bio
           a.out-2819    [007] .....  3690.480094: __blk_mq_sched_bio_merge <-blk_mq_submit_bio
           a.out-2819    [007] .....  3690.480094: dd_bio_merge <-__blk_mq_sched_bio_merge
           a.out-2819    [007] .....  3690.480094: _raw_spin_lock <-dd_bio_merge
           a.out-2819    [007] .....  3690.480095: blk_mq_sched_try_merge <-dd_bio_merge
           a.out-2819    [007] .....  3690.480095: elv_merge <-blk_mq_sched_try_merge    
   

===================================
blk-mq      elevator   scsi_queue_rq  HBA_queue_command 

===================================

           <...>-1942    [001] .....  2244.221069: blk_finish_plug <-wb_writeback
           <...>-1942    [001] .....  2244.221069: blk_flush_plug_list <-blk_finish_plug
           <...>-1942    [001] .....  2244.221069: blk_mq_flush_plug_list <-blk_flush_plug_list
           <...>-1942    [001] .....  2244.221069: blk_mq_sched_insert_requests <-blk_mq_flush_plug_list
           <...>-1942    [001] .....  2244.221069: rcu_read_unlock_strict <-blk_mq_sched_insert_requests
           <...>-1942    [001] .....  2244.221070: dd_insert_requests <-blk_mq_sched_insert_requests
           <...>-1942    [001] .....  2244.221070: _raw_spin_lock <-dd_insert_requests
           <...>-1942    [001] .....  2244.221070: dd_insert_request <-dd_insert_requests
           <...>-1942    [001] .....  2244.221070: blk_mq_sched_try_insert_merge <-dd_insert_request
           <...>-1942    [001] .....  2244.221070: elv_attempt_insert_merge <-blk_mq_sched_try_insert_merge
           <...>-1942    [001] .....  2244.221070: elv_rqhash_find <-elv_attempt_insert_merge
           <...>-1942    [001] .....  2244.221071: elv_rb_add <-dd_insert_request
           <...>-1942    [001] .....  2244.221071: elv_rqhash_add <-dd_insert_request
           <...>-1942    [001] .....  2244.221071: dd_insert_request <-dd_insert_requests
           <...>-1942    [001] .....  2244.221071: blk_mq_sched_try_insert_merge <-dd_insert_request
           <...>-1942    [001] .....  2244.221071: elv_attempt_insert_merge <-blk_mq_sched_try_insert_merge
           <...>-1942    [001] .....  2244.221071: blk_attempt_req_merge <-elv_attempt_insert_merge
           <...>-1942    [001] .....  2244.221072: attempt_merge.part.0 <-blk_attempt_req_merge
           <...>-1942    [001] .....  2244.221072: elv_rqhash_find <-elv_attempt_insert_merge
           <...>-1942    [001] .....  2244.221072: elv_rb_add <-dd_insert_request
           <...>-1942    [001] .....  2244.221072: elv_rqhash_add <-dd_insert_request
           <...>-1942    [001] .....  2244.221072: blk_mq_run_hw_queue <-blk_mq_sched_insert_requests
           <...>-1942    [001] .....  2244.221072: dd_has_work <-blk_mq_run_hw_queue
           <...>-1942    [001] .....  2244.221073: rcu_read_unlock_strict <-blk_mq_run_hw_queue
           <...>-1942    [001] .....  2244.221073: __blk_mq_delay_run_hw_queue <-blk_mq_run_hw_queue
           <...>-1942    [001] .....  2244.221073: __blk_mq_run_hw_queue <-__blk_mq_delay_run_hw_queue
           <...>-1942    [001] .....  2244.221073: blk_mq_sched_dispatch_requests <-__blk_mq_run_hw_queue
           <...>-1942    [001] .....  2244.221073: __blk_mq_sched_dispatch_requests <-blk_mq_sched_dispatch_requests
           <...>-1942    [001] .....  2244.221074: blk_mq_do_dispatch_sched <-__blk_mq_sched_dispatch_requests
           <...>-1942    [001] .....  2244.221074: __blk_mq_do_dispatch_sched <-blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221074: dd_has_work <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221074: scsi_mq_get_budget <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221075: dd_dispatch_request <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221075: _raw_spin_lock <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221075: __dd_dispatch_request <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221075: deadline_next_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221076: __dd_dispatch_request <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221076: deadline_next_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221076: deadline_next_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221076: deadline_remove_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221076: elv_rb_del <-deadline_remove_request
           <...>-1942    [001] .....  2244.221076: elv_rqhash_del <-deadline_remove_request
           <...>-1942    [001] .....  2244.221077: blk_req_needs_zone_write_lock <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221077: scsi_mq_set_rq_budget_token <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221077: blk_mq_get_driver_tag <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221077: __blk_mq_tag_busy <-blk_mq_get_driver_tag
           <...>-1942    [001] .....  2244.221077: dd_has_work <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221078: scsi_mq_get_budget <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221078: dd_dispatch_request <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221078: _raw_spin_lock <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221078: __dd_dispatch_request <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221078: deadline_next_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221078: __dd_dispatch_request <-dd_dispatch_request
           <...>-1942    [001] .....  2244.221078: deadline_next_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221079: deadline_remove_request <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221079: elv_rb_del <-deadline_remove_request
           <...>-1942    [001] .....  2244.221079: elv_rqhash_del <-deadline_remove_request
           <...>-1942    [001] .....  2244.221079: blk_req_needs_zone_write_lock <-__dd_dispatch_request
           <...>-1942    [001] .....  2244.221079: scsi_mq_set_rq_budget_token <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221079: blk_mq_get_driver_tag <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221080: __blk_mq_tag_busy <-blk_mq_get_driver_tag
           <...>-1942    [001] .....  2244.221080: dd_has_work <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221080: blk_mq_dispatch_rq_list <-__blk_mq_do_dispatch_sched
           <...>-1942    [001] .....  2244.221080: blk_mq_get_driver_tag <-blk_mq_dispatch_rq_list
           <...>-1942    [001] .....  2244.221080: blk_mq_get_driver_tag <-blk_mq_dispatch_rq_list
           <...>-1942    [001] .....  2244.221080: scsi_queue_rq <-blk_mq_dispatch_rq_list
           <...>-1942    [001] .....  2244.221081: scsi_prepare_cmd <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221081: scsi_init_command <-scsi_prepare_cmd
           <...>-1942    [001] .....  2244.221081: init_timer_key <-scsi_init_command
           <...>-1942    [001] .....  2244.221082: sd_init_command <-scsi_prepare_cmd
           <...>-1942    [001] .....  2244.221082: sd_setup_read_write_cmnd <-sd_init_command
           <...>-1942    [001] .....  2244.221082: scsi_alloc_sgtables <-sd_setup_read_write_cmnd
           <...>-1942    [001] .....  2244.221082: __blk_rq_map_sg <-scsi_alloc_sgtables
           <...>-1942    [001] .....  2244.221082: __blk_bios_map_sg <-__blk_rq_map_sg
           <...>-1942    [001] .....  2244.221083: blk_mq_start_request <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221083: ktime_get <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221084: __rq_qos_issue <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221084: wbt_issue <-__rq_qos_issue
           <...>-1942    [001] .....  2244.221084: blk_add_timer <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221084: scsi_dispatch_cmd <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221084: scsi_log_send <-scsi_dispatch_cmd
           <...>-1942    [001] .....  2244.221085: pvscsi_queue <-scsi_dispatch_cmd
           <...>-1942    [001] .....  2244.221085: _raw_spin_lock_irqsave <-pvscsi_queue
           <...>-1942    [001] d....  2244.221085: _raw_spin_lock_irqsave <-pvscsi_queue
           <...>-1942    [001] d....  2244.221085: pvscsi_queue_ring <-pvscsi_queue
           <...>-1942    [001] d....  2244.221086: is_vmalloc_addr <-pvscsi_queue_ring
           <...>-1942    [001] d....  2244.221086: dma_map_page_attrs <-pvscsi_queue_ring
           <...>-1942    [001] d....  2244.221086: scsi_dma_map <-pvscsi_queue_ring
           <...>-1942    [001] d....  2244.221086: dma_map_sg_attrs <-scsi_dma_map
           <...>-1942    [001] d....  2244.221086: __dma_map_sg_attrs <-dma_map_sg_attrs
           <...>-1942    [001] d....  2244.221086: dma_direct_map_sg <-__dma_map_sg_attrs
           <...>-1942    [001] d....  2244.221087: _raw_spin_unlock_irqrestore <-pvscsi_queue
           <...>-1942    [001] d....  2244.221098: _raw_spin_unlock_irqrestore <-pvscsi_queue
           <...>-1942    [001] .....  2244.221098: blk_mq_get_driver_tag <-blk_mq_dispatch_rq_list
           <...>-1942    [001] .....  2244.221099: scsi_queue_rq <-blk_mq_dispatch_rq_list
           <...>-1942    [001] .....  2244.221099: scsi_prepare_cmd <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221099: scsi_init_command <-scsi_prepare_cmd
           <...>-1942    [001] .....  2244.221099: init_timer_key <-scsi_init_command
           <...>-1942    [001] .....  2244.221099: sd_init_command <-scsi_prepare_cmd
           <...>-1942    [001] .....  2244.221100: sd_setup_read_write_cmnd <-sd_init_command
           <...>-1942    [001] .....  2244.221100: scsi_alloc_sgtables <-sd_setup_read_write_cmnd
           <...>-1942    [001] .....  2244.221100: __blk_rq_map_sg <-scsi_alloc_sgtables
           <...>-1942    [001] .....  2244.221100: __blk_bios_map_sg <-__blk_rq_map_sg
           <...>-1942    [001] .....  2244.221100: blk_mq_start_request <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221100: ktime_get <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221101: __rq_qos_issue <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221101: wbt_issue <-__rq_qos_issue
           <...>-1942    [001] .....  2244.221101: blk_add_timer <-blk_mq_start_request
           <...>-1942    [001] .....  2244.221101: scsi_dispatch_cmd <-scsi_queue_rq
           <...>-1942    [001] .....  2244.221101: scsi_log_send <-scsi_dispatch_cmd
           <...>-1942    [001] .....  2244.221101: pvscsi_queue <-scsi_dispatch_cmd
           <...>-1942    [001] .....  2244.221101: _raw_spin_lock_irqsave <-pvscsi_queue
           <...>-1942    [001] d....  2244.221102: _raw_spin_lock_irqsave <-pvscsi_queue
           <...>-1942    [001] d....  2244.221102: pvscsi_queue_ring <-pvscsi_queue




IO completion from  __do_soft_irq to ext4_end_bio
          <idle>-0       [001] d....  2245.526197: __do_softirq <-irq_exit_rcu
          <idle>-0       [007] dN...  2245.526197: calc_load_nohz_stop <-tick_nohz_idle_exit
          <idle>-0       [001] ..s..  2245.526197: blk_done_softirq <-__do_softirq
          <idle>-0       [001] ..s..  2245.526198: blk_complete_reqs <-blk_done_softirq
          <idle>-0       [007] dN...  2245.526198: tick_nohz_restart <-tick_nohz_idle_exit
          <idle>-0       [007] dN...  2245.526198: hrtimer_cancel <-tick_nohz_restart
          <idle>-0       [007] dN...  2245.526198: hrtimer_active <-hrtimer_cancel
          <idle>-0       [001] ..s..  2245.526198: scsi_complete <-blk_complete_reqs
          <idle>-0       [007] dN...  2245.526198: hrtimer_try_to_cancel.part.0 <-hrtimer_cancel
          <idle>-0       [001] ..s..  2245.526198: scsi_decide_disposition <-scsi_complete
          <idle>-0       [007] dN...  2245.526198: _raw_spin_lock_irqsave <-hrtimer_try_to_cancel.part.0
          <idle>-0       [007] dN...  2245.526198: __remove_hrtimer <-hrtimer_try_to_cancel.part.0
          <idle>-0       [001] ..s..  2245.526198: scsi_handle_queue_ramp_up <-scsi_decide_disposition
          <idle>-0       [007] dN...  2245.526198: hrtimer_update_next_event <-__remove_hrtimer
          <idle>-0       [001] ..s..  2245.526198: scsi_log_completion <-scsi_complete
          <idle>-0       [007] dN...  2245.526199: __hrtimer_next_event_base <-hrtimer_update_next_event
          <idle>-0       [001] ..s..  2245.526199: scsi_finish_command <-scsi_complete
          <idle>-0       [007] dN...  2245.526199: __hrtimer_next_event_base <-hrtimer_update_next_event
          <idle>-0       [001] ..s..  2245.526199: scsi_device_unbusy <-scsi_finish_command
          <idle>-0       [001] ..s..  2245.526199: scsi_dec_host_busy <-scsi_device_unbusy
          <idle>-0       [007] dN...  2245.526199: tick_program_event <-__remove_hrtimer
          <idle>-0       [007] dN...  2245.526199: clockevents_program_event <-tick_program_event
          <idle>-0       [001] ..s..  2245.526199: rcu_read_unlock_strict <-scsi_dec_host_busy
          <idle>-0       [007] dN...  2245.526199: ktime_get <-clockevents_program_event
          <idle>-0       [001] ..s..  2245.526199: sd_done <-scsi_finish_command
          <idle>-0       [007] dN...  2245.526199: lapic_next_deadline <-clockevents_program_event
          <idle>-0       [001] ..s..  2245.526199: scsi_io_completion <-scsi_finish_command
          <idle>-0       [001] ..s..  2245.526200: scsi_end_request <-scsi_io_completion
          <idle>-0       [001] ..s..  2245.526200: blk_update_request <-scsi_end_request
          <idle>-0       [001] ..s..  2245.526200: bio_advance <-blk_update_request
          <idle>-0       [001] ..s..  2245.526200: bio_endio <-blk_update_request
          <idle>-0       [001] ..s..  2245.526201: __rq_qos_done_bio <-bio_endio
          <idle>-0       [007] dN...  2245.526201: _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel.part.0
          <idle>-0       [001] ..s..  2245.526201: bio_uninit <-bio_endio
          <idle>-0       [007] dN...  2245.526201: hrtimer_forward <-tick_nohz_restart
          <idle>-0       [001] ..s..  2245.526201: rcu_read_unlock_strict <-bio_uninit
          <idle>-0       [007] dN...  2245.526201: hrtimer_start_range_ns <-tick_nohz_restart
          <idle>-0       [001] ..s..  2245.526201: ext4_end_bio <-bio_endio

Linux fiemap internals

In this blog lets look and try to find the physical blocks of a file. Given a struct inode * of a file.

Every file has a inode. There is a on disk inode and one struct inode. The disk inode is stored in the disk, so across reboots it holds the information of a file whereabouts and details in the disk. 

On disk file inode has different layout for various filesystems: 

If we see the ext4.h, it looks like this :

/*

 * Structure of an inode on the disk

 */

struct ext4_inode {

..

..

};

This has mapping from file blocks to disk blocks.

For every filesystem, we can call an IOCTL and get the filemaps. 

A C program to call this IOCTL is mentioned here :

https://github.com/shekkbuilder/fiemap/blob/master/fiemap.c

User space C code looks like : 

/* Find out how many extents there are */

if (ioctl(fd, FS_IOC_FIEMAP, fiemap) < 0) {

fprintf(stderr, "fiemap ioctl() failed\n");

return NULL;

}

..

..

if (ioctl(fd, FS_IOC_FIEMAP, fiemap) < 0) {

fprintf(stderr, "fiemap ioctl() failed\n");

return NULL;

}

Kernel ioctl called for these is : 

static int ioctl_fiemap(struct file *filp, struct fiemap __user *ufiemap)

{  

..

error = inode->i_op->fiemap(inode, &fieinfo, fiemap.fm_start,

fiemap.fm_length);

..

}

This will call inode specific fiemap : 

For ext4 it is :

int ext4_fiemap(struct inode *inode, struct fiemap_extent_info *fieinfo,

u64 start, u64 len)

{

int error = 0;

For BTRFS is is :

static int btrfs_fiemap(struct inode *inode, struct fiemap_extent_info *fieinfo,

__u64 start, __u64 len)

{

For XFS it is :

STATIC int

xfs_vn_fiemap(

struct inode *inode,

struct fiemap_extent_info *fieinfo,

u64 start,

u64 length)

{

Kernel documentation talks about the fiemap here :

Documentation\filesystems\fiemap.rst

So can we print the filemap from kernel. Answers is yes, we can do it by calling inode fiemap function from kernel.

Lets look at the implementation which fetches this info from kernel : 

u64 traverse_extent(struct inode *inode)

{

        int n = 0;

        u64 sector_num = 0;

    if (inode->i_op->fiemap)

    {

        printk("traverse_extent fiemap present = %llx\n", inode->i_op->fiemap);

        struct fiemap fiemap;

        fiemap.fm_start = 0;

        fiemap.fm_extent_count = 1;

        struct fiemap_extent_info fieinfo = { 0, };

        struct fiemap_extent *ext1 = kmalloc(sizeof(struct fiemap_extent), GFP_KERNEL);

        memset(ext1, 0, sizeof(struct fiemap_extent));

        fieinfo.fi_extents_start = ext1;

        fieinfo.fi_extents_max = 1;

        u64 len = 4096;

        int ret = inode->i_op->fiemap(inode, &fieinfo, fiemap.fm_start, len);

        if(fieinfo.fi_extents_start)

        {

                printk("after dest logical = %llu\n", fieinfo.fi_extents_start->fe_logical);

                printk("after dest physical = %llu\n", fieinfo.fi_extents_start->fe_physical);

                if(fieinfo.fi_extents_start->fe_physical)

                        sector_num = fieinfo.fi_extents_start->fe_physical/512;

        }

        kfree(ext1);

    }

Very loosely written code, but if spent time it can be modified. 

Happy Hacking 😉😉

Linux libaio example and ftrace

LIBAIO

Lets see sample program which uses libaio and delve into the IO path for the same. 

#include <linux/aio_abi.h>
#include <sys/syscall.h>
#include <linux/aio_abi.h>
#include <errno.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <inttypes.h>
#include <assert.h>
typedef unsigned long uintptr_t;
int fd = 0;
int fd1 = 0;
// first operation
char buff1[512];
struct iocb iocb1    = {0};

// second operation
char buff2[512];
struct iocb iocb2    = {0};
aio_context_t ioctx = 0;
unsigned maxevents = 128;

// syscall wrappers
static inline int
io_setup(unsigned maxevents, aio_context_t *ctx) {
    return syscall(SYS_io_setup, maxevents, ctx);
}

static inline int
io_submit(aio_context_t ctx, long nr, struct iocb **iocbpp) {
    return syscall(SYS_io_submit, ctx, nr, iocbpp);
}

static inline int
io_getevents(aio_context_t ctx, long min_nr, long nr,
                 struct io_event *events, struct timespec *timeout) {
    return syscall(SYS_io_getevents, ctx, min_nr, nr, events, timeout);
}

static inline int
io_destroy(aio_context_t ctx)
{
    return syscall(SYS_io_destroy, ctx);
}

void fill_iocb_1(int local_fd)
{
iocb1.aio_data       = 0xbeef; // will be returned in completion
iocb1.aio_fildes     = local_fd;
iocb1.aio_lio_opcode = IOCB_CMD_PREAD;
iocb1.aio_reqprio    = 0;
iocb1.aio_buf        = (uintptr_t)buff1;
iocb1.aio_nbytes     = sizeof(buff1);
iocb1.aio_offset     = 0;      // read file at offset 0
}

void fill_iocb_2(int local_fd)
{
iocb2.aio_data       = 0xbaba; // will be returned in completion
iocb2.aio_fildes     = local_fd;
iocb2.aio_lio_opcode = IOCB_CMD_PREAD;
iocb2.aio_reqprio    = 0;
iocb2.aio_buf        = (uintptr_t)buff2;
iocb2.aio_nbytes     = sizeof(buff2);
iocb2.aio_offset     = 4096;   // read file at offset 4096 (bytes)
}

int main()
{
struct iocb *iocb_ptrs[2] = { &iocb1, &iocb2 };
size_t nevents = 2;
struct io_event events[nevents];
int ret = 0;
nevents = 2;
fd = open("/root/test", O_RDWR|O_DIRECT);
if(fd < 0)
{
perror("file open");
exit(1);
}
ioctx = 0;
if (io_setup(maxevents, &ioctx) < 0) {
perror("io_setup");
exit(1);
}
else {
printf("io_setup is successsful\n");
}
fill_iocb_1(fd);
fill_iocb_2(fd);
// submit operations
ret = io_submit(ioctx, 2, iocb_ptrs);
if (ret < 0) {
perror("io_submit");
exit(1);
} else if (ret != 2) {
perror("io_submit: unhandled partial success");
exit(1);
}
ret = io_getevents(ioctx, 1 /* min */, nevents, events, NULL);
if (ret < 0) {
perror("io_getevents");
exit(1);
}
printf("Got %d events\n", ret);
for (size_t i=0; i<ret; i++) {
struct io_event *ev = &events[i];
assert(ev->data == 0xbeef || ev->data == 0xbaba);
printf("Event returned with res=%lld res2=%lld\n", ev->res, ev->res2);
nevents--;
if (ev->res < 0 ){
printf("Error \n");
}
if(i == 0)
{
printf("Data = \n");
for (int j = 0; j < 512; j++)
printf("%d\n", buff1[j]);
printf("\n");
}
}
io_destroy(ioctx);
close(fd);
return 0;
}

Lets ftrace the io_submit and io_getevents functions : 
cd /sys/kernel/debug/tracing
cat /dev/null >  trace
echo __x64_sys_io_submit > set_graph_function
echo 10 > max_graph_depth
echo function_graph > current_tracer
echo 1 > tracing_on

/root/libaio/./a.out  

cp trace ~/io_submit_dio_trace_depth_10_2
echo 0 > tracing_on
echo > set_graph_function
echo 0 > max_graph_depth
cat /dev/null >  trace

libaio and O_DIRECT
https://stackoverflow.com/questions/34235892/should-libaio-engine-to-be-used-with-unbuffered-io-directonly

Compilation : 
gcc -D_GNU_SOURCE my_aio.c


# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 11)               |  __x64_sys_io_submit() {
 11)               |    lookup_ioctx() {
 11)               |      do_page_fault() {
 11)               |        __do_page_fault() {
 11)   0.307 us    |          down_read_trylock();
 11)               |          find_vma() {
 11)   0.433 us    |            vmacache_find();
 11)   0.270 us    |            vmacache_update();
 11)   1.626 us    |          }
 11)               |          handle_mm_fault() {
 11)   0.319 us    |            mem_cgroup_from_task();
 11)   0.264 us    |            __count_memcg_events();
 11)               |            __handle_mm_fault() {
 11)   0.330 us    |              pmd_devmap_trans_unstable();
 11)               |              do_fault() {
 11)               |                filemap_map_pages() {
 11)               |                  alloc_set_pte() {
 11)   0.322 us    |                    pmd_devmap_trans_unstable();
 11)   0.332 us    |                    _raw_spin_lock();
 11)   1.027 us    |                    page_add_file_rmap();
 11)   3.002 us    |                  }
 11)   0.346 us    |                  unlock_page();
 11)               |                  alloc_set_pte() {
 11)   0.801 us    |                    page_add_file_rmap();
 11)   1.358 us    |                  }
 11)   0.282 us    |                  unlock_page();
 11)               |                  alloc_set_pte() {
 11)   0.791 us    |                    page_add_file_rmap();
 11)   1.336 us    |                  }
 11)   0.270 us    |                  unlock_page();
 11)   8.944 us    |                }
 11)   9.706 us    |              }
 11) + 11.120 us   |            }
 11) + 12.799 us   |          }
 11)   0.266 us    |          up_read();
 11) + 17.076 us   |        }
 11) + 17.596 us   |      }
 11) + 19.061 us   |    }
 11)               |    io_submit_one() {
 11)               |      kmem_cache_alloc() {
 11)   0.358 us    |        should_failslab();
 11)   0.960 us    |      }
 11)   0.334 us    |      __get_reqs_available();
 11)               |      fget() {
 11)   0.300 us    |        __fget();
 11)   0.953 us    |      }
 11)               |      aio_read() {
 11)   0.755 us    |        aio_prep_rw();
 11)   0.545 us    |        aio_setup_rw();
 11)               |        rw_verify_area() {
 11)               |          security_file_permission() {
 11)               |            apparmor_file_permission() {
 11)               |              common_file_perm() {
 11)   0.285 us    |                aa_file_perm();
 11)   0.866 us    |              }
 11)   1.408 us    |            }
 11)   0.292 us    |            __fsnotify_parent();
 11)   0.319 us    |            fsnotify();
 11)   3.108 us    |          }
 11)   3.707 us    |        }
 11)               |        generic_file_read_iter() {
 11)               |          filemap_write_and_wait_range() {
 11)   0.392 us    |            __filemap_fdatawrite_range();
 11)               |            __filemap_fdatawait_range() {
 11)               |              pagevec_lookup_range_tag() {
 11)   0.760 us    |                find_get_pages_range_tag();
 11)   1.475 us    |              }
 11)   2.040 us    |            }
 11)   0.313 us    |            filemap_check_errors();
 11)   4.029 us    |          }
 11)               |          touch_atime() {
 11)               |            atime_needs_update() {
 11)               |              current_time() {
 11)   0.263 us    |                ktime_get_coarse_real_ts64();
 11)   0.266 us    |                timespec64_trunc();
 11)   1.393 us    |              }
 11)   1.980 us    |            }
 11)   2.514 us    |          }
 11)   0.690 us    |          btrfs_direct_IO [btrfs]();
 11)               |          _cond_resched() {
 11)   0.335 us    |            rcu_all_qs();
 11)   0.859 us    |          }
 11)               |          pagecache_get_page() {
 11)   0.574 us    |            find_get_entry();
 11)   2.355 us    |          }
 11)   0.340 us    |          mark_page_accessed();
 11)               |          touch_atime() {
 11)               |            atime_needs_update() {
 11)               |              current_time() {
 11)   0.268 us    |                ktime_get_coarse_real_ts64();
 11)   0.268 us    |                timespec64_trunc();
 11)   1.318 us    |              }
 11)   1.876 us    |            }
 11)   2.436 us    |          }
 11) + 17.043 us   |        }
 11)   0.429 us    |        aio_complete_rw();
 11)   0.295 us    |        kfree();
 11) + 25.152 us   |      }
 11)   0.276 us    |      _raw_spin_lock_irqsave();
 11)   0.274 us    |      _raw_spin_unlock_irqrestore();
 11)               |      fput() {
 11)   0.287 us    |        fput_many();
 11)   0.786 us    |      }
 11)   0.547 us    |      kmem_cache_free();
 11) + 32.749 us   |    }
 11)               |    io_submit_one() {
 11)               |      kmem_cache_alloc() {
 11)   0.266 us    |        should_failslab();
 11)   0.799 us    |      }
 11)   0.296 us    |      __get_reqs_available();
 11)               |      fget() {
 11)   0.328 us    |        __fget();
 11)   0.823 us    |      }
 11)               |      aio_read() {
 11)   0.366 us    |        aio_prep_rw();
 11)   0.294 us    |        aio_setup_rw();
 11)               |        rw_verify_area() {
 11)               |          security_file_permission() {
 11)               |            apparmor_file_permission() {
 11)               |              common_file_perm() {
 11)   0.330 us    |                aa_file_perm();
 11)   0.859 us    |              }
 11)   1.359 us    |            }
 11)   0.276 us    |            __fsnotify_parent();
 11)   0.285 us    |            fsnotify();
 11)   3.073 us    |          }
 11)   3.628 us    |        }
 11)               |        generic_file_read_iter() {
 11)               |          filemap_write_and_wait_range() {
 11)   0.281 us    |            __filemap_fdatawrite_range();
 11)               |            __filemap_fdatawait_range() {
 11)               |              pagevec_lookup_range_tag() {
 11)   0.401 us    |                find_get_pages_range_tag();
 11)   0.909 us    |              }
 11)   1.440 us    |            }
 11)   0.273 us    |            filemap_check_errors();
 11)   3.073 us    |          }
 11)               |          touch_atime() {
 11)               |            atime_needs_update() {
 11)               |              current_time() {
 11)   0.268 us    |                ktime_get_coarse_real_ts64();
 11)   0.268 us    |                timespec64_trunc();
 11)   1.388 us    |              }
 11)   1.974 us    |            }
 11)   2.546 us    |          }
 11)   0.311 us    |          btrfs_direct_IO [btrfs]();
 11)   7.110 us    |        }
 11)   0.344 us    |        aio_complete_rw();
 11)   0.308 us    |        kfree();
 11) + 14.100 us   |      }
 11)   0.322 us    |      _raw_spin_lock_irqsave();
 11)   0.304 us    |      refill_reqs_available();
 11)   0.344 us    |      _raw_spin_unlock_irqrestore();
 11)               |      fput() {
 11)   0.265 us    |        fput_many();
 11)   0.804 us    |      }
 11)   0.293 us    |      kmem_cache_free();
 11) + 21.363 us   |    }
 11) + 76.921 us   |  }

Linux io_uring example and internals

Linux io_uring basics and details can be fetched from here https://kernel.dk/io_uring.pdf. Reader is encouraged to complete this document first. 

Also various examples of io_uring are mentioned here:
https://github.com/shuveb/io_uring-by-example   

I am using 5.3.18-22 kernel in this blog. 

Lets see the program to do read of twenty(20) 512bytes blocks from a block device.

#include <stdio.h>
#include <stdlib.h>
#include <sys/stat.h>
#include <sys/ioctl.h>
#include <sys/syscall.h>
#include <sys/mman.h>
#include <sys/uio.h>
#include <linux/fs.h>

#include <fcntl.h>
#include <unistd.h>
#include <string.h>
/* If your compilation fails because the header file below is missing,
 * your kernel is probably too old to support io_uring.

 * */
#include <linux/io_uring.h>

#define QUEUE_DEPTH 1
#define BLOCK_SZ    512

/* This is x86 specific */
#define read_barrier()  __asm__ __volatile__("":::"memory")
#define write_barrier() __asm__ __volatile__("":::"memory")

struct app_io_sq_ring {
    unsigned *head;
    unsigned *tail;
    unsigned *ring_mask;
    unsigned *ring_entries;
    unsigned *flags;
    unsigned *array;
};

struct app_io_cq_ring {
    unsigned *head;
    unsigned *tail;
    unsigned *ring_mask;
    unsigned *ring_entries;
    struct io_uring_cqe *cqes;
};

struct submitter {
    int ring_fd;
    struct app_io_sq_ring sq_ring;
    struct io_uring_sqe *sqes;
    struct app_io_cq_ring cq_ring;
};

int io_uring_setup(unsigned entries, struct io_uring_params *p)
{
    return (int) syscall(__NR_io_uring_setup, entries, p);
}

int io_uring_enter(int ring_fd, unsigned int to_submit,
                          unsigned int min_complete, unsigned int flags)
{
    return (int) syscall(__NR_io_uring_enter, ring_fd, to_submit, min_complete,
                   flags, NULL, 0);
}

struct io_info {
    int num_io;
    struct iovec iovecs[];
};

struct file_info {
    off_t file_sz;
    struct iovec iovecs[];      /* Referred by readv/writev */
};

int submit_to_sq(char *file_path, struct submitter *s) {
    struct io_info *ii;
    struct stat st;

    int file_fd = open(file_path, O_RDONLY);
    if (file_fd < 0 ) {
        perror("open");
        return 1;
    }

    struct app_io_sq_ring *sring = &s->sq_ring;
    unsigned index = 0, tail = 0, next_tail = 0;
    off_t file_sz = 0;

    // fetch the block device size

    if(fstat(file_fd, &st) < 0) {
        perror("fstat");
        return -1;
    }

    if (S_ISBLK(st.st_mode)) {
        unsigned long long bytes;
        if (ioctl(file_fd, BLKGETSIZE64, &bytes) != 0) {
            perror("ioctl");
            return -1;
        }
        file_sz =  bytes;
    } else if (S_ISREG(st.st_mode))
        file_sz =  st.st_size;

    printf("sz = %llu\n", file_sz);

    if (file_sz < 0)
        return 1;

    //Lets submit IO to read first 20 blocks
    struct iovec *iovecs;//[20];
    ii = malloc(sizeof(*ii) + sizeof(struct iovec) * 20);
    memset (ii, 0, sizeof(*ii) + (sizeof(struct iovec) * 20));

    iovecs = ii->iovecs;
    ii->num_io = 20;

    for (int i = 0;i < 20;i++)
    {
        iovecs[i].iov_len = 512;

        void *buf;
        if( posix_memalign(&buf, BLOCK_SZ, BLOCK_SZ)) {
            perror("posix_memalign");
            return 1;
        }

        iovecs[i].iov_base = buf;
    }
    /* Add our submission queue entry to the tail of the SQE ring buffer */

    next_tail = tail = *sring->tail;
    read_barrier();
    index = tail & *s->sq_ring.ring_mask;

    next_tail++;

    struct io_uring_sqe *sqe = &s->sqes[index];
    sqe->fd = file_fd;
    sqe->flags = 0;
    sqe->opcode = IORING_OP_READV;
    sqe->addr = (unsigned long) iovecs;
    sqe->len = 20;
    sqe->off = 0;
    sqe->user_data = (unsigned long long) ii;
    sring->array[index] = index;
    tail = next_tail;

    /* Update the tail so the kernel can see it. */
    if(*sring->tail != tail) {
        *sring->tail = tail;
        write_barrier();
    }

    int ret =  io_uring_enter(s->ring_fd, 1, 1,  IORING_ENTER_GETEVENTS);
    if(ret < 0) {
        perror("io_uring_enter");
        return 1;
    }
    return 0;
}

void read_from_cq(struct submitter *s) {
    struct iovec *iovecs;
    struct io_info *ii;
    struct app_io_cq_ring *cring = &s->cq_ring;
    struct io_uring_cqe *cqe;
    unsigned head, reaped = 0;
    head = *cring->head;
    do {
        read_barrier();
        /*
         * Remember, this is a ring buffer. If head == tail, it means that the
         * buffer is empty.
         * */
        if (head == *cring->tail)
            break;

        /* Get the entry */
        cqe = &cring->cqes[head & *s->cq_ring.ring_mask];
        ii = (struct io_info*) cqe->user_data;
        iovecs = ii->iovecs;
        if (cqe->res < 0)
            fprintf(stderr, "Error: %s\n", strerror(abs(cqe->res)));

        for (int i = 0; i < 20; i++)
        {
             printf("iov_base  = %p, iov_len = %d\n",
                 iovecs[i].iov_base, iovecs[i].iov_len);
             printf("%d, %d\n", *((char *)iovecs[i].iov_base) , *((char *)iovecs[i].iov_base + 1));

        }
        head++;
    } while (1);
    cring->head = head;
    write_barrier();
}

int app_setup_uring(struct submitter *s) {
struct app_io_sq_ring *sring = &s->sq_ring;
    struct app_io_cq_ring *cring = &s->cq_ring;
    struct io_uring_params p;
    void *sq_ptr, *cq_ptr;
    memset(&p, 0, sizeof(p));
    s->ring_fd = io_uring_setup(QUEUE_DEPTH, &p);
    if (s->ring_fd < 0) {
        perror("io_uring_setup");
        return 1;
    }

    // Fetch and decide on submission and completion ring sizes
    int sring_sz = p.sq_off.array + p.sq_entries * sizeof(unsigned);
    int cring_sz = p.cq_off.cqes + p.cq_entries * sizeof(struct io_uring_cqe);
    printf("sring_sz  = %d, cring_sz = %d\n", sring_sz, cring_sz);

    //  mmap the submission ring
    sq_ptr = mmap(0, sring_sz, PROT_READ | PROT_WRITE,
            MAP_SHARED | MAP_POPULATE,
            s->ring_fd, IORING_OFF_SQ_RING);
    if (sq_ptr == MAP_FAILED) {
        perror("mmap");
        return 1;
    }

    // mmap the completion ring
    /* Map in the completion queue ring buffer in older kernels separately */
        cq_ptr = mmap(0, cring_sz, PROT_READ | PROT_WRITE,
                MAP_SHARED | MAP_POPULATE,
                s->ring_fd, IORING_OFF_CQ_RING);

        if (cq_ptr == MAP_FAILED) {

            perror("mmap");
            return 1;
        }
    /* Save useful fields in a global app_io_sq_ring struct for later easy reference */
    sring->head = sq_ptr + p.sq_off.head;
    sring->tail = sq_ptr + p.sq_off.tail;
    sring->ring_mask = sq_ptr + p.sq_off.ring_mask;
    sring->ring_entries = sq_ptr + p.sq_off.ring_entries;
    sring->flags = sq_ptr + p.sq_off.flags;
    sring->array = sq_ptr + p.sq_off.array;
    /* Map in the submission queue entries array */
    s->sqes = mmap(0, p.sq_entries * sizeof(struct io_uring_sqe),
            PROT_READ | PROT_WRITE, MAP_SHARED | MAP_POPULATE,
            s->ring_fd, IORING_OFF_SQES);
    if (s->sqes == MAP_FAILED) {
        perror("mmap");
        return 1;
    }
    /* Save useful fields in a global app_io_cq_ring struct for later easy reference */
    cring->head = cq_ptr + p.cq_off.head;
    cring->tail = cq_ptr + p.cq_off.tail;
    cring->ring_mask = cq_ptr + p.cq_off.ring_mask;
    cring->ring_entries = cq_ptr + p.cq_off.ring_entries;
    cring->cqes = cq_ptr + p.cq_off.cqes;
    return 0;
}
int main(int argc, char *argv[]) {
    struct submitter *s;
    s = malloc(sizeof(*s));
    if (!s) {
        perror("malloc");
        return 1;
    }
    memset(s, 0, sizeof(*s));
    if(app_setup_uring(s)) {
        fprintf(stderr, "Unable to setup uring!\n");
        return 1;
    }
    printf("setup completed\n");

    // Open the block device and read the data

    submit_to_sq(argv[1], s);
    printf("submit cq completed\n");
    read_from_cq(s);
    printf("read cq completed\n");
}

Output of this program :

 ./a.out /dev/sdej

sring_sz  = 148, cring_sz = 176

setup completed

sz = 5369364480

submit cq completed

iov_base  = 0x17aca00, iov_len = 512

0, 0

iov_base  = 0x17ace00, iov_len = 512

0, 0

iov_base  = 0x17ad200, iov_len = 512

-128, 2

iov_base  = 0x17ad600, iov_len = 512

0, 0

iov_base  = 0x17ada00, iov_len = 512

0, 0

iov_base  = 0x17ade00, iov_len = 512

0, 0

iov_base  = 0x17ae200, iov_len = 512

0, 0

iov_base  = 0x17ae800, iov_len = 512

0, 0

iov_base  = 0x17aec00, iov_len = 512

-127, 2

iov_base  = 0x17af000, iov_len = 512

-119, 2

iov_base  = 0x17af400, iov_len = 512

0, 0

iov_base  = 0x17af800, iov_len = 512

8, 0

iov_base  = 0x17afc00, iov_len = 512

0, 0

iov_base  = 0x17b0000, iov_len = 512

0, 0

iov_base  = 0x17b0400, iov_len = 512

0, 0

iov_base  = 0x17b0a00, iov_len = 512

0, 0

iov_base  = 0x17b0e00, iov_len = 512

2, -128

iov_base  = 0x17b1200, iov_len = 512

0, 0

iov_base  = 0x17b1600, iov_len = 512

0, 0

iov_base  = 0x17b1a00, iov_len = 512

0, 0

read cq completed

Lets see the system calls this program uses : 

cat /proc/kallsyms | grep uring_setup

ffffffff9cf30b30 t io_uring_setup

ffffffff9cf31350 T __x64_sys_io_uring_setup

Also after this mmap is done for submission and completion rings. Then we use io_uring_enter

 cat /proc/kallsyms | grep io_uring_enter

ffffffff9cf300c0 T __ia32_sys_io_uring_enter

ffffffff9cf30390 T __x64_sys_io_uring_enter

Ftrace for the io_uring_enter : 

# tracer: function_graph

#

# CPU  DURATION                  FUNCTION CALLS

# |     |   |                     |   |   |   |

  9)               |  __x64_sys_io_uring_enter() {

  9)               |    __fdget() {

  9)   0.395 us    |      __fget_light();

  9)   1.620 us    |    }

  9)   0.370 us    |    mutex_lock();

  9)               |    io_ring_submit() {

  9)   0.315 us    |      io_get_sqring();

  9)               |      io_submit_sqe() {

  9)               |        kmem_cache_alloc() {

  9)   0.333 us    |          should_failslab();

  9)   1.075 us    |        }

  9)               |        fget() {

  9)   0.318 us    |          __fget();

  9)   0.960 us    |        }

  9)               |        io_queue_sqe() {

  9)               |          __io_submit_sqe() {

  9)               |            io_read() {

  9)   1.003 us    |              io_prep_rw();

  9)               |              io_import_iovec.isra.28() {

  9)               |                rw_copy_check_uvector() {

  9)               |                  __kmalloc() {

  9)   0.343 us    |                    kmalloc_slab();

  9)   0.325 us    |                    should_failslab();

  9)   1.579 us    |                  }

  9)   2.604 us    |                }

  9)   3.300 us    |              }

  9)               |              rw_verify_area() {

  9)               |                security_file_permission() {

  9)               |                  apparmor_file_permission() {

  9)   0.480 us    |                    common_file_perm();

  9)   1.030 us    |                  }

  9)   0.303 us    |                  __fsnotify_parent();

  9)   0.320 us    |                  fsnotify();

  9)   3.010 us    |                }

  9)   3.650 us    |              }

  9)               |              blkdev_read_iter() {

  9)               |                generic_file_read_iter() {

  9)               |                  _cond_resched() {

  9)   0.295 us    |                    rcu_all_qs();

  9)   0.888 us    |                  }

  9)               |                  pagecache_get_page() {

  9)   0.420 us    |                    find_get_entry();

  9)   1.133 us    |                  }

  9)               |                  touch_atime() {

  9)   0.758 us    |                    atime_needs_update();

  9)   0.493 us    |                    __sb_start_write();

  9)   0.622 us    |                    __mnt_want_write();

  9)   0.513 us    |                    current_time();

  9)   0.767 us    |                    generic_update_time();

  9)   0.293 us    |                    __mnt_drop_write();

  9)   0.290 us    |                    __sb_end_write();

  9)   6.542 us    |                  }

  9) + 10.372 us   |                }

  9) + 10.992 us   |              }

  9)   0.302 us    |              io_async_list_note();

  9)   0.385 us    |              kfree();

  9) + 22.211 us   |            }

  9) + 23.097 us   |          }

  9)               |          kmem_cache_alloc_trace() {

  9)   0.285 us    |            should_failslab();

  9)   0.888 us    |          }

  9)               |          queue_work_on() {

  9)               |            __queue_work() {

  9)   0.295 us    |              get_work_pool();

  9)   0.375 us    |              _raw_spin_lock();

  9)               |              insert_work() {

  9)   0.287 us    |                get_pwq.isra.24();

  9)               |                wake_up_process() {

  9)               |                  try_to_wake_up() {

  9)   0.480 us    |                    _raw_spin_lock_irqsave();

  9)   1.093 us    |                    select_task_rq_fair();

  9)   0.315 us    |                    _raw_spin_lock();

  9)   0.420 us    |                    update_rq_clock();

  9)   3.212 us    |                    ttwu_do_activate();

  9)   0.405 us    |                    _raw_spin_unlock_irqrestore();

  9)   8.424 us    |                  }

  9)   9.002 us    |                }

  9) + 10.362 us   |              }

  9) + 12.360 us   |            }

  9) + 12.982 us   |          }

  9) + 38.604 us   |        }

  9) + 42.868 us   |      }

  9) + 45.786 us   |    }

  9)   0.345 us    |    mutex_unlock();

  9)               |    io_cqring_wait() {

  9)   0.310 us    |      init_wait_entry();

  9)               |      prepare_to_wait_event() {

  9)   0.307 us    |        _raw_spin_lock_irqsave();

  9)   0.300 us    |        _raw_spin_unlock_irqrestore();

  9)   1.545 us    |      }

  9)               |      schedule() {

  9)               |        rcu_note_context_switch() {

  9)   0.293 us    |          rcu_qs();

  9)   0.905 us    |        }

  9)   0.315 us    |        _raw_spin_lock();

  9)               |        update_rq_clock() {

  9)   0.367 us    |          update_rq_clock.part.85();

  9)   0.912 us    |        }

  9)               |        deactivate_task() {

  9)               |          dequeue_task_fair() {

  9)               |            dequeue_entity() {

  9)               |              update_curr() {

  9)   0.352 us    |                update_min_vruntime();

  9)   0.570 us    |                cpuacct_charge();

  9)               |                __cgroup_account_cputime() {

  9)   0.552 us    |                  cgroup_rstat_updated();

  9)   1.487 us    |                }

  9)   4.268 us    |              }

  9)               |              __update_load_avg_se() {

  9)   0.467 us    |                __accumulate_pelt_segments();

  9)   1.555 us    |              }

  9)   0.508 us    |              _raw_spin_lock();

  9)               |              __update_load_avg_cfs_rq() {

  9)   0.455 us    |                __accumulate_pelt_segments();

  9)   1.525 us    |              }

  9)               |              dbs_update_util_handler() {

  9)   0.498 us    |                cpufreq_this_cpu_can_update();

  9)   1.433 us    |              }

  9)   0.450 us    |              clear_buddies();

  9)   0.448 us    |              account_entity_dequeue();

  9)   0.462 us    |              update_cfs_group();

  9)   0.552 us    |              update_min_vruntime();

  9) + 16.094 us   |            }

  9)   0.478 us    |            hrtick_update();

  9) + 18.077 us   |          }

  9) + 18.975 us   |        }

  9)               |        pick_next_task_fair() {

  9)               |          newidle_balance() {

  9)   0.583 us    |            __msecs_to_jiffies();

  9)   1.758 us    |          }

  9)   2.788 us    |        }

  9)               |        put_prev_task_fair() {

  9)               |          put_prev_entity() {

  9)   0.477 us    |            check_cfs_rq_runtime();

  9)   1.347 us    |          }

  9)   2.385 us    |        }

  9)               |        pick_next_task_idle() {

  9)               |          set_next_task_idle() {

  9)   0.573 us    |            __update_idle_core();

  9)   1.512 us    |          }

  9)   2.535 us    |        }

  9)   0.430 us    |        enter_lazy_tlb();

  9)   1.495 us    |        finish_task_switch();

  9) ! 853.302 us  |      }

  9)               |      prepare_to_wait_event() {

  9)   0.585 us    |        _raw_spin_lock_irqsave();

  9)   0.873 us    |        _raw_spin_unlock_irqrestore();

  9)   2.938 us    |      }

  9)               |      finish_wait() {

  9)   0.297 us    |        _raw_spin_lock_irqsave();

  9)   0.305 us    |        _raw_spin_unlock_irqrestore();

  9)   1.605 us    |      }

  9) ! 862.405 us  |    }

  9)   0.315 us    |    io_ring_drop_ctx_refs();

  9) ! 915.753 us  |  }