Linux posts: 2019

We will write a simple C program and write to file. We will see how the write is given to the disk.
Which are the layers through which the IO traverses.

Let us make a file system on the entire disk:

[root@kundan ~]# mkfs.ext4 /dev/sdh
mke2fs 1.42.9 (28-Dec-2013)
/dev/sdh is entire device, not just one partition!
Proceed anyway? (y,n) y
Discarding device blocks: done
Filesystem label=
OS type: Linux
Block size=1024 (log=0)
Fragment size=1024 (log=0)
Stride=0 blocks, Stripe width=0 blocks
130560 inodes, 522240 blocks
26112 blocks (5.00%) reserved for the super user
First data block=1
Maximum filesystem blocks=34078720
64 block groups
8192 blocks per group, 8192 fragments per group
2040 inodes per group
Superblock backups stored on blocks:
8193, 24577, 40961, 57345, 73729, 204801, 221185, 401409

Allocating group tables: done
Writing inode tables: done
Creating journal (8192 blocks): done
Writing superblocks and filesystem accounting information: done

Let us mount the filesystem on a directory and try to write to a file in that directory.
mount /dev/sdh /mnt

USER SPACE applications :
In our C program we will write to a file in /mnt directory using O_SYNC.
O_SYNC The file is opened for synchronous I/O. Any write's on the resulting file descriptor will block the calling process until the data has been physically written to the underlying hardware.
#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;
}

Lets trace this using ftrace :
cd /sys/kernel/debug/tracing
cat /dev/null > trace
echo vfs_write > set_graph_function
echo 10 > max_graph_depth
echo function_graph > 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

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

SINGLE QUEUE IO SUBMISSION

VFS LAYER

12) | vfs_write() {

...

12) 0.080 us | __sb_start_write();

12) | __vfs_write() {

12) | ext4_file_write_iter [ext4]() {

12) 0.216 us | down_write_trylock();

12) 0.451 us | ext4_write_checks [ext4]();

12) | __generic_file_write_iter() {

...

12) | __mark_inode_dirty() {

12) | ext4_dirty_inode [ext4]() {

12) | __ext4_journal_start_sb [ext4]() {

12) 0.067 us | ext4_journal_check_start [ext4]();

12) | jbd2__journal_start [jbd2]() {

12) | kmem_cache_alloc() {

12) | cache_grow_begin() {

12) | __alloc_pages_nodemask() {

...

12) | ext4_mark_inode_dirty [ext4]() {

12) | ext4_reserve_inode_write [ext4]() {

12) | __ext4_get_inode_loc [ext4]() {

12) 0.075 us | ext4_get_group_desc [ext4]();

12) 0.068 us | ext4_inode_table [ext4]();

12) | __getblk_gfp() {

12) | __find_get_block() {

12) 0.073 us | mark_page_accessed();

12) 1.043 us | }

12) 1.702 us | }

12) 4.303 us | }

12) | __ext4_journal_get_write_access [ext4]() {

12) | jbd2_journal_get_write_access [jbd2]() {

...

12) | ext4_mark_iloc_dirty [ext4]() {

12) | ext4_do_update_inode [ext4]() {

12) 0.065 us | _raw_spin_lock();

...

12) | generic_perform_write() {

12) | ext4_da_write_begin [ext4]() {

12) 0.135 us | ext4_nonda_switch [ext4]();

12) | __ext4_journal_start_sb [ext4]() {

12) 0.068 us | ext4_journal_check_start [ext4]();

12) | jbd2__journal_start [jbd2]() {

12) + 11.529 us | }

12) | ext4_da_write_end [ext4]() {

12) 0.065 us | down_write();

12) 0.065 us | up_write();

12) | ext4_mark_inode_dirty [ext4]() {

...

12) ! 153.424 us | }

12) 0.066 us | up_write();

