perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog
で Linux カーネル内のボトルネックをマクロに分析する方法を紹介しましたが*1、
システムコールインターフェースとカーネルのブロックレイヤーの中間(ファイルシステムレイヤーなど)で詰まっていると考えられます*3。
このようなケースで、1回のシステムコール発行の所要時間の内訳*4をミクロに追跡するには Brendan Gregg の funcgraph が便利です*5。
実行結果
# ./funcgraph -Htp 4511 vfs_write Tracing "vfs_write" for PID 4511... Ctrl-C to end. # tracer: function_graph # # TIME CPU DURATION FUNCTION CALLS # | | | | | | | | 935.579600 | 3) | vfs_write() { 935.579602 | 3) | rw_verify_area() { 935.579602 | 3) | security_file_permission() { 935.579602 | 3) 0.085 us | cap_file_permission(); 935.579603 | 3) 0.810 us | } 935.579603 | 3) 1.367 us | } 935.579604 | 3) | do_sync_write() { 935.579604 | 3) | pipe_write() { 935.579604 | 3) | mutex_lock() { 935.579604 | 3) 0.044 us | _cond_resched(); 935.579605 | 3) 0.434 us | } 935.579605 | 3) 0.159 us | pipe_iov_copy_from_user(); 935.579606 | 3) 0.097 us | mutex_unlock(); 935.579606 | 3) | __wake_up_sync_key() { 935.579606 | 3) 0.096 us | _raw_spin_lock_irqsave(); 935.579607 | 3) 0.062 us | __wake_up_common(); 935.579607 | 3) 0.070 us | _raw_spin_unlock_irqrestore(); 935.579608 | 3) 1.441 us | } 935.579608 | 3) 0.133 us | kill_fasync(); 935.579609 | 3) | file_update_time() { 935.579609 | 3) | current_fs_time() { 935.579609 | 3) 0.046 us | current_kernel_time(); 935.579610 | 3) 0.048 us | timespec_trunc(); 935.579610 | 3) 0.881 us | } 935.579610 | 3) | mnt_want_write_file() { 935.579611 | 3) 0.257 us | mnt_want_write(); 935.579611 | 3) 0.764 us | } 935.579611 | 3) 0.225 us | __mark_inode_dirty(); 935.579612 | 3) 0.044 us | mnt_drop_write(); 935.579612 | 3) 3.495 us | } 935.579613 | 3) 8.489 us | } 935.579613 | 3) 9.035 us | } 935.579613 | 3) 0.055 us | __fsnotify_parent(); 935.579613 | 3) | fsnotify() { 935.579614 | 3) 0.164 us | __srcu_read_lock(); 935.579614 | 3) 0.044 us | __srcu_read_unlock(); 935.579615 | 3) 1.253 us | } 935.579615 | 3) + 13.624 us | }
手順
# curl -L -O https://raw.githubusercontent.com/brendangregg/perf-tools/master/kernel/funcgraph # chmod u+x funcgraph # mount -t debugfs debugfs /sys/kernel/debug # ps -ef|grep [c]hrome # ./funcgraph -Htp 4511 vfs_write
