EEMポリシー実行時の性能測定と高速化

# はじめに
この記事はシスコの有志による 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](https://www.cisco.com/c/en/us/td/docs/ios-xml/ios/eem/configuration/xe-3s/eem-xe-3s-book/eem-policy-tcl.html) こちらの、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       | 


## 手動で実行するパフォーマンステストスクリプト
<details>
<summary>no_perf_test_init.tcl</summary>
<div>

```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 
}
```
</div>
</details>


## no_perf_test_init.tclから呼び出されるコマンド実行EEMポリシー（性能測定用）

<details><summary>ap_perf_test_base_cpu.tcl</summary><div>

```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
    }
}
}
```
</div></details>


## 設定例

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](https://qiita.com/kikuta2055/items/42526882b57eafe480ad#event_reqinfo-%E3%81%A8%E3%81%AF)なども活用してノイズの少ない書き方を応援したいです。

それっぽいことを書いてきましたが、誰得な一発ネタでした。ここまで読んで頂いて、どうもありがとうございました。

# 参考
[Cisco WAN 実践ケーススタディ – 2008/8/29](https://www.amazon.co.jp/dp/4844326104) ... EEMのことを詳しく書いています。
[Embedded Event Manager Configuration Guide, Cisco IOS XE Release 3S](https://www.cisco.com/c/en/us/td/docs/ios-xml/ios/eem/configuration/xe-3s/eem-xe-3s-book/eem-policy-tcl.html)
[Cisco IOS-XEでルーティングテーブルの変化を捕捉して外部サービスに投稿](https://qiita.com/kikuta2055/items/42526882b57eafe480ad)