12) | vfs_fsync_range() {

12) | ext4_sync_file [ext4]() {

12) | file_write_and_wait_range() {

12) | __filemap_fdatawrite_range() {

EXT4 USING THE PAGE CACHE

12) | do_writepages() {

12) | ext4_writepages [ext4]() {

12) 0.203 us | mapping_tagged();

12) 0.063 us | ext4_io_submit_init [ext4]();

...

12) | ext4_init_io_end [ext4]() {

12) | kmem_cache_alloc() {

12) | cache_grow_begin() {

12) | mpage_prepare_extent_to_map [ext4]() {

12) | pagevec_lookup_tag() {

12) 0.333 us | find_get_pages_tag();

12) 1.010 us | }

12) | mpage_process_page_bufs [ext4]() {

12) | mpage_submit_page [ext4]() {

...

12) | ext4_bio_write_page [ext4]() {

12) 0.065 us | unlock_page_memcg();

12) 6.516 us | }

12) | bio_alloc_bioset() {

12) | mempool_alloc() {

12) | mempool_alloc_slab() {

12) 0.165 us | kmem_cache_alloc();

12) 1.015 us | }

12) 1.872 us | }

12) | bvec_alloc() {

12) | mempool_alloc() {

12) | mempool_alloc_slab() {

12) 0.115 us | kmem_cache_alloc();

12) 0.662 us | }

12) 1.303 us | }

12) 1.972 us | }

12) 5.461 us | }

PAGE CACHE RAM PAGES ADDED TO BIO

12) 0.087 us | bio_add_page();

12) | __pagevec_release() {

...

12) + 14.431 us | }

12) + 38.890 us | }

12) | ext4_io_submit [ext4]() {

BLOCK IO, ELEVATOR, REQUEST and MERGE

12) | submit_bio() {

12) | generic_make_request() {

12) | generic_make_request_checks() {

...

12) 0.156 us | blk_queue_enter();

12) | blk_queue_bio() {

12) 0.206 us | blk_queue_bounce();

...

12) | elv_merge() {

12) 0.263 us | elv_rqhash_find();

12) | get_request() {

12) | elv_may_queue() {

12) | cfq_may_queue() {

12) 0.087 us | ioc_lookup_icq();

...

12) 0.133 us | blk_rq_init();

12) | ioc_create_icq() {

12) | blk_init_request_from_bio() {

12) 0.258 us | blk_rq_bio_prep();

12) 0.897 us | }

...

12) 0.098 us | ext4_put_io_end_defer [ext4]();

12) 0.156 us | mpage_release_unused_pages [ext4]();

12) | blk_finish_plug() {

12) | blk_flush_plug_list() {

12) 0.065 us | _raw_spin_lock();

12) | __elv_add_request() {

12) | elv_attempt_insert_merge() {

12) 0.081 us | elv_rqhash_find();

12) 0.659 us | }

12) 0.091 us | elv_rqhash_add();

12) | cfq_insert_request() {

...

12) | __blk_run_queue() {

12) | scsi_request_fn [scsi_mod]() {

12) | blk_peek_request() {

...

SCSI COMMAND PREPARATION

12) | scsi_prep_fn [scsi_mod]() {

12) 0.063 us | scsi_prep_state_check.isra.29 [scsi_mod]();

12) 0.208 us | get_device();

12) | scsi_init_command [scsi_mod]() {

12) 0.067 us | init_timer_key();

12) 0.068 us | scsi_add_cmd_to_list [scsi_mod]();

12) 1.629 us | }

12) | scsi_setup_cmnd [scsi_mod]() {

12) 0.739 us | alua_prep_fn [scsi_dh_alua]();

12) | sd_init_command [sd_mod]() {

12) 3.654 us | sd_setup_read_write_cmnd [sd_mod]();

12) 4.406 us | }

12) 7.198 us | }

12) + 11.997 us | }

12) + 32.313 us | }

