はじめに
ネットワーク業界においてはいまだ多く使われているSNMPトラップ。
このSNMPトラップを受信するのにsnmptrapd + SNMPTTの鉄板の組み合わせがZabbixなどを始め、よく用いられています1。
今回SNMPトラップを大量に受信する場合に必要なチューニング方法や測定方法を調べたのですが、他にまとまったドキュメントがなかったので記録として記述します。
特にSNMPTTにおいてPREEXECなどでSNMPトラップのフォーマット変換や情報の補完を行う場合もあるかと思います。日本語を含むマルチバイト文字列を含んだSNMPトラップへの対応をサンプルとして、そのようなPREEXECの実装時のチューニングポイントなども合わせて確認していきます。
バージョン情報等々
まず、前提として検証環境の紹介です。本検証はノートPCのLinuxマシン上に立てたVM上で実施しました。
Specは下記の通り、非凡なPCですので下記検証結果の遅延時間や処理時間の絶対値には意味がないとい点をご考慮ください。2
検証Host Machine
- 物理マシン : Lenovo A285
- CPU : AMD Ryzen 3 PRO 2300U
- Memory : 8GB
- OS : Ubuntu 18.04.1 LTS
- Kernel : 4.15.0-43-generic
検証Guest Machine
- Hypervisor: qemu-kvm: 2.11 / libvirt 4.00
- CPU : 1 vCPU (not pinned)
- Memory : 2GB
- OS : Ubuntu 18.04.1 LTS
- Kernel : 4.15.0-45-generic
ソフトウェアバージョン(Guest OS)
- libsnmp-base : 5.7.3
- libsnmp-perl : 5.7.3
- libsnmp30:amd64 : 5.7.3
- snmp : 5.7.3
- snmpd : 5.7.3
- snmptrapd : 5.7.3
- snmptt : 1.4-1
- python3 : 3.6.7
- bash : 4.4.19
- strace : 4.21
インストール方法等については割愛します(apt-getしただけです)。
使用ソフトウェアとSNMPトラップの処理の流れ
まず、前提としてSNMPトラップの処理の流れを簡単に説明しておきます。
今回OSSとしてsnmptrapdとSNMPTTを用います。snmptrapdがSNMPトラップをUDPポート162で受信し、SNMPTTがその受信内容を引継ぎ、Zabbix向けのログ整形および変換、補完処理を行います。
- まずネットワーク上からSNMPトラップ(UDP/ポート162)をOSが受信します
- SNMPトラップはUDPポート162にバインドされている
snmptrapdに渡されます - 後述する
snmptthandler-embeddedを経由しファイルシステム上のspoolファイルに出力されます -
snmpttデーモンが設定された周期でspoolファイルを刈取り、snmptt.confの内容に従い変換等のログ整形処理を行います -
snmpttデーモンにより整形されたメッセージがsnmptt.logに出力されます
+-------------+ +----------+
( 1.snmptrap )---->| 2.snmptrapd +----> [ 3.spool file ] <-----+ 4.snmptt |-------> [ 5.snmptt.log ]
+-------------+ +----------+
以降、Linux OS、snmptrapdおよびSNMPTTの設定を順次説明します。
Linux OSのカーネルパラーメータの設定
OSデフォルトでのUDPの受信バッファサイズが少ないため、大量のSNMPトラップを受信した場合、バッファ溢れによりパケロスを起こします。そのため、バッファサイズをカーネルパラメータより変更します（手元の環境ではデフォルトで212992bytes）。
以下のパラメータを必要に応じて設定を変更します。
必要に応じてsysctl.conf等で永続化します。
/proc/sys/net/core/rmem_default/proc/sys/net/core/rmem_max
# echo $((2 * 1024 * 1024)) >> /proc/sys/net/core/rmem_default
# echo $((2 * 1024 * 1024)) >> /proc/sys/net/core/rmem_max
同じサーバで負荷用にsnmptrapコマンドを送信する場合は以下を合わせて設定
/proc/sys/net/core/wmem_default/proc/sys/net/core/wmem_max
バッファサイズの変更後はsnmptrapdのリスタートを行います。
# systemctl restart snmptrapd
snmptrapdの設定
次にsnmptrapdの設定です。
snmptrapdのアプリケーション設定を記載するsnmptrapd.confとsystemdの設定ファイルsnmptrapd.serviceの設定を変更します。
systemdを用いないでinitを用いるケースやsystemdの設定ファイルのパスの場所が違う場合があります。ご自身のOSバージョンにより適宜読み替えて実施ください
snmptrapd.confの設定変更
/etc/snmp/snmptrapd.conf
disableAuthorization yes
perl do "/usr/lib/snmptt/snmptthandler-embedded"
[snmp]
hexOutputLength 0
コメント行を省略し表示していますが、設定変更箇所は３点のみ、１点目はSNMPトラップの認証をしないという設定ですので必要に応じて設定を入れてください。
ポイントは次の２点
- snmptthandler-embedded
- hexOutputLengh
snmptthandler-embedded
perl do "/usr/lib/snmptt/snmptthandler-embedded"
通常は下記のようにtraphandleの設定を入れ、snmptrapdの後段で処理するプログラムを指定します。しかし、この方法ではトラップの受信毎にforkが走るためオーバヘッドが大きくなり、snmptrapdがシングルプロセスでしか動作しないことも影響し処理速度が稼げない可能性があります。
sample
traphandle default /usr/bin/traptoemail -s smtp.example.org foobar@example.org
これに対してsnmptthandler-embeddedを用いることにより、snmptrapd起動時にperlスクリプトを読み込むため、高速に処理が可能になります3。snmptt.conf内で設定されたディレクトリ(デフォルト/var/spool/snmptt)にSNMPトラップの内容を１トラップ、１ファイルで書き出します。
SNMPトラップのspoolファイルへの書き出し例
/var/spool/snmptt/#snmptt-trap-1551022436502570
1551022436
192.168.122.44
192.168.122.44
.1.3.6.1.2.1.1.3.0 (845666) 2:20:56.66
.1.3.6.1.6.3.1.1.4.1.0 .1.3.6.1.4.1.2054.1.0.3
.1.3.6.1.6.3.18.1.4.0 public
.1.3.6.1.4.1.2054.1.1.1 Hex-STRING: 97 D7 82 CC 8B 71 82 CD
.1.3.6.1.4.1.2054.1.1.2 Hex-STRING: 82 E6 82 AD 8A 60 90 48 82 A4
.1.3.6.1.4.1.2054.1.1.3 Hex-STRING: 8B 71 82 BE
.1.3.6.1.4.1.2054.1.1.4 Hex-STRING: 54 45 53 54 3A 4D 65 73 73 61 67 65 20 90 B6 94 9E 90 B6 95 C4 90 B6 97 91
.1.3.6.1.4.1.2054.1.1.5 1551022436
.1.3.6.1.4.1.2054.1.1.6 "ascii message"
.1.3.6.1.4.1.2054.1.1.7 1
.1.3.6.1.6.3.18.1.3.0 192.168.0.1
.1.3.6.1.6.3.18.1.4.0 "public"
.1.3.6.1.6.3.1.1.4.3.0 .1.3.6.1.4.1.2054.1
.1.3.6.1.6.3.10.2.1.1.0 "0x57e6b6e6f677e6"
.1.3.6.1.6.3.18.1.1.1.3 "unknown"
.1.3.6.1.6.3.18.1.1.1.4 "0x57e6b6e6f677e6"
.1.3.6.1.6.3.18.1.1.1.5 "unknown"
hexOutputLength
[snmp]
hexOutputLength 0
マルチバイト文字列の非ASCII文字列などのOcted-STRINGを扱う上で重要なポイントになるのがhexOutputLengthオプションです。
デフォルトで設定されておらず、これが無いとspoolファイルのHex-STRING出力が下記のように改行されてしまいます。
/var/spool/snmptt/#snmptt-trap-1551022518793398
...omitted...
.1.3.6.1.4.1.2054.1.1.1 Hex-STRING: 97 D7 82 CC 8B 71 82 CD
.1.3.6.1.4.1.2054.1.1.2 Hex-STRING: 82 E6 82 AD 8A 60 90 48 82 A4
.1.3.6.1.4.1.2054.1.1.3 Hex-STRING: 8B 71 82 BE
.1.3.6.1.4.1.2054.1.1.4 Hex-STRING: 54 45 53 54 3A 4D 65 73 73 61 67 65 20 90 B6 94
9E 90 B6 95 C4 90 B6 97 91
.1.3.6.1.4.1.2054.1.1.5 1551022436
.1.3.6.1.4.1.2054.1.1.6 "ascii message"
...omitted...
改行されると、改行された行がOIDが9Eで値が90 B6 95 C4 90 B6 97 91というvariable bindingの一つとSNMPTTにより認識されてしまいます。
その結果、snmptt.conf内の変数取得が失敗します。4
daemon起動パラメータ
デフォルトのままでは未分類のMIB等の扱いが面倒ですので、一律mib変換をかけない方法に変更します。
この処理は必要でなければやる必要は無いかと思いますが、パフォーマンスには多少影響しそうな気はします。5
/lib/systemd/system/snmptrapd.service
[Unit]
Description=Simple Network Management Protocol (SNMP) Trap Daemon.
After=network.target
ConditionPathExists=/etc/snmp/snmptrapd.conf
[Service]
Environment="MIBSDIR=/usr/share/snmp/mibs:/usr/share/snmp/mibs/iana:/usr/share/snmp/mibs/ietf:/usr/share/mibs/site:/usr/share/snmp/mibs:/usr/share/mibs/iana:/usr/share/mibs/ietf:/usr/share/mibs/netsnmp"
Type=simple
#ExecStart=/usr/sbin/snmptrapd -Lsd -f
ExecStart=/usr/sbin/snmptrapd -Lsd -On -f
ExecReload=/bin/kill -HUP $MAINPID
[Install]
WantedBy=multi-user.target
変更箇所は起動パラメータ、-Oオプションを設定し、MIBの変換をかけない設定とします。
ExecStart=/usr/sbin/snmptrapd -Lsd -On -f
参考：MANページ
root@ubuntu:/usr/local/bin# man snmpcmd | grep 'On' -A1
-On Displays the OID numerically:
.1.3.6.1.2.1.1.3.0 = Timeticks: (14096763) 1 day, 15:09:27.63
SNMPTTの設定
最後にSNMPを変換するSNMPTT側の設定です。
SNMPTTにはSNMPTT自身の動作に関わる設定が含まれるsnmptt.iniとSNMPトラップの変換ルールを記載したsnmptt.confの２つの設定ファイルがあります。
ここでは主にsnmptt.iniについての設定をメインで記載します。
snmptt.iniの設定
SNMPTT自体の動作に関する設定です。
コメントはインラインで記載。
/etc/snmp/snmptt.ini
[General]
snmptt_system_name =
# 動作モードをdaemonにしてsystemd等で起動します
mode = daemon
multiple_event = 1
# dnsを使用しないよに設定
dns_enable = 0
strip_domain = 0
strip_domain_list = <<END
domain.com
END
resolve_value_ip_addresses = 0
# mibの解決を実施しないように一律disableに設定
net_snmp_perl_enable = 0
net_snmp_perl_cache_enable = 0
net_snmp_perl_best_guess = 0
translate_log_trap_oid = 0
translate_value_oids = 0
translate_enterprise_oid_format = 0
translate_trap_oid_format = 0
translate_varname_oid_format = 0
translate_integers = 0
wildcard_expansion_separator = " "
allow_unsafe_regex = 0
remove_backslash_from_quotes = 0
dynamic_nodes = 0
description_mode = 0
description_clean = 1
threads_enable = 0
# とりあえず10で設定しますが、増やせばパフォーマンスは若干向上します（パフォーマンス変化は割愛）
threads_max = 10
[DaemonMode]
daemon_fork = 1
daemon_uid = snmptt
pid_file = /var/run/snmptt.pid
spool_directory = /var/spool/snmptt/
# spoolファイルの刈取り速度を指定します、タイムラグと処理負荷から変更すればよいかと思われます。
sleep = 1
use_trap_time = 1
keep_unlogged_traps = 1
duplicate_trap_window = 0
[Logging]
stdout_enable = 0
log_enable = 1
log_file = /var/log/snmptt/snmptt.log
log_system_enable = 1
log_system_file = /var/log/snmptt/snmpttsystem.log
unknown_trap_log_enable = 0
unknown_trap_log_file =
statistics_interval = 0
# /var/log/snmptt/snmptt.logに直接書き出すためにdisable
syslog_enable = 0
syslog_facility = local0
syslog_level_debug = <<END
END
syslog_level_info = <<END
END
syslog_level_notice = <<END
END
syslog_level_warning = <<END
END
syslog_level_err = <<END
END
syslog_level_crit = <<END
END
syslog_level_alert = <<END
END
syslog_level = warning
syslog_system_enable = 0
syslog_system_facility = local0
syslog_system_level = warning
[SQL]
db_translate_enterprise = 0
db_unknown_trap_format = '$-*'
sql_custom_columns = <<END
END
sql_custom_columns_unknown = <<END
END
mysql_dbi_enable = 0
mysql_dbi_host = localhost
mysql_dbi_port = 3306
mysql_dbi_database = snmptt
mysql_dbi_table = snmptt
mysql_dbi_table_unknown = snmptt_unknown
mysql_dbi_table_statistics =
mysql_dbi_username = snmpttuser
mysql_dbi_password = password
mysql_ping_on_insert = 1
mysql_ping_interval = 300
postgresql_dbi_enable = 0
postgresql_dbi_module = 0
postgresql_dbi_hostport_enable = 0
postgresql_dbi_host = localhost
postgresql_dbi_port = 5432
postgresql_dbi_database = snmptt
postgresql_dbi_table_unknown = snmptt_unknown
postgresql_dbi_table_statistics =
postgresql_dbi_table = snmptt
postgresql_dbi_username = snmpttuser
postgresql_dbi_password = password
postgresql_ping_on_insert = 1
postgresql_ping_interval = 300
dbd_odbc_enable = 0
dbd_odbc_dsn = snmptt
dbd_odbc_table = snmptt
dbd_odbc_table_unknown = snmptt_unknown
dbd_odbc_table_statistics =
dbd_odbc_username = snmptt
dbd_odbc_password = password
dbd_odbc_ping_on_insert = 1
dbd_odbc_ping_interval = 300
[Exec]
exec_enable = 1
pre_exec_enable = 1
unknown_trap_exec =
unknown_trap_exec_format =
exec_escape = 1
[Debugging]
DEBUGGING = 0
DEBUGGING_FILE =
DEBUGGING_FILE_HANDLER =
[TrapFiles]
snmptt_conf_files = <<END
/etc/snmp/snmptt.conf
END
snmptt.confの設定
実際にTrapの内容を変換処理を設定するsnmptt.confの内容はこちら。
後ほど、こちらのsnmptt.confを変化させて処理性能を確認します。
/etc/snmp/snmptt.conf
#
#
# 今回のテスト対象はこちら
EVENT OrigTrap .1.3.6.1.4.1.2054.1.0.3 "Orig Trap" Normal
FORMAT ZBXTRAP $aA $5 $p1 ($p2) - $p3 - $p4
SDESC
Test
EDESC
#
#
#
またこのsnmptt.confに対応したSNMPトラップを送出するためのスクリプトは下記の通り。
loopsend.sh
#!/bin/bash
# SNMPトラップで送るメッセージをs-jisでエンコード
MSG1=$(echo '隣の客は' | nkf -s)
MSG2=$(echo 'よく柿食う' | nkf -s)
MSG3=$(echo '客だ' | nkf -s)
MSG4=$(echo 'TEST:Message 生麦生米生卵' | nkf -s)
MSG5=$(echo 'ascii message' | nkf -s)
for i in $(seq $1)
do
#sjisでエンコードされた文字列をverbind,1-4,6に設定
snmptrap -c public -v 1 192.168.122.44 1.3.6.1.4.1.2054.1 '192.168.0.1' 6 3 ''\
1.3.6.1.4.1.2054.1.1.1 s "$MSG1"\
1.3.6.1.4.1.2054.1.1.2 s "$MSG2"\
1.3.6.1.4.1.2054.1.1.3 s "$MSG3"\
1.3.6.1.4.1.2054.1.1.4 s "$MSG4"\
1.3.6.1.4.1.2054.1.1.5 i "$(date +%s)"\
1.3.6.1.4.1.2054.1.1.6 s "$MSG5"\
1.3.6.1.4.1.2054.1.1.7 i "$i"
if [ "$i" == "$(($i % 5))" ]
then
sleep 0.01
fi
done
飛び出し方
# 10トラップを送る場合の例
./loopsend.sh 10
無変換処理時の最大性能
snmptrapdの処理限界
まずはじめにsnmptrapd単体において、秒間に受信、処理（spoolファイルへの書出し）ができる最大値を求めます。
測定方法
-
snmptrapdのpidを調べ、straceでシステムコールをトレースします
strace -ttT -o trace.log -p $(pgrep snmptrapd | awk '{print $2}') - forループを用いてsnmptrapコマンドで大量のSNMPトラップを生成します
(上記スクリプトを参照) - spoolファイルの書き出しのために開かれた
openシステムコールの呼び出し間隔を計測しspoolファイル一つの生成にかかる処理速度を推察します
測定結果
14:49:11.771523 openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 10 <0.000016>
14:49:11.771580 fstat(10, {st_mode=S_IFREG|0644, st_size=715, ...}) = 0 <0.000011>
14:49:11.771631 read(10, "# This file is managed by man:sy"..., 4096) = 715 <0.000021>
14:49:11.771696 read(10, "", 4096) = 0 <0.000011>
14:49:11.771744 close(10) = 0 <0.000011>
14:49:11.771791 uname({sysname="Linux", nodename="ubuntu", ...}) = 0 <0.000010>
14:49:11.771852 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 10 <0.000018>
14:49:11.771909 connect(10, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000021>
14:49:11.771974 close(10) = 0 <0.000015>
14:49:11.772028 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 10 <0.000015>
14:49:11.772096 fstat(10, {st_mode=S_IFREG|0644, st_size=221, ...}) = 0 <0.000011>
14:49:11.772149 read(10, "127.0.0.1 localhost\n\n# The follo"..., 4096) = 221 <0.000012>
14:49:11.772229 read(10, "", 4096) = 0 <0.000010>
14:49:11.772280 close(10) = 0 <0.000011>
14:49:11.772348 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 10 <0.000016>
14:49:11.772402 connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0 <0.000125>
14:49:11.772577 gettimeofday({tv_sec=1551192551, tv_usec=772597}, NULL) = 0 <0.000010>
14:49:11.772630 poll([{fd=10, events=POLLOUT}], 1, 0) = 1 ([{fd=10, revents=POLLOUT}]) <0.000013>
14:49:11.772687 sendto(10, "\332e\1\0\0\1\0\0\0\0\0\1\0011\0010\003168\003192\7in-addr"..., 53, MSG_NOSIGNAL, NULL, 0) = 53 <0.000617>
14:49:11.773376 poll([{fd=10, events=POLLIN}], 1, 5000) = 1 ([{fd=10, revents=POLLIN}]) <0.139815>
14:49:11.913293 ioctl(10, FIONREAD, [53]) = 0 <0.000014>
14:49:11.913370 recvfrom(10, "\332e\201\203\0\1\0\0\0\0\0\1\0011\0010\003168\003192\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 53 <0.000014>
14:49:11.913473 close(10) = 0 <0.000017>
14:49:11.913663 getpid() = 9324 <0.000011>
14:49:11.913718 sendto(8, "<30>Feb 26 14:49:11 snmptrapd[93"..., 665, MSG_NOSIGNAL, NULL, 0) = 665 <0.003715>
14:49:11.921218 gettimeofday({tv_sec=1551192551, tv_usec=921265}, NULL) = 0 <0.000015>
+14:49:11.921353 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551192551921265", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 10 <0.000076>
14:49:11.921495 ioctl(10, TCGETS, 0x7ffcb26a4c30) = -1 ENOTTY (Inappropriate ioctl for device) <0.000011>
14:49:11.921553 lseek(10, 0, SEEK_CUR) = 0 <0.000010>
14:49:11.921600 fstat(10, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000011>
14:49:11.921655 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 <0.000010>
14:49:11.921732 write(10, "1551192551\n192.168.122.44\n192.16"..., 819) = 819 <0.000029>
14:49:11.921807 close(10) = 0 <0.000013>
14:49:11.921894 getpid() = 9324 <0.000010>
14:49:11.921946 sendto(8, "<31>Feb 26 14:49:11 snmptrapd[93"..., 86, MSG_NOSIGNAL, NULL, 0) = 86 <0.000511>
14:49:11.922592 clock_gettime(CLOCK_MONOTONIC, {tv_sec=178572, tv_nsec=90182579}) = 0 <0.000012>
14:49:11.922662 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000015>
14:49:11.922841 clock_gettime(CLOCK_MONOTONIC, {tv_sec=178572, tv_nsec=90425903}) = 0 <0.000011>
14:49:11.922906 clock_gettime(CLOCK_MONOTONIC, {tv_sec=178572, tv_nsec=90484718}) = 0 <0.000010>
14:49:11.922956 clock_gettime(CLOCK_MONOTONIC, {tv_sec=178572, tv_nsec=90534355}) = 0 <0.000010>
14:49:11.923005 select(10, [3 5 7 9], [], [], {tv_sec=4, tv_usec=247822}) = 1 (in [9], left {tv_sec=4, tv_usec=247813}) <0.000019>
14:49:11.923083 recvmsg(9, {msg_name={sa_family=AF_INET, sin_port=htons(46330), sin_addr=inet_addr("192.168.122.44")}, msg_namelen=28->16, msg_iov=[{iov_base="0\201\336\2\1\0\4\6public\244\201\320\6\10+\6\1\4\1\220\6\1@\4\300\250\0"..., iov_len=65536}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("ens3"), ipi_spec_dst=inet_addr("192.168.122.44"), ipi_addr=inet_addr("192.168.122.44")}}], msg_controllen=32, msg_flags=0}, MSG_DONTWAIT) = 225 <0.000017>
14:49:11.923194 getsockname(9, {sa_family=AF_INET, sin_port=htons(162), sin_addr=inet_addr("0.0.0.0")}, [28->16]) = 0 <0.000012>
14:49:11.923262 getpid() = 9324 <0.000009>
14:49:11.923312 openat(AT_FDCWD, "/etc/hosts.allow", O_RDONLY) = 10 <0.000016>
14:49:11.923369 fstat(10, {st_mode=S_IFREG|0644, st_size=411, ...}) = 0 <0.000010>
14:49:11.923421 read(10, "# /etc/hosts.allow: list of host"..., 4096) = 411 <0.000013>
14:49:11.923478 read(10, "", 4096) = 0 <0.000010>
14:49:11.923525 close(10) = 0 <0.000012>
14:49:11.923571 openat(AT_FDCWD, "/etc/hosts.deny", O_RDONLY) = 10 <0.000014>
14:49:11.923624 fstat(10, {st_mode=S_IFREG|0644, st_size=711, ...}) = 0 <0.000012>
14:49:11.923678 read(10, "# /etc/hosts.deny: list of hosts"..., 4096) = 711 <0.000011>
14:49:11.923730 read(10, "", 4096) = 0 <0.000010>
14:49:11.923776 close(10) = 0 <0.000011>
14:49:11.923857 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000013>
14:49:11.923928 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=715, ...}) = 0 <0.000018>
14:49:11.923991 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 10 <0.000014>
14:49:11.924048 fstat(10, {st_mode=S_IFREG|0644, st_size=221, ...}) = 0 <0.000011>
14:49:11.924099 read(10, "127.0.0.1 localhost\n\n# The follo"..., 4096) = 221 <0.000011>
14:49:11.924156 read(10, "", 4096) = 0 <0.000010>
14:49:11.924202 close(10) = 0 <0.000011>
14:49:11.924259 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 10 <0.000020>
14:49:11.924317 connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0 <0.000023>
14:49:11.924383 gettimeofday({tv_sec=1551192551, tv_usec=924399}, NULL) = 0 <0.000010>
14:49:11.924432 poll([{fd=10, events=POLLOUT}], 1, 0) = 1 ([{fd=10, revents=POLLOUT}]) <0.000019>
14:49:11.924651 sendto(10, "\240t\1\0\0\1\0\0\0\0\0\1\0011\0010\003168\003192\7in-addr"..., 53, MSG_NOSIGNAL, NULL, 0) = 53 <0.000365>
14:49:11.925089 poll([{fd=10, events=POLLIN}], 1, 5000) = 1 ([{fd=10, revents=POLLIN}]) <0.035662>
14:49:11.960853 ioctl(10, FIONREAD, [53]) = 0 <0.000014>
14:49:11.960930 recvfrom(10, "\240t\201\203\0\1\0\0\0\0\0\1\0011\0010\003168\003192\7in-addr"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 53 <0.000014>
14:49:11.961023 close(10) = 0 <0.000017>
14:49:11.961163 getpid() = 9324 <0.000010>
14:49:11.961215 sendto(8, "<30>Feb 26 14:49:11 snmptrapd[93"..., 665, MSG_NOSIGNAL, NULL, 0) = 665 <0.000443>
14:49:11.961944 write(1, "90 B6 97 91 \n .1.3.6.1.4.1.2054"..., 8192) = 8192 <0.002536>
14:49:11.968593 gettimeofday({tv_sec=1551192551, tv_usec=970506}, NULL) = 0 <0.003934>
+14:49:11.979258 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551192551970506", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 10 <0.002869>
14:49:11.986858 ioctl(10, TCGETS, 0x7ffcb26a4c30) = -1 ENOTTY (Inappropriate ioctl for device) <0.003390>
14:49:11.994826 lseek(10, 0, SEEK_CUR) = 0 <0.003349>
14:49:12.002884 fstat(10, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.003296>
14:49:12.010784 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 <0.001749>
14:49:12.012837 write(10, "1551192552\n192.168.122.44\n192.16"..., 819) = 819 <0.000031>
14:49:12.012931 close(10) = 0 <0.000013>
上記例ですと、①回目のファイルオープンが11.979258、②回めのファイルオープンが11.921353ですので、間隔は② - ① = 0.057905。1ファイル0.057905のため、逆数を取ると、秒間17.3メッセージを処理_(1/17.3=58.49msecで1メッセージを処理)_していることがわかります。
ちなみに、今回999メッセージを58.44秒で処理されたため、17.1 message / secが最終的な結果でした
SNMPTTの処理限界
次に、SNMPトラップの変換を行わない場合のSNMPTTの処理速度をまず測定し、処理能力の最大値を求めます。
測定方法
- SNMPTTのデーモンを停止し、snmptrapdのみ起動された状態で、snmptrapコマンドを使いspoolディレクトリにspoolファイルを生成します。
- 十分な数のSNMPトラップがspoolディレクトリに溜まったら、spoolファイルを別ディレクトリに移動します
- SNMPTTのデーモンを起動します
- SNMPTTデーモンのpidを調べ、
straceでシステムコールをトレースします
strace -ttT -o trace.log -p $(ps -ef | grep ^snmp | awk '{print $2}') - 移動させたspoolファイルをもとのspoolディレクトリに配置します
- spoolファイルが削除された後、spoolファイルの
unlinkシステムコールの呼び出し間隔を計測しspoolファイル一つにかかる処理速度を推察します
測定結果
実際に実施した場合のstraceの実行結果は下記のようになります。
17:20:10.729948 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551028654059775", O_RDONLY) = 3 <0.000034>
17:20:10.730070 ioctl(3, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000024>
17:20:10.730172 lseek(3, 0, SEEK_CUR) = 0 <0.000023>
17:20:10.730266 fstat(3, {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000024>
17:20:10.730366 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000024>
17:20:10.730538 read(3, "1551028654\n192.168.122.44\n192.16"..., 8192) = 810 <0.000032>
17:20:10.730685 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.730816 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.730948 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.731111 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000030>
17:20:10.731234 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.731376 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.731496 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000027>
17:20:10.731970 read(3, "", 8192) = 0 <0.000026>
17:20:10.733402 openat(AT_FDCWD, "/var/log/snmptt/snmptt.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4 <0.000035>
17:20:10.733526 lseek(4, 0, SEEK_END) = 87705 <0.000023>
17:20:10.733621 ioctl(4, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000022>
17:20:10.733716 lseek(4, 0, SEEK_CUR) = 87705 <0.000022>
17:20:10.733809 fstat(4, {st_mode=S_IFREG|0664, st_size=87705, ...}) = 0 <0.000023>
17:20:10.733909 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000023>
17:20:10.734012 brk(0x55cd822ce000) = 0x55cd822ce000 <0.000028>
17:20:10.734123 write(4, "Sun Feb 24 17:17:34 2019 .1.3.6."..., 299) = 299 <0.000041>
17:20:10.734238 close(4) = 0 <0.000025>
17:20:10.734333 brk(0x55cd822cc000) = 0x55cd822cc000 <0.000035>
17:20:10.734492 close(3) = 0 <0.000026>
17:20:10.734596 lstat("#snmptt-trap-1551028654059775", {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000026>
+17:20:10.734707 unlink("#snmptt-trap-1551028654059775") = 0 <0.000096>
17:20:10.734890 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551028654097076", O_RDONLY) = 3 <0.000036>
17:20:10.735007 ioctl(3, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000022>
17:20:10.735103 lseek(3, 0, SEEK_CUR) = 0 <0.000022>
17:20:10.735196 fstat(3, {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000024>
17:20:10.735299 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000022>
17:20:10.735410 read(3, "1551028654\n192.168.122.44\n192.16"..., 8192) = 810 <0.000030>
17:20:10.735531 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.735656 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.735784 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.735915 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.736035 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.736160 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.736280 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.736728 read(3, "", 8192) = 0 <0.000025>
17:20:10.737824 openat(AT_FDCWD, "/var/log/snmptt/snmptt.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4 <0.000032>
17:20:10.737940 lseek(4, 0, SEEK_END) = 88004 <0.000022>
17:20:10.738034 ioctl(4, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000023>
17:20:10.738130 lseek(4, 0, SEEK_CUR) = 88004 <0.000022>
17:20:10.738222 fstat(4, {st_mode=S_IFREG|0664, st_size=88004, ...}) = 0 <0.000023>
17:20:10.738324 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000022>
17:20:10.738432 write(4, "Sun Feb 24 17:17:34 2019 .1.3.6."..., 299) = 299 <0.000033>
17:20:10.738538 close(4) = 0 <0.000025>
17:20:10.738648 close(3) = 0 <0.000025>
17:20:10.738761 lstat("#snmptt-trap-1551028654097076", {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000027>
+17:20:10.738871 unlink("#snmptt-trap-1551028654097076") = 0 <0.000072>
17:20:10.739030 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551028654128244", O_RDONLY) = 3 <0.000030>
17:20:10.739141 ioctl(3, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000022>
17:20:10.739237 lseek(3, 0, SEEK_CUR) = 0 <0.000022>
17:20:10.739329 fstat(3, {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000024>
17:20:10.739430 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000022>
17:20:10.739538 read(3, "1551028654\n192.168.122.44\n192.16"..., 8192) = 810 <0.000031>
17:20:10.739656 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.739780 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.739905 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.740033 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.740152 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000029>
17:20:10.740276 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000028>
17:20:10.740395 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 <0.000031>
17:20:10.740756 read(3, "", 8192) = 0 <0.000024>
17:20:10.741816 openat(AT_FDCWD, "/var/log/snmptt/snmptt.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4 <0.000032>
17:20:10.741931 lseek(4, 0, SEEK_END) = 88303 <0.000023>
17:20:10.742025 ioctl(4, TCGETS, 0x7ffdabd34fd0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000023>
17:20:10.742122 lseek(4, 0, SEEK_CUR) = 88303 <0.000023>
17:20:10.742214 fstat(4, {st_mode=S_IFREG|0664, st_size=88303, ...}) = 0 <0.000024>
17:20:10.742314 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000023>
17:20:10.742416 write(4, "Sun Feb 24 17:17:34 2019 .1.3.6."..., 299) = 299 <0.000031>
17:20:10.742521 close(4) = 0 <0.000025>
17:20:10.742631 close(3) = 0 <0.000025>
17:20:10.742730 lstat("#snmptt-trap-1551028654128244", {st_mode=S_IFREG|0644, st_size=810, ...}) = 0 <0.000026>
+17:20:10.742840 unlink("#snmptt-trap-1551028654128244") = 0 <0.000068>
強調した行で記載のあるunlinkシステムコールの呼ばれたタイミングが①10.734707、②10.738871、③10.742840の３回であるため各間隔の平均値が0.0040665、1秒間に約245.9回処理_(1/245.9=4.07msecで1メッセージを処理)_が可能であることがわかります。
ちなみに、今回999メッセージを4.047秒で処理されたため、247 message / secが最終的な結果でした
処理限界値の考察結果
以上の結果から、この環境においては、SNMPTTの処理遅延が約58msecを下回らない限り、リアルタイムで処理が可能そうです。また逆の言い方をすると、いくらSNMPTTの処理が高速でも17.1メッセージ毎秒を超えるSNMPトラップはsnmptrapdがボトルネックとなり処理できないことがわかりました。
| Func | 処理速度(Message/sec) | 処理遅延(msec) |
|---|---|---|
| snmptrapd | 17.1 | 58.49 |
| SNMPTT | 247.1 | 4.05 |
＊注釈
なお、ちゃんとしたXeonのサーバで後日計ったところ、より高速に処理できてましたので当然ですがこちらの速度はかなり環境に依存します。
PREEXECの使い方による計算コストの比較
非ASCII文字列がSNMPトラップ上のVariable bindingに乗ってくるため、文字コード変換を行うユースケースを考え、PREEXECの性能に与える影響を検証します。
PREEXECとは
PREEXECはSNMPTTのsnmptt.confに記載される変換ルールの一つです。
PREEXECはFORMATの前に実行するプログラムを指定でき、また引数にSNMPトラップ上のVariable bindingの情報やIPアドレスなどの情報を渡すことができます。
今回はPREEXECにより、Shift-JISで記載されたSNMPトラップのメッセージを変換し、snmptt.logにutf-8で記載する例を考えます。
シェルスクリプトによる比較
複数PREEXECによる計算コスト
まず複数回PREEXECを呼ぶ例を検証します。
# 今回のテスト対象はこちら
EVENT OrigTrap .1.3.6.1.4.1.2054.1.0.3 "Orig Trap" Normal
FORMAT ZBXTRAP $aA $5 $p1 ($p2) - $p3 - $p4
PREEXEC /usr/local/bin/translate.bash "$1"
PREEXEC /usr/local/bin/translate.bash "$2"
PREEXEC /usr/local/bin/translate.bash "$3"
PREEXEC /usr/local/bin/translate.bash "$4"
SDESC
Test
EDESC
呼び出されるシェルスクリプトはこちら。
引数でHex-String: ....を受け取り、16進数表記をxxdを用いてバイナリ化し、nkfを用いて文字コード変換をします。
translate.bash
#!/bin/bash
echo $1 | cut -f2 -d':' | sed -e 's/ //g' | xxd -r -ps | nkf -w
限界性能の検証と同じ方法にてstraceを実施し1トラップの処理にかかる時間を計測します
root@ubuntu:~/snmp# cat $(ls -1rt strace-* | tail -1) |egrep '(snmptt-trap)|(clone)'
12:49:49.257777 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551012588929782", O_RDONLY) = 3 <0.000042>
12:49:49.261868 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5704f1d290) = 7645 <0.000406>
12:49:49.278237 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5704f1d290) = 7655 <0.000282>
12:49:49.287176 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5704f1d290) = 7662 <0.000278>
12:49:49.295916 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5704f1d290) = 7669 <0.000330>
12:49:49.305610 lstat("#snmptt-trap-1551012588929782", {st_mode=S_IFREG|0644, st_size=743, ...}) = 0 <0.000016>
12:49:49.305677 unlink("#snmptt-trap-1551012588929782") = 0 <0.000045>
計測の結果から、openat()システムコールでspool上のtrapファイルを開きunlink()システムコールまでの間にPREEXECの回数分だけclone()システムコールが呼ばれていることがわかります。
こちらのopenat()からunlink()でファイルを削除するまでの所要時間と、clone()でPREEXECで指定されたプログラムが呼ばれた間隔からスクリプト呼び出しと実行のコストを計算した結果が下記の通りです。
所要時間：49.305677 - 49.257777 = 0.0479sec
PREEXECによるスクリプトの処理速度：≒0.01sec
PREEXEC1回による計算コスト
次にPREEXECは一度だけ呼び出し、FORMATで行っていた処理をスクリプトで実施する場合を比較します。
# 今回のテスト対象はこちら
EVENT OrigTrap .1.3.6.1.4.1.2054.1.0.3 "Orig Trap" Normal
FORMAT ZBXTRAP $aA $5 $p1
PREEXEC /usr/local/bin/translate_msg.bash "$1" "$2" "$3" "$4"
SDESC
Test
EDESC
呼び出されるシェルスクリプトはこちら
translate_msg.bash
#!/bin/bash
MSG1=$(echo $1 | cut -f2 -d':' | sed -e 's/ //g' | xxd -r -ps | nkf -w)
MSG2=$(echo $2 | cut -f2 -d':' | sed -e 's/ //g' | xxd -r -ps | nkf -w)
MSG3=$(echo $3 | cut -f2 -d':' | sed -e 's/ //g' | xxd -r -ps | nkf -w)
MSG4=$(echo $4 | cut -f2 -d':' | sed -e 's/ //g' | xxd -r -ps | nkf -w)
echo "$MSG1 ($MSG2) - $MSG3 - $MSG4"
straceの結果
root@ubuntu:~/snmp# cat $(ls -1rt strace-* | tail -1) |egrep '(snmptt-trap)|(clone)'
13:09:58.662443 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551013798110937", O_RDONLY) = 3 <0.000039>
13:09:58.665946 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fdbf4fb1290) = 7821 <0.003125>
13:09:58.702109 lstat("#snmptt-trap-1551013798110937", {st_mode=S_IFREG|0644, st_size=743, ...}) = 0 <0.000028>
13:09:58.702223 unlink("#snmptt-trap-1551013798110937") = 0 <0.000075>
所要時間：58.702223 - 58.662443 = 0.03978sec
PREEXECによるスクリプトの処理速度：≒0.036sec
同様に計算をすると、処理にかかる時間に大きな差は生まれませんでした。
これはプログラムがシェルスクリプトなので、フォークにかかるコストがSNMPTTからシェル側に移動しただけだからだと推察できます。
Pythonによる比較
次に、同様の処理をスクリプト言語であるPythonを使った場合で比較してみます
複数PREEXECによる計算コスト
複数回PREEXECを呼ぶ例
# 今回のテスト対象はこちら
EVENT OrigTrap .1.3.6.1.4.1.2054.1.0.3 "Orig Trap" Normal
FORMAT ZBXTRAP $aA $5 $p1 ($p2) - $p3 - $p4
PREEXEC /usr/local/bin/translate.py "$1"
PREEXEC /usr/local/bin/translate.py "$2"
PREEXEC /usr/local/bin/translate.py "$3"
PREEXEC /usr/local/bin/translate.py "$4"
SDESC
Test
EDESC
呼び出されるシェルスクリプトはこちら
translate.py
#!/usr/bin/python3.6
import sys
print(bytes.fromhex(sys.argv[1][12:]).decode('sjis'))
straceの結果
13:31:17.856971 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551015076969363", O_RDONLY) = 3 <0.000032>
13:31:17.860079 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fec4a3ef290) = 1747 <0.004432>
13:31:17.897331 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fec4a3ef290) = 1749 <0.000404>
13:31:17.932375 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fec4a3ef290) = 1751 <0.000514>
13:31:17.970362 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fec4a3ef290) = 1753 <0.000402>
13:31:18.008341 lstat("#snmptt-trap-1551015076969363", {st_mode=S_IFREG|0644, st_size=742, ...}) = 0 <0.000018>
13:31:18.008551 unlink("#snmptt-trap-1551015076969363") = 0 <0.000070>
シェルスクリプトに比べて非常に低速です。これはPython自体の起動にかかる時間が遅いことが影響しているように見受けられます。
そのため、Forkの回数が増えることによりPythonの起動時間のオーバーヘッドの合計が非常に大きくなっていると考えられます。
所要時間：18.008551 - 17.856971 = 0.151sec
PREEXECによるスクリプトの処理速度：≒0.037sec
PREEXEC1回による計算コスト
次にPREEXECは一度だけ呼び出し、FORMATで行っていた処理をスクリプトで実施する場合を比較します
# 今回のテスト対象はこちら
EVENT OrigTrap .1.3.6.1.4.1.2054.1.0.3 "Orig Trap" Normal
FORMAT ZBXTRAP $aA $5 $p1
PREEXEC /usr/local/bin/translate_msg.py "$1" "$2" "$3" "$4"
SDESC
Test
EDESC
呼び出されるPythonスクリプトはこちら
translate_msg.py
#!/usr/bin/python3.6
import sys
msg=[]
for i in [1,2,3,4]:
msg.append(bytes.fromhex(sys.argv[i][12:]).decode('sjis'))
print("{} ({}) - {} - {}".format(msg[0],msg[1],msg[2],msg[3]))
straceの結果
root@ubuntu:~/snmp# cat $(ls -1rt strace-* |tail -1) | egrep '(snmptt-trap)|(clone)'
16:45:23.587580 openat(AT_FDCWD, "/var/spool/snmptt/#snmptt-trap-1551199522743169", O_RDONLY) = 3 <0.000033>
16:45:23.591057 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f40064d3290) = 17190 <0.000524>
16:45:23.640515 lstat("#snmptt-trap-1551199522743169", {st_mode=S_IFREG|0644, st_size=818, ...}) = 0 <0.000036>
16:45:23.640640 unlink("#snmptt-trap-1551199522743169") = 0 <0.000086>
所要時間：23.64064 - 23.58758 = 0.05306sec
PREEXECによるスクリプトの処理速度：≒0.050sec
複数呼び出しによる起動時間のオーバーヘッドがこちらは劇的に改善しました。
ただ、未だスクリプト起動のオーバーヘッドが遅く、シェルスクリプトに劣ることが見て取れます。
PREEXECの呼び出しに関する結論
上記の結果から、PREEXECの呼び出しはforkシステムコールが走るため大幅に遅くなる傾向があります（1回のPREEXEC呼び出しだけでも4.05ms -> 40msec程度の10倍）。
そのため、パフォーマンスを求める場合はForkのオーバヘッドを考え、むやみにPREEXECを使用するのではなく、PREEXECの呼び出しスクリプトや回数を調整する必要があります。
また、 Pythonではfork後のスクリプト起動にも時間がかかるという点も見受けられたため、必要に応じてスクリプト言語やプログラム言語の選択をするべきであることが見て取れました。
とはいえ、冒頭に示した通り、今回の環境においてはsnmptrapdの1メッセージの処理時間がそもそも58 msecかかるため、今回の単一呼び出し時のPythonスクリプト程度の処理速度では特に問題は発生しないこともわかります。
そのため求める処理性能のボトルネックと移植性やメンテナンス性を考え、スクリプト言語の選択や処理方法の決定をする必要がわかりました。
| Bash(msec) | Python(msec) | |
|---|---|---|
| 複数 PREEXEC | 47.9 | 151.0 |
| 単一 PREEXEC | 39.8 | 53.0 |
まとめ
この他にも諸々のパフォーマンスチューニングポイントは存在するとは思いますが、まずはベーシックなチューニング項目や処理性能測定を実施しました。
結果として、ボトルネックの特定方法と処理の傾向を見て取ることができました。
繰り返しになりますが、どこにボトルネックが来ているかにより処理の戦略は大きく変わるため、まずはそれぞれのコンポーネントの限界性能の測定が第一に必要であるということが見て取れます。