Friday 19 April 2019

Write system call and ftrace

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  |              }
Posted by at

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)