CentOS7のdmesgにperf: interrupt took too longに関するメッセージが出力される


CentOS7で運用しているサーバで「perf: interrupt took too long (3989 > 3933), lowering kernel.perf_event_max_sample_rate to 50000」というような出力が発生しているのに気がついた。

$ dmesg|grep "kernel.perf_event_max_sample_rate"
[ 1502.981806] perf: interrupt took too long (2512 > 2500), lowering kernel.perf_event_max_sample_rate to 79000
[ 2019.987492] perf: interrupt took too long (3147 > 3140), lowering kernel.perf_event_max_sample_rate to 63000
[ 2910.077414] perf: interrupt took too long (3989 > 3933), lowering kernel.perf_event_max_sample_rate to 50000
$

パフォーマンス情報を取得するために、どれくらいの周期でデータを取得したらいいのかは、サーバのハードウェア構成などによって変化するため、自動調整するようになっているようだ。
まずは、長い間隔で収集(サンプリングレート)し、うまくデータが取れていないようだったら、だんだん時間を短縮していく、といことになっている。

journalctlでログから発生時刻を確認する。

# journalctl |grep "perf_event_max_sample_rate"
 2月 27 10:44:11 blog.osakana.net kernel: perf: interrupt took too long (2512 > 2500), lowering kernel.perf_event_max_sample_rate to 79000
 2月 27 10:52:48 blog.osakana.net kernel: perf: interrupt took too long (3147 > 3140), lowering kernel.perf_event_max_sample_rate to 63000
 2月 27 11:07:38 blog.osakana.net kernel: perf: interrupt took too long (3989 > 3933), lowering kernel.perf_event_max_sample_rate to 50000
#

この日は10:19頃にkernelアップデートのため再起動したことにより、サンプリングレートの値が初期化され、調整が必要になったようだ。

過去のログを遡ってみると「perf: interrupt took too long (5208 > 5190), lowering kernel.perf_event_max_sample_rate to 38000」というのが、一番低い値である模様。
最初の変更後の値が79000ということを考えると、起動時の初期値は80000以上だったと思われるので、周期が半分以下となったということである。

さて、kernel.perf_event_max_sample_rateの現在値は「/proc/sys/kernel/perf_event_max_sample_rate」で確認出来る。

# cat /proc/sys/kernel/perf_event_max_sample_rate
50000
#

値を変更する場合は、上記に値を入れる。

恒久的に変更するには、sysctlの設定ファイルを作成する。
CentOS7の場合、/etc/sysctl.d ディレクトリに設定ファイルを作成する。
(/etc/sysctl.confに追加するという手もあるが、今後のパッチで変更される可能性があるため)

まず、現在の設定値を確認

# sysctl -a | grep perf_event_max_sample_rate
kernel.perf_event_max_sample_rate = 50000
#

/etc/sysctl.d/90-local.conf として設定値を入れた設定ファイルを作成

# echo "kernel.perf_event_max_sample_rate = 38000" > /etc/sysctl.d/90-local.conf
# cat /etc/sysctl.d/90-local.conf
kernel.perf_event_max_sample_rate = 38000
#

sysctlの設定をシステムに適用します。

# sysctl --system
* Applying /usr/lib/sysctl.d/00-system.conf ...
* Applying /usr/lib/sysctl.d/50-default.conf ...
kernel.sysrq = 16
kernel.core_uses_pid = 1
net.ipv4.conf.default.rp_filter = 1
net.ipv4.conf.all.rp_filter = 1
net.ipv4.conf.default.accept_source_route = 0
net.ipv4.conf.all.accept_source_route = 0
net.ipv4.conf.default.promote_secondaries = 1
net.ipv4.conf.all.promote_secondaries = 1
fs.protected_hardlinks = 1
fs.protected_symlinks = 1
* Applying /etc/sysctl.d/90-local.conf ...
kernel.perf_event_max_sample_rate = 38000
* Applying /etc/sysctl.d/99-sysctl.conf ...
* Applying /etc/sysctl.conf ...
#

値が変更されたことを確認します。

# sysctl -a | grep perf_event_max_sample_rate
kernel.perf_event_max_sample_rate = 38000
#

2017/03/03追記
kernel.perf_event_max_sample_rate の値を調整した後、現在のところは同じメッセージは出力されていません。

2017/03/22追記
約1ヶ月経過しましたが、出力されていないので、うちの環境では38000で問題ないようです。

Leave a Comment


NOTE - You can use these HTML tags and attributes:
<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>