12) | blk_queue_start_tag() {

12) | blk_start_request() {

...

12) 0.210 us | scsi_init_cmd_errh [scsi_mod]();

12) | scsi_dispatch_cmd [scsi_mod]() {

12) 0.070 us | scsi_log_send [scsi_mod]();

EMULEX DRIVER CALLS

12) | lpfc_queuecommand [lpfc]() {

12) 0.075 us | scsi_is_fc_rport [scsi_transport_fc]();

12) | lpfc_get_scsi_buf_s3 [lpfc]() {

12) 0.068 us | _raw_spin_lock_irqsave();

12) 0.075 us | _raw_spin_unlock_irqrestore();

12) 1.391 us | }

12) 1.556 us | lpfc_scsi_prep_dma_buf_s3 [lpfc]();

12) | lpfc_scsi_prep_cmnd [lpfc]() {

12) 0.083 us | int_to_scsilun [scsi_mod]();

12) 1.306 us | }

12) | lpfc_sli_issue_iocb [lpfc]() {

12) 0.067 us | _raw_spin_lock_irqsave();

12) | __lpfc_sli_issue_iocb_s3 [lpfc]() {

12) 0.068 us | lpfc_sli_next_iocb_slot [lpfc]();

12) 0.473 us | lpfc_sli_submit_iocb [lpfc]();

12) 0.092 us | lpfc_sli_next_iocb_slot [lpfc]();

12) 2.945 us | }

12) 0.075 us | _raw_spin_unlock_irqrestore();

12) 4.852 us | }

12) + 13.464 us | }

....

MULTIQUEUE IO SUBMISSION ON NVME

Lets make filesystem and mount a NVMe device :

For nvme devices :
mkfs.ext4 /dev/nvme0n4

ncpp240034:~ # mkfs.ext4 /dev/nvme0n4
mke2fs 1.43.8 (1-Jan-2018)
/dev/nvme0n4 contains a ext4 file system
last mounted on /root/my_mnt on Fri Mar 22 03:13:32 2019
Proceed anyway? (y,N) y
Creating filesystem with 26214400 4k blocks and 6566400 inodes
Filesystem UUID: 5f8ca338-eb67-488a-93c2-ec0d4260e9db
Superblock backups stored on blocks:
32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208,
4096000, 7962624, 11239424, 20480000, 23887872

Allocating group tables: done
Writing inode tables: done
Creating journal (131072 blocks): done
Writing superblocks and filesystem accounting information: done

MOUNT the device
ncpp240034:~ # mount /dev/nvme0n4 /mnt

Lets write to the device and take an ftrace:

cd /sys/kernel/debug/tracing
cat /dev/null > trace
echo vfs_write > set_graph_function
echo 30 > max_graph_depth
echo function_graph > current_tracer
echo 1 > tracing_on

/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out
/root/kundan/a.out

cp trace /root/kundan/vfs_write_trace
echo 0 > tracing_on
echo > set_graph_function
echo 0 > max_graph_depth
cat /dev/null > trace

Ftrace on NVMe enabled with multiqueue

