ablog

不器用で落着きのない技術者のメモ

sysのCPU使用率が高い場合にその内訳を調べる方法

Linux

OSレベルで sys のCPU使用率が高い場合に perf*1 を使って、何の処理の割合が高いか調べる方法です。
perf は

  • 特定のプロセスだけでなくOS全体の統計を見れる
  • カーネル（sys）とユーザー（user）の両方を見れる

ところが非常に便利だと思う*2。

準備

$ cat write_loop.c
#include <unistd.h>

int main(void)
{
        while(1) {
                write(1, "foo\n", 4);
        }
}

$ gcc write_loop.c -o write_loop
  • 実行権限を付与する
$ chmod u+x write_loop

検証

$ ./write_loop > /dev/null &
[1] 9188
  • mpstat で CPU 毎の偏りを見る
$ mpstat -P ALL 2 3
Linux 2.6.39-400.17.1.el6uek.x86_64 (yazekats-linux) 12/07/2013      _x86_64_        (4 CPU)

01:02:23 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft %steal  %guest   %idle
01:02:25 PM  all    4.13    0.00   22.28    0.00    0.00    0.00 0.00    0.00   73.59
01:02:25 PM    0   12.06    0.00   87.94    0.00    0.00    0.00 0.00    0.00    0.00 <--CPU番号「0」の %sys が80%以上
01:02:25 PM    1    0.50    0.00    0.50    0.00    0.00    0.00 0.00    0.00   99.00
01:02:25 PM    2    1.50    0.00    0.50    0.50    0.00    0.00 0.00    0.00   97.50
01:02:25 PM    3    2.00    0.00    0.50    0.00    0.00    0.00 0.00    0.00   97.50

01:02:25 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft %steal  %guest   %idle
01:02:27 PM  all    4.12    0.00   22.62    0.12    0.00    0.00 0.00    0.00   73.12
01:02:27 PM    0   11.44    0.00   88.56    0.00    0.00    0.00 0.00    0.00    0.00 <--CPU番号「0」の %sys が80%以上
01:02:27 PM    1    2.50    0.00    0.00    0.00    0.00    0.00 0.00    0.00   97.50
01:02:27 PM    2    1.50    0.00    1.00    0.00    0.00    0.00 0.00    0.00   97.50
01:02:27 PM    3    1.51    0.00    0.50    0.00    0.00    0.00 0.00    0.00   97.99

01:02:27 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft %steal  %guest   %idle
01:02:29 PM  all    4.25    0.00   22.38    0.00    0.00    0.00 0.00    0.00   73.38
01:02:29 PM    0   11.50    0.00   88.50    0.00    0.00    0.00 0.00    0.00    0.00 <--CPU番号「0」の %sys が80%以上
01:02:29 PM    1    1.51    0.00    0.00    0.00    0.00    0.00 0.00    0.00   98.49
01:02:29 PM    2    1.51    0.00    0.50    0.00    0.00    0.00 0.00    0.00   97.99
01:02:29 PM    3    2.00    0.00    0.00    0.00    0.00    0.00 0.00    0.00   98.00

Average:     CPU    %usr   %nice    %sys %iowait    %irq   %soft %steal  %guest   %idle
Average:     all    4.17    0.00   22.43    0.04    0.00    0.00 0.00    0.00   73.36
Average:       0   11.67    0.00   88.33    0.00    0.00    0.00 0.00    0.00    0.00 <--CPU番号「0」の %sys が80%以上
Average:       1    1.50    0.00    0.17    0.00    0.00    0.00 0.00    0.00   98.33
Average:       2    1.50    0.00    0.67    0.17    0.00    0.00 0.00    0.00   97.66
Average:       3    1.84    0.00    0.33    0.00    0.00    0.00 0.00    0.00   97.83
  • perf で CPU番号「0」でCPU使用率が高い関数を調べる
$ perf top -C 0
   PerfTop:    1018 irqs/sec  kernel:90.4%  exact:  0.0% [1000Hz cycles],  (all, CPU: 0)
-----------------------------------------------------------------------------------------------------

             samples  pcnt function                 DSO
             _______ _____ ________________________ _________________________

             1020.00 13.1% vfs_write [kernel.kallsyms] <--writeシステムコールが大量に発行されている兆候が見られる
              993.00 12.8% fget_light [kernel.kallsyms]
              636.00  8.2% audit_syscall_exit [kernel.kallsyms]
              607.00  7.8% system_call [kernel.kallsyms]
              581.00  7.5% __write_nocancel /lib64/libc-2.12.so
              476.00  6.1% system_call_after_swapgs [kernel.kallsyms]
              461.00  5.9% rw_verify_area [kernel.kallsyms]
              407.00  5.2% current_kernel_time [kernel.kallsyms]
              376.00  4.8% audit_syscall_entry [kernel.kallsyms]
              331.00  4.3% fsnotify [kernel.kallsyms]
              276.00  3.5% sys_write [kernel.kallsyms] <--writeシステムコールが大量に発行されている兆候が見られる
              172.00  2.2% sysret_check [kernel.kallsyms]
              156.00  2.0% __srcu_read_unlock [kernel.kallsyms]
              136.00  1.7% security_file_permission [kernel.kallsyms]
              123.00  1.6% unroll_tree_refs [kernel.kallsyms]
              119.00  1.5% __fsnotify_parent [kernel.kallsyms]
              105.00  1.3% path_put [kernel.kallsyms]
               95.00  1.2% __srcu_read_lock [kernel.kallsyms]
               89.00  1.1% kfree [kernel.kallsyms]
               88.00  1.1% __GI___libc_write /lib64/libc-2.12.so
               87.00  1.1% auditsys [kernel.kallsyms]
               78.00  1.0% sysret_signal [kernel.kallsyms]
               64.00  0.8% dput [kernel.kallsyms]
               56.00  0.7% cap_file_permission [kernel.kallsyms]
               55.00  0.7% write_null [kernel.kallsyms]
               53.00  0.7% main /home/yazekats/write_loop
               44.00  0.6% mntput [kernel.kallsyms]
               28.00  0.4% sysret_audit [kernel.kallsyms]

検証環境

$ cat /etc/issue
Oracle Linux Server release 6.4
Kernel \r on an \m

$ uname -a
Linux ****** 2.6.39-400.17.1.el6uek.x86_64 #1 SMP Fri Feb 22 18:16:18 PST 2013 x86_64 x86_64 x86_64 GNU/Linux

参考

関連


追記(2014/04/29):

ソフトウェア開発に愛用している生産性向上ツールを教えてください。デスクトップでは何を使っていますか?
Web ブラウザ (メールや時間つぶし用) だけで、あとは git を使用する端末がいくつかあり、たまには "gitk" ウィンドウで git 履歴ビューを見ます。ふだんは e-メールを読んだり、e-メールで質問に答えたり、ツリーをマージしたり、その結果を調べたりしています。
そのほかによく使うツールは、いつも気にしている負荷 (主にカーネルのコンパイルとか git の作業負荷など) のパフォーマンス プロファイリングを行うための "perf" ツールです。

30人のLinuxカーネル開発者：Linus Torvalds

Linus Torvalds も perf を愛用しているようです。

*1:Linux Kernel 2.6.31以降、Kernel に統合された

*2:特定のプロセスに絞って見ることもできます