funcgraph で Linux カーネル内のボトルネックをミクロに追跡する

perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog
Linux カーネル内のボトルネックをマクロに分析する方法を紹介しましたが*1

  • strace でI/Oシステムコールのレスポンスを調べると遅く*2
  • iostat の await でカーネルのブロックレイヤーのI/Oレスポンスを調べると速い場合、

システムコールインターフェースとカーネルのブロックレイヤーの中間(ファイルシステムレイヤーなど)で詰まっていると考えられます*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

*1:カーネル内に限りらずユーザー空間も分析できます

*2:調べ方は strace でシステムコールの所要時間を調べる - ablog 参照

*3:このような分析観点を「挟撃ちの原則」と読んでいます

*4:カーネル内のどの関数がボトルネックになっているか

*5:funcgraph は bash で書かれたシェルスクリプトで内部的には ftrace を使っています