VFS :
22) | vfs_fsync_range() {

EXT4 :
22) | ext4_sync_file [ext4]() {
22) | file_write_and_wait_range() {
22) | __filemap_fdatawrite_range() {
22) 0.065 us | _raw_spin_lock();
22) 0.074 us | wbc_attach_and_unlock_inode();
22) | do_writepages() {
22) | ext4_writepages [ext4]() {
22) 0.097 us | mapping_tagged();
22) 0.074 us | ext4_io_submit_init [ext4]();
22) | tag_pages_for_writeback() {
22) 0.071 us | _raw_spin_lock_irq();
22) 1.200 us | }
22) 0.089 us | blk_start_plug();
22) | ext4_init_io_end [ext4]() {
22) | kmem_cache_alloc() {
22) | cache_grow_begin() {
22) | __alloc_pages_nodemask() {
22) | get_page_from_freelist() {
22) 0.062 us | __inc_numa_state();
22) 0.072 us | __inc_numa_state();
22) 1.500 us | }
22) 2.143 us | }
22) 0.068 us | mod_zone_page_state();
22) 0.197 us | get_random_u32();
22) 5.046 us | }
22) | cache_grow_end.part.47() {
22) 0.089 us | _raw_spin_lock();
22) 0.732 us | }
22) 7.554 us | }
22) 8.249 us | }
22) | mpage_prepare_extent_to_map [ext4]() {
22) | pagevec_lookup_tag() {
22) 0.186 us | find_get_pages_tag();
22) 0.862 us | }
22) | mpage_process_page_bufs [ext4]() {
22) | mpage_submit_page [ext4]() {
22) | clear_page_dirty_for_io() {
22) 0.077 us | page_mapping();
22) | page_mkclean() {
22) 0.089 us | page_mapped();
22) 0.774 us | }
22) 0.146 us | dec_node_page_state();
22) 0.091 us | dec_zone_page_state();
22) 4.023 us | }
22) | ext4_bio_write_page [ext4]() {
22) | __test_set_page_writeback() {
22) 0.062 us | page_mapping();
22) 0.063 us | lock_page_memcg();
22) 0.066 us | _raw_spin_lock_irqsave();
....
BIO SUBMISSION
22) | ext4_io_submit [ext4]() {
22) | submit_bio() {
22) | generic_make_request() {
22) | generic_make_request_checks() {
22) | create_task_io_context() {
22) 0.282 us | kmem_cache_alloc_node();
22) 0.075 us | _raw_spin_lock();
22) 1.663 us | }
22) 0.345 us | blk_throtl_bio();
22) 4.395 us | }
22) 0.291 us | blk_queue_enter();

BLK IO MAKE REQUEST
22) | blk_mq_make_request() {
22) 0.094 us | blk_queue_bounce();
22) 0.314 us | blk_queue_split();
22) 0.186 us | bio_integrity_prep();
22) 0.125 us | blk_attempt_plug_merge();
22) | __blk_mq_sched_bio_merge() {
22) 0.155 us | _raw_spin_lock();
22) 1.486 us | }
22) | wbt_wait() {
22) | rwb_arm_timer() {
22) 0.062 us | nsecs_to_jiffies();
22) | mod_timer() {
22) | lock_timer_base() {
22) 0.086 us | _raw_spin_lock_irqsave();
22) 0.786 us | }
22) 0.066 us | detach_if_pending();
22) 0.068 us | get_nohz_timer_target();
22) 0.091 us | _raw_spin_lock();
22) | __internal_add_timer() {
22) 0.080 us | calc_wheel_index();
22) 0.763 us | }
22) 0.066 us | trigger_dyntick_cpu.isra.34();
22) 0.083 us | _raw_spin_unlock_irqrestore();
22) 6.335 us | }
22) 7.660 us | }
22) 9.377 us | }
22) | blk_mq_get_request() {
22) | blk_mq_get_tag() {
22) 0.443 us | __blk_mq_get_tag();
22) 1.303 us | }
22) 0.074 us | __blk_mq_tag_busy();
22) 3.192 us | }
22) | blk_mq_bio_to_request() {
22) | blk_init_request_from_bio() {
22) 0.169 us | blk_rq_bio_prep();
22) 0.854 us | }
22) | blk_account_io_start() {
22) 0.255 us | disk_map_sector_rcu();
22) | part_round_stats() {
22) | part_in_flight() {
22) | blk_mq_in_flight() {
22) | blk_mq_queue_tag_busy_iter() {
22) | bt_iter() {
22) 0.106 us | blk_mq_check_inflight();
22) 0.792 us | }
22) 4.822 us | }
22) 5.472 us | }
22) 6.220 us | }
22) 7.038 us | }
22) 0.088 us | part_inc_in_flight();
22) 9.377 us | }
22) + 11.598 us | }
22) + 32.441 us | }
22) + 39.520 us | }
22) + 40.232 us | }
22) + 40.947 us | }
22) 0.125 us | ext4_put_io_end_defer [ext4]();
22) 0.088 us | mpage_release_unused_pages [ext4]();
22) | blk_finish_plug() {
22) | blk_flush_plug_list() {
22) | blk_mq_flush_plug_list() {
22) | blk_mq_sched_insert_requests() {
22) | blk_mq_insert_requests() {
22) 0.065 us | _raw_spin_lock();
22) 0.192 us | blk_mq_hctx_mark_pending.isra.32();
22) 1.526 us | }
RUN THE BLK MQ HW QUEUE
22) | blk_mq_run_hw_queue() {
22) | __blk_mq_delay_run_hw_queue() {
22) | __blk_mq_run_hw_queue() {
22) | blk_mq_sched_dispatch_requests() {
22) | blk_mq_flush_busy_ctxs() {
22) | flush_busy_ctx() {
22) 0.065 us | _raw_spin_lock();
22) 0.869 us | }
22) 1.703 us | }
22) | blk_mq_dispatch_rq_list() {
22) 0.071 us | blk_mq_get_driver_tag();

