はじめに
この記事はシスコの有志による Cisco Systems Japan Advent Calendar 2020 の 日目として投稿しています。
2017年版: https://qiita.com/advent-calendar/2017/cisco
2018年版: https://qiita.com/advent-calendar/2018/cisco
2019年版: https://qiita.com/advent-calendar/2019/cisco
2020年版: https://qiita.com/advent-calendar/2020/cisco
2020年版(2枚目): https://qiita.com/advent-calendar/2020/cisco2
今年は初の二枚目もあって、びっくり！有志すごい！
これはなに？
- Cisco IOS
一発ネタです - tmpsys: 何それ！っていうシスコユーザーに捧げます
- EEMポリシーの秒間実行数を測定できるスクリプト（あなたの環境にも、たぶん入ってます）
- EEMポリシーの実行数を高速化するFast Policy
- ハードウェア間で参考までにCPU性能比較
- EEMによる起動ロジック処理（TclやPython）の、性能試験や比較などに役立つかも
tmpsys: を掘る
10年以上前からくっついてきてる内容なので、ラボの隅っこで腐っている埋もれているIOSルーターやスイッチでも動作確認できると思います。
Cat9200-L#dir ?
/all List all files
/recursive List files recursively
all-filesystems List files on all filesystems
cns: Directory or file name
crashinfo: Directory or file name
flash: Directory or file name
null: Directory or file name
nvram: Directory or file name
system: Directory or file name
tar: Directory or file name
tmpsys: Directory or file name <======これ！これ！
webui: Directory or file name
| Output modifiers
<cr> <cr>
ここに、ライブラリやテンプレート（EEMからメールで送るテンプレファイル）があります。
Cat9200-L#pwd
tmpsys:/lib/tcl/
Cat9200-L#dir
Directory of tmpsys:/lib/tcl/
50 -r-- 18002 <no date> auto.tcl
60 -r-- 2613 <no date> base.tcl
62 -r-- 9371 <no date> base64.tcl
63 -r-- 16923 <no date> cli_lib.tcl
64 -r-- 2589 <no date> context_lib.tcl
3 drw- 0 <no date> eem_scripts <======これ！
67 -r-- 185 <no date> email_template_cfg.tm
68 -r-- 147 <no date> email_template_chs.tm
69 -r-- 154 <no date> email_template_cmd.tm
70 -r-- 156 <no date> email_template_dmp.tm
71 -r-- 144 <no date> email_template_sl.tm
72 -r-- 325 <no date> email_template_sm.tm
73 -r-- 135 <no date> email_template_wd.tm
51 -r-- 9183 <no date> history.tcl
52 -r-- 23558 <no date> http.tcl
56 -r-- 17985 <no date> init.tcl
58 -r-- 6980 <no date> ldAout.tcl
61 -r-- 33266 <no date> optparse.tcl
53 -r-- 19463 <no date> package.tcl
57 -r-- 1062 <no date> parray.tcl
66 -r-- 4823 <no date> parse_lib.tcl
54 -r-- 34061 <no date> safe.tcl
65 -r-- 13768 <no date> smtp_lib.tcl
59 -r-- 14838 <no date> tclIndex
55 -r-- 4547 <no date> word.tcl
No space information available
今日の本題です。
Cat9200-L#dir
Directory of tmpsys:/lib/tcl/eem_scripts/
13 -r-- 7458 <no date> ap_perf_test_base_cpu.tcl <==今日の本題
10 -r-- 12574 <no date> ap_pnp.tcl
17 -r-- 19119 <no date> cl_show_eem_tech.tcl
12 -r-- 3327 <no date> no_perf_test_init.tcl <==今日の本題
14 -r-- 4245 <no date> sl_intf_down.tcl
11 -r-- 6112 <no date> tm_cli_cmd.tcl
15 -r-- 8271 <no date> tm_crash_reporter.tcl
16 -r-- 5464 <no date> tm_fsys_usage.tcl
No space information available
ap_perf_test_base_cpu.tcl と no_perf_test_init.tcl
まず、シスコが公式に提供するEEMスクリプトって、前のプレフィックス（アルファベット二文字）があるんですが、これが何かわかりにくい！しかも定着しなかったし！ということでムズムズするので、今回はここに記載しておきます。二文字で、EEMスクリプトのイベント検出種別（Event Detector）を表してたんですね。古いマニュアルには載ってるのですが...。参考：Embedded Event Manager Configuration Guide, Cisco IOS XE Release 3S こちらの、Table 2 Two-Character Abbreviation Specificationに記載があります。
| プレフィックス | Event Detector |
|---|---|
| ap | event_register_appl |
| cl | event_register_cli |
| ct | event_register_counter |
| go | event_register_gold |
| if | event_register_interface |
| io | event_register_ioswdsysmon |
| la | event_register_ipsla |
| nf | event_register_nf |
| no | event_register_none |
| oi | event_register_oir |
| pr | event_register_process |
| rf | event_register_rf |
| rs | event_register_resource |
| rt | event_register_routing |
| rp | event_register_rpc |
| sl | event_register_syslog |
| sn | event_register_snmp |
| st | event_register_snmp_notification |
| so | event_register_snmp_object |
| tm | event_register_timer |
| tr | event_register_track |
| ts | event_register_timer_subscriber |
| wd | event_register_wdsysmon |
手動で実行するパフォーマンステストスクリプト
no_perf_test_init.tcl
::cisco::eem::event_register_none
#------------------------------------------------------------------
# EEM policy used for measuring the cpu performance of EEM policies.
#
# October 2006, Cisco EEM team
#
# Copyright (c) 2006 by cisco Systems, Inc.
# All rights reserved.
#------------------------------------------------------------------
###
### Input arguments: none
###
### The following EEM environment variables are used: none
###
### Environment variables are used by the policies invoked from this script.
### Typically:
### _perf_iterations is used set the iteration count for the policy.
### _perf_cmd1, _perf_cmd2, _perf_cmd3 are used to specify
### optional commands to be executed as part of the test.
### See ap_perf_test_base_cpu.tcl for a more thorough explanation.
###
### Description:
### Script used to launch policy performance tests.
### Policies are passed 1 input:
### a beginning iteration count set to 0
###
### Outputs:
### Console output via activated policies.
###
### Usage Example:
### For this example we will use the cpu usage test.
###
### >conf t
### >service timestamps log datetime msec
### >event manager environment _perf_iterations 100
### >event manager environment _perf_cmd1 show int counters protocol status
### >event manager policy ap_perf_base_cpu.tcl
### >event manager policy no_perf_test_init.tcl
### >end
### Oct 16 14:57:17.284: %SYS-5-CONFIG_I: Configured from console by console
### >event manager run no_perf_test_init.tcl
###
### Oct 16 14:57:17.284: %SYS-5-CONFIG_I: Configured from console by console
### >event manager run no_perf_test_init.tcl
###
### Oct 16 19:32:02.772: %HA_EM-6-LOG:
### eem_policy/no_perf_test_init.tcl: EEM performance test start
### Oct 16 19:32:03.115: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 1
### Oct 16 19:32:03.467: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 2
### ...
### Oct 16 19:32:36.936: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 100
### Oct 16 19:32:36.936: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test end
###
### The user must calculate execution time and average time of execution.
### In this example, total time = 19:32:36.936 - 19:32:02.772 = 34.164
### Average script execution time = 341.64 milliseconds
###
namespace import ::cisco::eem::*
namespace import ::cisco::lib::*
# query the event info
array set arr_einfo [event_reqinfo]
if {$_cerrno != 0} {
set result [format "component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
action_syslog priority info msg "EEM performance test start"
if {$_cerrno != 0} {
set result [format \
"component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
# cause the first iteration to run
event_publish sub_system 798 type 9999 arg1 0
if {$_cerrno != 0} {
set result [format \
"component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
no_perf_test_init.tclから呼び出されるコマンド実行EEMポリシー（性能測定用）
ap_perf_test_base_cpu.tcl
::cisco::eem::event_register_appl sub_system 798 type 9999 maxrun 0
#------------------------------------------------------------------
# EEM policy used for measuring the cpu performance of EEM policies.
#
# July 2005, Cisco EEM team
#
# Copyright (c) 2005-2008 by cisco Systems, Inc.
# All rights reserved.
#------------------------------------------------------------------
###
### Input arguments:
###
### arg1 $iter - current iteration count
###
### The following EEM environment variables are used:
###
### _perf_iterations (mandatory) - number of iterations over which we
### will run our measurement.
###
### _perf_fast (optional) - if set to any value run this policy
### in high performance mode.
### _perf_fast_no_refresh (optional)
### - if _perf_fast is set, set this to
### any value and environment variables
### will not be refreshed. By default they
### will be refreshed upon each event
### iteration.
### Example:
### event manager environment _perf_iterations 100
###
### _perf_cmd1 (optional) - optional non interactive cli command
### to be executed as part of the
### measurement test.
### Example:
### event manager environment _perf_cmd1 enable
###
### _perf_cmd2 (optional) - optional non interactive cli command
### to be executed as part of the
### measurement test.
### To use _perf_cmd2, _perf_cmd1 MUST
### be defined.
### Example:
### event manager environment _perf_cmd2 show ver
###
### _perf_cmd3 (optional) - optional non interactive cli command
### to be executed as part of the
### measurement test.
### To use _perf_cmd3, _perf_cmd1 MUST
### be defined.
### Example:
### event manager environment _perf_cmd3 show int counters protocol status
###
### Description:
### Iterate through _perf_iterations of this policy.
### It is up to the user to calculate the average
### execution time based on the system timestamps.
### Optional commands _perf_cmd1,
### _perf_cmd2 and _perf_cmd3 are executed if defined.
###
### A value of 100 is a good starting point.
###
### Outputs:
### Console output.
###
### Usage example:
### >conf t
### >service timestamps debug datetime msec
### >event manager environment _perf_iterations 100
### >event manager policy ap_perf_base_cpu.tcl
### >event manager policy no_perf_test_init.tcl
### >end
### 2d19h: %SYS-5-CONFIG_I: Configured from console by console
### >event manager run no_perf_test_init.tcl
###
### Oct 16 14:57:17.284: %SYS-5-CONFIG_I: Configured from console by console
### >event manager run no_perf_test_init.tcl
###
### Oct 16 19:32:02.772: %HA_EM-6-LOG:
### eem_policy/no_perf_test_init.tcl: EEM performance test start
### Oct 16 19:32:03.115: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 1
### Oct 16 19:32:03.467: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 2
### ...
### Oct 16 19:32:36.936: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test iteration 100
### Oct 16 19:32:36.936: %HA_EM-6-LOG:
### eem_policy/ap_perf_test_base_cpu.tcl: EEM performance test end
###
### The user must calculate execution time and average time of execution.
### In this example, total time = 19:32:36.936 - 19:32:02.772 = 34.164
### Average script execution time = 341.64 milliseconds
###
# check if all the env variables we need exist
# If any of them doesn't exist, print out an error msg and quit
if {![info exists _perf_iterations]} {
set result \
"Policy cannot be run: variable _perf_iterations has not been set"
error $result $errorInfo
}
# ensure our target iteration count > 0
if {$_perf_iterations <= 0} {
set result \
"Policy cannot be run: variable _perf_iterations <= 0"
error $result $errorInfo
}
if {[info exists _perf_fast_no_refresh]} {
set refresh_vars 0
} else {
set refresh_vars 1
}
namespace import ::cisco::eem::*
namespace import ::cisco::lib::*
set done 0
while { $done == 0 } {
# query the event info
array set arr_einfo [event_reqinfo]
if {$_cerrno != 0} {
set result [format "component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
set iter $arr_einfo(data1)
set iter [expr $iter + 1]
# if _perf_cmd1 is defined
if {[info exists _perf_cmd1]} {
# open the cli library
if [catch {cli_open} result] {
error $result $errorInfo
} else {
array set cli1 $result
}
# execute the comamnd defined in _perf_cmd1
if [catch {cli_exec $cli1(fd) $_perf_cmd1} result] {
error $result $errorInfo
}
# if _perf_cmd2 is defined
if {[info exists _perf_cmd2]} {
# execute the comamnd defined in _perf_cmd2
if [catch {cli_exec $cli1(fd) $_perf_cmd2} result] {
error $result $errorInfo
} else {
set cmd_output $result
}
}
# if _perf_cmd3 is defined
if {[info exists _perf_cmd3]} {
# execute the comamnd defined in _perf_cmd3
if [catch {cli_exec $cli1(fd) $_perf_cmd3} result] {
error $result $errorInfo
} else {
set cmd_output $result
}
}
# close the cli library
if [catch {cli_close $cli1(fd) $cli1(tty_id)} result] {
error $result $errorInfo
}
}
# log a message
set msg [format "EEM performance test iteration %s" $iter]
action_syslog priority info msg $msg
if {$_cerrno != 0} {
set result [format "component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
# use the context info from the previous run to determine when to end
if {$iter >= $_perf_iterations} {
#log the final messages
action_syslog priority info msg "EEM performance test end"
if {$_cerrno != 0} {
set result [format \
"component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
exit 0
}
# cause the next iteration to run
event_publish sub_system 798 type 9999 arg1 $iter
if {$_cerrno != 0} {
set result [format \
"component=%s; subsys err=%s; posix err=%s;\n%s" \
$_cerr_sub_num $_cerr_sub_err $_cerr_posix_err $_cerr_str]
error $result
}
if {[info exists _perf_fast]} {
event_completion status 0
if {$iter < $_perf_iterations} {
array set _event_state_arr [event_wait refresh_vars $refresh_vars]
if {$_event_state_arr(event_state) != 0} {
exit 0
}
} else {
set done 1
}
} else {
set done 1
}
}
}
設定例
100回のEEMポリシーをどれくらいの速度で実行できるかを測定します。
event manager environment _perf_iterations 100 <===== ポリシー数
event manager environment _perf_cmd1 show ip int brief <===== ポリシーの中で実行するコマンド（任意）
event manager policy no_perf_test_init.tcl <===== スクリプトの登録（メモリ上に展開）
event manager policy ap_perf_test_base_cpu.tcl <===== スクリプトの登録（メモリ上に展開）
実行例
Cat9200-L#terminal monitor
Cat9200-L#
Cat9200-L#even manager run no_perf_test_init.tcl
Cat9200-L#
Dec 2 12:36:37.103: %HA_EM-6-LOG: no_perf_test_init.tcl: EEM performance test start
Dec 2 12:36:37.684: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 1
Dec 2 12:36:38.299: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 2
Dec 2 12:36:38.912: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 3
<snip>
Dec 2 12:37:37.713: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 98
Dec 2 12:37:38.331: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 99
Dec 2 12:37:38.948: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 100
Dec 2 12:37:38.948: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test end
(12:37:38.948 - 12:36:37.103)/100 = 61.845秒/100 = ポリシーあたり0.62秒くらいです。
Fast Policyの設定をOnにして、ぶん回します。
Cat9200-L(config)#event manager environment _perf_fast 1
再チャレンジ。
Cat9200-L#even manager run no_perf_test_init.tcl
Cat9200-L#
Dec 2 12:42:21.784: %HA_EM-6-LOG: no_perf_test_init.tcl: EEM performance test start
Dec 2 12:42:22.367: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 1
<snip>
Dec 2 12:42:55.051: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test iteration 100
Dec 2 12:42:55.051: %HA_EM-6-LOG: ap_perf_test_base_cpu.tcl: EEM performance test end
(12:42:55.051 - 12:42:21.784)/100 = 33.267秒/100 = ポリシーあたり0.33秒くらいです。だいたい二倍速になりました！
比較
手元にある装置で条件を揃えて比較してみました。
- コンフィグは上記と同じ
- 100ポリシーを実行、show ip int briefを行う
- コマンド実行有り（_perf_cmd1 show ip int brief）, Fast policyオプション（_perf_fast）をオン
- コマンド実行無し, Fast policyオプション（_perf_fast）をオン
- コマンド実行無し, , Fast policyオプション（_perf_fast）をオフ
- IOSバージョンは本来可能な限り揃えるべきですが、ネタ記事のため雑なままです
- 本来はそれぞれの測定につき数回テストを行って平均を取るべきですが、ネタ記事のため一発ぽんです
- CPU割り込み処理などをなくした状態でテストを行うべきですが、ネタ記事のためコンフィグをお掃除してないままテストしてます😢
結果
| 装置 | バージョン | 100ポリシー（秒）, CLIあり | 100ポリシー（秒）, CLIなし | Fast Policyなし, CLIなし |
|---|---|---|---|---|
| C9200L-24P-4G | 16.12.3 | 33.267 | 0.540 | 22.068 |
| C9300-24P | 17.03.02a | 32.131 | 0.142 | 6.821 |
| Cisco C1111-4P | 16.11.1a | 33.737 | 0.398 | 13.354 |
| Cisco4331 | 16.12.04 | 32.519 | 0.416 | 14.875 |
| C9120AXI-Q(EWC) | 17.03.01 | 36.093 | 1.435 | 74.977 |
興味深い！
考察
- 今更ながら、Fast Policyは効果がある
- EEMポリシーにて、CLIを実行するのは、CPU的にはかなり負担が高い
- 装置の型番とCPU/EEMポリシーの処理能力は、一部を除き比例している
まとめ
冬のネタ記事のつもりで書き始めましたが、やってみると散々使ってきたEEMのCLIアクションは、やはりCPU的には負担が高かったんですね。だから、モデルドリブンなNetconfのネイティブな実装を進める必要がある、と納得感がもてる実験にもなりました（だいぶ飛躍）。ローレベルでみると、SSHでコマンドをひたすら実行するツールなんかも人気がありますが、長い目で見ればネットワーク装置にとって負担を減らす（ひいては低価格化、省エネ化）ことに貢献する実装を応援していきたいです（Netconfでやったらもっと高速に実行できる、という勝手な仮説で書いてますがｗｗｗまぁアプリ層からみたら低速になるかもしれないけど、装置内では省エネ化はできそう）。EEM的にも、アクションでCLIを実行して正規表現で取り出すなど普通にやりがち（散々やってきました）ですが、もっともっとevent_reqinfoなども活用してノイズの少ない書き方を応援したいです。
それっぽいことを書いてきましたが、誰得な一発ネタでした。ここまで読んで頂いて、どうもありがとうございました。
参考
Cisco WAN 実践ケーススタディ – 2008/8/29 ... EEMのことを詳しく書いています。
Embedded Event Manager Configuration Guide, Cisco IOS XE Release 3S
Cisco IOS-XEでルーティングテーブルの変化を捕捉して外部サービスに投稿