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
#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
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
No comments:
Post a Comment