NVME FC DRIVER
22) | nvme_fc_queue_rq [nvme_fc]() {
22) 0.820 us | nvme_setup_cmd [nvme_core]();
22) | nvme_fc_start_fcp_op [nvme_fc]() {
22) 0.415 us | blk_rq_map_sg();
22) | blk_mq_start_request() {
22) 0.148 us | ktime_get();
22) 0.088 us | wbt_issue();
22) | blk_add_timer() {
22) 0.069 us | round_jiffies_up();
22) 0.063 us | round_jiffies_up();
22) | mod_timer() {
22) | lock_timer_base() {
22) 0.142 us | _raw_spin_lock_irqsave();
22) 0.891 us | }
22) 0.066 us | detach_if_pending();
22) 0.071 us | get_nohz_timer_target();
22) 0.063 us | _raw_spin_lock();
22) | __internal_add_timer() {
22) 0.063 us | calc_wheel_index();
22) 0.783 us | }
22) 0.066 us | trigger_dyntick_cpu.isra.34();
22) 0.083 us | _raw_spin_unlock_irqrestore();
22) 6.628 us | }
22) 9.134 us | }
22) + 11.792 us | }
QLOGIC DRIVER IO SUBMISSION
22) | qla_nvme_post_cmd [qla2xxx]() {
22) | mempool_alloc() {
22) | mempool_alloc_slab() {
22) | kmem_cache_alloc() {
22) 0.078 us | _raw_spin_lock();
22) 0.114 us | transfer_objects();
22) 0.083 us | get_first_slab();
22) 0.065 us | get_first_slab();
22) 0.063 us | get_first_slab();
22) 0.069 us | get_first_slab();
22) 5.358 us | }
22) 5.988 us | }
22) 6.860 us | }
22) 0.066 us | __init_waitqueue_head();
22) 0.066 us | _raw_spin_lock_irqsave();
22) 0.077 us | _raw_spin_unlock_irqrestore();
22) + 10.649 us | }
22) + 26.126 us | }
22) + 28.609 us | }
22) + 30.317 us | }
22) + 33.449 us | }
22) + 34.135 us | }
22) + 34.886 us | }
22) + 35.535 us | }
22) + 38.483 us | }
22) + 39.526 us | }
22) + 40.320 us | }
22) + 41.001 us | }
22) ! 143.595 us | }
22) ! 144.438 us | }
22) 0.123 us | wbc_detach_inode();
22) ! 147.312 us | }

Linux posts

Articles in this blog

Tuesday, 17 September 2019

Linux FUSE Internals

Friday, 19 April 2019

Write system call and ftrace