こういう環境で、こういうプログラムを動かした。トレースは手で編集してあります。
$ uname -a
Linux localhost 2.6.43.2-6.local.fc15.i686 #1 SMP Wed May 2 12:56:55 JST 2012 i686 i686 i386 GNU/Linux
import os
path = "/mnt/xfs/a"
tr = os.open("/sys/kernel/debug/tracing/tracing_on", os.O_WRONLY)
fd = os.open(path, os.O_SYNC | os.O_RDWR)
os.write(tr, "1")
os.write(fd, "aaaa")
os.write(tr, "0")
os.close(fd)
$ cat /sys/kernel/debug/tracing/trace
python-1907 [000] .... 369.121217: xfs_trans_alloc <-xfs_file_fsync ＃ トランザクションメモリ確保
python-1907 [000] .... 369.121218: _xfs_trans_alloc <-xfs_trans_alloc
python-1907 [000] .... 369.121218: kmem_zone_zalloc <-_xfs_trans_alloc
python-1907 [000] .... 369.121236: xfs_trans_reserve <-xfs_file_fsync ＃ ログ領域予約
python-1907 [000] .... 369.121237: xfs_log_reserve <-xfs_trans_reserve
python-1907 [000] .... 369.121238: xlog_ticket_alloc <-xfs_log_reserve
python-1907 [000] .... 369.121238: kmem_zone_zalloc <-xlog_ticket_alloc
python-1907 [000] .... 369.121238: kmem_zone_alloc <-kmem_zone_zalloc
python-1907 [000] .... 369.121239: kmem_cache_alloc <-kmem_zone_alloc
python-1907 [000] .... 369.121239: _cond_resched <-kmem_cache_alloc
python-1907 [000] .... 369.121240: kmem_cache_size <-kmem_zone_zalloc
python-1907 [000] .... 369.121240: memset <-kmem_zone_zalloc
python-1907 [000] .... 369.121241: __init_waitqueue_head <-xlog_ticket_alloc
python-1907 [000] .... 369.121242: xlog_grant_push_ail <-xfs_log_reserve
python-1907 [000] .... 369.121242: xlog_space_left <-xlog_grant_push_ail
python-1907 [000] .... 369.121243: xlog_grant_log_space <-xfs_log_reserve
python-1907 [000] .... 369.121244: xlog_space_left <-xlog_grant_log_space
python-1907 [000] .... 369.121244: xlog_grant_add_space <-xlog_grant_log_space
python-1907 [000] .... 369.121245: xlog_grant_add_space <-xlog_grant_log_space
python-1907 [000] .... 369.121245: xfs_ilock <-xfs_file_fsync
python-1907 [000] .... 369.121246: down_write <-xfs_ilock
python-1907 [000] .... 369.121247: _cond_resched <-down_write
python-1907 [000] .... 369.121247: xfs_trans_ijoin <-xfs_file_fsync ＃ inode をトランザクションに入れ、アイテムをつなぐ
python-1907 [000] .... 369.121248: xfs_inode_item_init <-xfs_trans_ijoin
python-1907 [000] .... 369.121248: kmem_zone_zalloc <-xfs_inode_item_init
python-1907 [000] .... 369.121265: memset <-kmem_zone_zalloc
python-1907 [000] .... 369.121266: xfs_log_item_init <-xfs_inode_item_init
python-1907 [000] .... 369.121266: xfs_trans_add_item <-xfs_trans_ijoin
python-1907 [000] .... 369.121266: kmem_zone_zalloc <-xfs_trans_add_item
python-1907 [000] .... 369.121267: kmem_zone_alloc <-kmem_zone_zalloc
python-1907 [000] .... 369.121267: kmem_cache_alloc <-kmem_zone_alloc
python-1907 [000] .... 369.121267: _cond_resched <-kmem_cache_alloc
python-1907 [000] .... 369.121268: kmem_cache_size <-kmem_zone_zalloc
python-1907 [000] .... 369.121268: memset <-kmem_zone_zalloc
python-1907 [000] .... 369.121269: xfs_trans_log_inode <-xfs_file_fsync
python-1907 [000] .... 369.121269: xfs_trans_commit <-xfs_file_fsync ＃ コミット
python-1907 [000] .... 369.121270: xfs_trans_apply_dquot_deltas <-xfs_trans_commit
python-1907 [000] .... 369.121271: xfs_log_commit_cil <-xfs_trans_commit
python-1907 [000] .... 369.121271: xfs_inode_item_size <-xfs_log_commit_cil
python-1907 [000] .... 369.121272: kmem_zalloc <-xfs_log_commit_cil ＃ メモリバッファに、アイテムとベクトルをコピー
python-1907 [000] .... 369.121272: kmem_alloc <-kmem_zalloc
python-1907 [000] .... 369.121273: __kmalloc <-kmem_alloc
python-1907 [000] .... 369.121273: _cond_resched <-__kmalloc
python-1907 [000] .... 369.121274: memset <-kmem_zalloc
python-1907 [000] .... 369.121275: xfs_inode_item_format <-xfs_log_commit_cil
python-1907 [000] .... 369.121275: xfs_synchronize_times <-xfs_inode_item_format
python-1907 [000] .... 369.121276: kmem_alloc <-xfs_log_commit_cil
python-1907 [000] .... 369.121276: __kmalloc <-kmem_alloc
python-1907 [000] .... 369.121277: _cond_resched <-__kmalloc
python-1907 [000] .... 369.121277: memcpy <-xfs_log_commit_cil
python-1907 [000] .... 369.121277: memcpy <-xfs_log_commit_cil
python-1907 [000] .... 369.121278: down_read <-xfs_log_commit_cil
python-1907 [000] .... 369.121278: _cond_resched <-down_read
python-1907 [000] .... 369.121279: xfs_cil_prepare_item <-xfs_log_commit_cil
python-1907 [000] .... 369.121280: xfs_inode_item_pin <-xfs_cil_prepare_item
python-1907 [000] .... 369.121280: _raw_spin_lock <-xfs_log_commit_cil
python-1907 [000] .... 369.121281: xfs_log_done <-xfs_log_commit_cil
python-1907 [000] .... 369.121282: xlog_ungrant_log_space <-xfs_log_done
python-1907 [000] .... 369.121282: xlog_grant_sub_space <-xlog_ungrant_log_space
python-1907 [000] .... 369.121282: xlog_grant_sub_space <-xlog_ungrant_log_space
python-1907 [000] .... 369.121283: xfs_log_move_tail <-xlog_ungrant_log_space
python-1907 [000] .... 369.121284: xfs_log_ticket_put <-xfs_log_done
python-1907 [000] .... 369.121284: kmem_cache_free <-xfs_log_ticket_put
python-1907 [000] .... 369.121285: xfs_trans_unreserve_and_mod_sb <-xfs_log_commit_cil
python-1907 [000] .... 369.121286: xfs_trans_free_items <-xfs_log_commit_cil
python-1907 [000] .... 369.121286: xfs_inode_item_committing <-xfs_trans_free_items
python-1907 [000] .... 369.121287: xfs_inode_item_unlock <-xfs_trans_free_items
python-1907 [000] .... 369.121288: xfs_trans_free_item_desc <-xfs_trans_free_items
python-1907 [000] .... 369.121288: kmem_cache_free <-xfs_trans_free_item_desc
python-1907 [000] .... 369.121288: up_read <-xfs_log_commit_cil
python-1907 [000] .... 369.121289: xfs_trans_free <-xfs_trans_commit ＃ 非同期のコミット完了
python-1907 [000] .... 369.121290: xfs_alloc_busy_clear <-xfs_trans_free
python-1907 [000] .... 369.121291: xfs_trans_free_dqinfo <-xfs_trans_free
python-1907 [000] .... 369.121291: kmem_cache_free <-xfs_trans_free
python-1907 [000] .... 369.121292: xfs_iunlock <-xfs_file_fsync
python-1907 [000] .... 369.121292: up_write <-xfs_iunlock
python-1907 [000] .... 369.121292: xfs_trans_unlocked_item <-xfs_iunlock
python-1907 [000] .... 369.121293: _xfs_log_force_lsn <-xfs_file_fsync ＃ 同期なので、ログフォース
python-1907 [000] .... 369.121293: xlog_cil_force_lsn <-_xfs_log_force_lsn
python-1907 [000] .... 369.121294: xlog_cil_push <-xlog_cil_force_lsn ＃ CILプッシュ
python-1907 [000] .... 369.121294: kmem_zalloc <-xlog_cil_push
python-1907 [000] .... 369.121295: kmem_alloc <-kmem_zalloc
python-1907 [000] .... 369.121295: __kmalloc <-kmem_alloc
python-1907 [000] .... 369.121295: _cond_resched <-__kmalloc
python-1907 [000] .... 369.121296: memset <-kmem_zalloc
python-1907 [000] .... 369.121297: xlog_cil_ticket_alloc <-xlog_cil_push
python-1907 [000] .... 369.121297: xlog_ticket_alloc <-xlog_cil_ticket_alloc
python-1907 [000] .... 369.121297: kmem_zone_zalloc <-xlog_ticket_alloc
python-1907 [000] .... 369.121298: kmem_zone_alloc <-kmem_zone_zalloc
python-1907 [000] .... 369.121298: kmem_cache_alloc <-kmem_zone_alloc
python-1907 [000] .... 369.121298: _cond_resched <-kmem_cache_alloc
python-1907 [000] .... 369.121299: kmem_cache_size <-kmem_zone_zalloc
python-1907 [000] .... 369.121299: memset <-kmem_zone_zalloc
python-1907 [000] .... 369.121300: __init_waitqueue_head <-xlog_ticket_alloc
python-1907 [000] .... 369.121300: down_write_trylock <-xlog_cil_push
python-1907 [000] .... 369.121300: _raw_spin_lock <-xlog_cil_push
python-1907 [000] .... 369.121301: up_write <-xlog_cil_push
python-1907 [000] .... 369.121301: xlog_write <-xlog_cil_push
python-1907 [000] .... 369.121302: xlog_state_get_iclog_space <-xlog_write
python-1907 [000] .... 369.121303: _raw_spin_lock <-xlog_state_get_iclog_space
python-1907 [000] .... 369.121304: memcpy <-xlog_write ＃ CILから、ログバッファに物理フォーマット
python-1907 [000] .... 369.121305: memcpy <-xlog_write
python-1907 [000] .... 369.121306: memcpy <-xlog_write
python-1907 [000] .... 369.121306: _raw_spin_lock <-xlog_write
python-1907 [000] .... 369.121307: xlog_state_release_iclog <-xlog_write
python-1907 [000] .... 369.121307: _raw_spin_lock <-_atomic_dec_and_lock
python-1907 [000] .... 369.121307: _raw_spin_lock <-xlog_cil_push
python-1907 [000] .... 369.121308: xfs_log_done <-xlog_cil_push
python-1907 [000] .... 369.121308: xlog_commit_record <-xfs_log_done
python-1907 [000] .... 369.121309: xlog_write <-xlog_commit_record
python-1907 [000] .... 369.121309: xlog_state_get_iclog_space <-xlog_write
python-1907 [000] .... 369.121309: _raw_spin_lock <-xlog_state_get_iclog_space
python-1907 [000] .... 369.121310: memcpy <-xlog_write
python-1907 [000] .... 369.121310: _raw_spin_lock <-xlog_write
python-1907 [000] .... 369.121310: xlog_ungrant_log_space <-xfs_log_done
python-1907 [000] .... 369.121311: xlog_grant_sub_space <-xlog_ungrant_log_space
python-1907 [000] .... 369.121311: xlog_grant_sub_space <-xlog_ungrant_log_space
python-1907 [000] .... 369.121312: xfs_log_move_tail <-xlog_ungrant_log_space
python-1907 [000] .... 369.121312: xfs_log_ticket_put <-xfs_log_done
python-1907 [000] .... 369.121312: kmem_cache_free <-xfs_log_ticket_put
python-1907 [000] .... 369.121313: xfs_log_notify <-xlog_cil_push
python-1907 [000] .... 369.121313: _raw_spin_lock <-xfs_log_notify
python-1907 [000] .... 369.121314: _raw_spin_lock <-xlog_cil_push
python-1907 [000] .... 369.121314: __wake_up <-xlog_cil_push
python-1907 [000] .... 369.121314: _raw_spin_lock_irqsave <-__wake_up
python-1907 [000] d... 369.121315: __wake_up_common <-__wake_up
python-1907 [000] d... 369.121315: _raw_spin_unlock_irqrestore <-__wake_up
python-1907 [000] .... 369.121316: xfs_log_release_iclog <-xlog_cil_push
python-1907 [000] .... 369.121316: xlog_state_release_iclog <-xfs_log_release_iclog
python-1907 [000] .... 369.121316: _raw_spin_lock <-_atomic_dec_and_lock
python-1907 [000] .... 369.121317: _raw_spin_lock <-xlog_cil_force_lsn
python-1907 [000] .... 369.121317: _raw_spin_lock <-_xfs_log_force_lsn
python-1907 [000] .... 369.121318: xlog_state_switch_iclogs <-_xfs_log_force_lsn
python-1907 [000] .... 369.121318: xlog_state_release_iclog <-_xfs_log_force_lsn
python-1907 [000] .... 369.121319: _raw_spin_lock <-_atomic_dec_and_lock
python-1907 [000] .... 369.121319: xlog_assign_tail_lsn <-xlog_state_release_iclog
python-1907 [000] .... 369.121320: xfs_ail_min_lsn <-xlog_assign_tail_lsn
python-1907 [000] .... 369.121320: _raw_spin_lock <-xfs_ail_min_lsn
python-1907 [000] .... 369.121320: xlog_sync <-xlog_state_release_iclog ＃ SYNCでログをディスクに書き込む
python-1907 [000] .... 369.121321: xlog_grant_add_space <-xlog_sync
python-1907 [000] .... 369.121321: xlog_grant_add_space <-xlog_sync
python-1907 [000] .... 369.121322: xlog_pack_data <-xlog_sync
python-1907 [000] .... 369.121324: xlog_bdstrat <-xlog_sync
python-1907 [000] .... 369.121324: xfs_buf_iorequest <-xlog_bdstrat
python-1907 [000] .... 369.121325: xfs_buf_wait_unpin <-xfs_buf_iorequest
python-1907 [000] .... 369.121325: xfs_buf_hold <-xfs_buf_iorequest
python-1907 [000] .... 369.121326: _xfs_buf_ioapply <-xfs_buf_iorequest
python-1907 [000] .... 369.121327: bio_alloc <-_xfs_buf_ioapply ＃ BIOを作って、しばらくは、XFS をはなれる
python-1907 [000] .... 369.121327: bio_alloc_bioset <-bio_alloc
python-1907 [000] .... 369.121328: mempool_alloc <-bio_alloc_bioset
python-1907 [000] .... 369.121328: _cond_resched <-mempool_alloc
python-1907 [000] .... 369.121328: mempool_alloc_slab <-mempool_alloc
python-1907 [000] .... 369.121329: kmem_cache_alloc <-mempool_alloc_slab
python-1907 [000] .... 369.121329: bio_init <-bio_alloc_bioset
python-1907 [000] .... 369.121330: bvec_alloc_bs <-bio_alloc_bioset
python-1907 [000] .... 369.121330: kmem_cache_alloc <-bvec_alloc_bs
python-1907 [000] .... 369.121331: bio_add_page <-_xfs_buf_ioapply
python-1907 [000] .... 369.121331: __bio_add_page.part.2 <-bio_add_page
python-1907 [000] .... 369.121332: submit_bio <-_xfs_buf_ioapply
loop0-1836 [000] .... 369.132359: xfs_buf_bio_end_io <-bio_endio ＃ I/O 完了
loop0-1836 [000] .... 369.132359: xfs_buf_ioerror <-xfs_buf_bio_end_io
loop0-1836 [000] .... 369.132360: _xfs_buf_ioend <-xfs_buf_bio_end_io
loop0-1836 [000] .... 369.132360: xfs_buf_ioend <-_xfs_buf_ioend
loop0-1836 [000] .... 369.132361: queue_work <-xfs_buf_ioend
kworker/0:3-1896 [000] .... 369.132389: xfs_buf_iodone_work <-process_one_work
kworker/0:3-1896 [000] .... 369.132389: xlog_iodone <-xfs_buf_iodone_work
kworker/0:3-1896 [000] .... 369.132390: xlog_state_done_syncing <-xlog_iodone
kworker/0:3-1896 [000] .... 369.132390: _raw_spin_lock <-xlog_state_done_syncing
kworker/0:3-1896 [000] .... 369.132391: __wake_up <-xlog_state_done_syncing
kworker/0:3-1896 [000] .... 369.132391: _raw_spin_lock_irqsave <-__wake_up
kworker/0:3-1896 [000] d... 369.132391: __wake_up_common <-__wake_up
kworker/0:3-1896 [000] d... 369.132392: _raw_spin_unlock_irqrestore <-__wake_up
kworker/0:3-1896 [000] .... 369.132392: xlog_state_do_callback <-xlog_state_done_syncing
kworker/0:3-1896 [000] .... 369.132392: _raw_spin_lock <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132394: xlog_get_lowest_lsn <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132396: _raw_spin_lock <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132397: xlog_cil_committed <-xlog_state_do_callback ＃ コミット完了コールバック
kworker/0:3-1896 [000] .... 369.132398: xfs_trans_committed_bulk <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132398: _raw_spin_lock <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132399: xfs_trans_ail_cursor_last <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132399: xfs_trans_ail_cursor_init <-xfs_trans_ail_cursor_last
kworker/0:3-1896 [000] .... 369.132401: xfs_inode_item_committed <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132401: _raw_spin_lock <-xfs_inode_item_committed ＃ inode コミット完了とアンピン
kworker/0:3-1896 [000] .... 369.132402: _raw_spin_lock <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132403: xfs_trans_ail_update_bulk <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132404: xfs_inode_item_unpin <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132404: wake_up_bit <-xfs_inode_item_unpin
kworker/0:3-1896 [000] .... 369.132405: bit_waitqueue <-wake_up_bit
kworker/0:3-1896 [000] .... 369.132405: __wake_up_bit <-wake_up_bit
kworker/0:3-1896 [000] .... 369.132406: _raw_spin_lock <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132406: xfs_trans_ail_cursor_done <-xfs_trans_committed_bulk
kworker/0:3-1896 [000] .... 369.132407: xfs_alloc_busy_clear <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132408: _raw_spin_lock <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132408: kmem_free <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132409: kfree <-kmem_free
kworker/0:3-1896 [000] .... 369.132409: kmem_free <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132409: kfree <-kmem_free
kworker/0:3-1896 [000] .... 369.132410: kmem_free <-xlog_cil_committed
kworker/0:3-1896 [000] .... 369.132410: kfree <-kmem_free
kworker/0:3-1896 [000] .... 369.132411: _raw_spin_lock <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132412: _raw_spin_lock <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132412: xlog_state_clean_log <-xlog_state_do_callback
kworker/0:3-1896 [000] .... 369.132413: __wake_up <-xlog_state_do_callback
python-1907 [000] .... 369.132444: remove_wait_queue <-_xfs_log_force_lsn
python-1907 [000] .... 369.132445: _raw_spin_lock_irqsave <-remove_wait_queue
python-1907 [000] d... 369.132445: _raw_spin_unlock_irqrestore <-remove_wait_queue
python-1907 [000] .... 369.132447: __fsnotify_parent <-vfs_write
python-1907 [000] .... 369.132448: fsnotify <-vfs_write
２０１２年５月 kanda.motohiro@gmail.com