perf interrupt took too long

debian8 のsyslogに以下のメッセージが表示されていた

May  5 21:43:53 hostname kernel: [ 4604.591417] perf interrupt took too long (2510 > 2500), lowering kernel.perf_event_max_sample_rate to 50000

内容

問題ないメッセージらしい
カーネルにperf toolが埋め込まれていて、カーネルは自動的にシステムへの影響を与えない程度のサンプルレートを決める
そのレートを超えたりすると出力される模様
そして、perfがインストールされていなかったり、有効になっていなくてもログとして出力するらしい
perfはおそらくperformance analysis tool(性能解析ツール)のこと

対策

とは言えずっとsyslogに記録されるのは嫌なので、、
perf_cpu_time_max_percent を 25 → 60 にして様子見(0だと無効にできるのでエラーはでなくなる)

root@hostname:/home/shimizu# cat /proc/sys/kernel/perf_event_max_sample_rate
6250
### perf_cpu_time_max_percent ###
### CPU時間をperfのサンプル取得にどれくらい使っていいのか決める。0だと無制限 ###
root@hostname:/home/shimizu# cat /proc/sys/kernel/perf_cpu_time_max_percent
25

### 以下を追加する ###
root@hostname:/home/shimizu# vi /etc/sysctl.conf
===
kernel.perf_cpu_time_max_percent = 60
===
root@hostname:/home/shimizu# vi /etc/sysctl.conf
root@hostname:/home/shimizu# sysctl -p
kernel.perf_cpu_time_max_percent = 60
root@hostname:/home/shimizu# cat /proc/sys/kernel/perf_cpu_time_max_percent
60

perfとは

perf – performance analysis tools for Linux
Linuxに付いてくるプロファイラ

### コマンド一覧を表示 ###
root@hostname:/home/shimizu# perf help

 usage: perf [--version] [--help] COMMAND [ARGS]

 The most commonly used perf commands are:
   annotate        Read perf.data (created by perf record) and display annotated code
   archive         Create archive with object files with build-ids found in perf.data file
...

### 取得できるイベントを表示 ###
root@hostname:/home/shimizu# perf list

List of pre-defined events (to be used in -e):
  cpu-cycles OR cycles                               [Hardware event]
  instructions                                       [Hardware event]
  cache-references                                   [Hardware event]
  cache-misses                                       [Hardware event]
...

### コマンドのパフォーマンスデータを取得する ###
root@hostname:/home/shimizu# perf stat ls
test.txt  test2.txt

 Performance counter stats for 'ls':

          1.946498      task-clock (msec)         #    0.615 CPUs utilized # 利用したCPU時間
                 2      context-switches          #    0.001 M/sec # コンテキストスイッチ数
                 0      cpu-migrations            #    0.000 K/sec # 別のCPUに移動した回数
                96      page-faults               #    0.049 M/sec # page-faults数
         2,408,669      cycles                    #    1.237 GHz # 利用したCPUのクロック数
         1,785,460      stalled-cycles-frontend   #   74.13% frontend cycles idle
         1,053,546      stalled-cycles-backend    #   43.74% backend  cycles idle
         1,248,885      instructions              #    0.52  insns per cycle
                                                  #    1.43  stalled cycles per insn
           248,726      branches                  #  127.781 M/sec
     <not counted>      branch-misses

       0.003166378 seconds time elapsed


### システム全体の情報を取得し確認可能 ###
root@hostname:/home/shimizu# perf record -a
Lowering default frequency rate to 3250.
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate.
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.071 MB perf.data (~3083 samples) ]

root@hostname:/home/shimizu# perf report

### イベントが発生した数を確認可能 ###
root@hostname:/home/shimizu# perf top

参考

Index» Kernel & Hardware» [Solved] dmesg: perf interrupt took too long…
https://bbs.archlinux.org/viewtopic.php?id=187636
perfの使い方
http://int.main.jp/txt/perf/