LoginSignup
10
1
Cisco Systems JapanAdvent Calendar 2023Day 19
@mekawaba(kawabata megumi)

NSO のパフォーマンスを Jaeger で可視化してみた

Last updated at Posted at 2023-12-18

:santa: 目次

  1. はじめに
  2. NSO の Progress Trace 機能
  3. Progress Trace の分析
  4. Jaeger による Progress Trace の可視化
  5. 最後に
  6. 免責事項

:santa: はじめに

本記事は Cisco の有志による Cisco Systems Japan Advent Calendar 2023 カレンダー2の19日目として投稿しています:christmas_tree::sparkles:

:santa: NSO の Progress Trace 機能

NSO は、 ユーザーからリクエストを受けると、トランザクションと呼ばれる論理単位で一連の処理を実行します。

トランザクションの各ステップでどのくらいの時間がかかっているかを調査する方法として、Progress Trace があります。設定のコミット時に “commit | details” と実行することで、下記のようにトランザクションの各ステップにかかる実際の時間を測定することができます。これにより、最も時間のかかっているステップを特定します。

admin@ncs(config-bgpmgr-xr-1_xr-2)# commit | details verbose

details のあとに、出力の詳細度合いを指定でき、debug > very-verbose > verbose > 指定なし の順番でより詳細に表示されます。この進行状況の追跡にかかるシステムのオーバーヘッドは、通常は無視できる程度です。

バックグラウンドでトランザクションの各動作を記録することも可能です。
まず、”unhide debug” でデフォルトで非表示の progress コマンドを使用できるようにします。

admin@ncs# unhide debug

そして、下記のように、Progress Trace の出力フォーマット (.csv or .log) を設定します。Operational Data としても出力することができます。NSO の Northbound Interface を通じて Trace データを取得する場合に便利です。

admin@ncs(config)# progress trace test
admin@ncs(config-trace-test)# destination file progress-trace.csv format csv
admin@ncs(config-trace-test)# destination file progress-trace.log format log
admin@ncs(config-trace-test)# destination oper-data

保存先は、ncs.conf で指定されたディレクトリ(デフォルトでは他のログファイルと同じ) となります。

ncs.conf の抜粋
    <progress-trace>
      <enabled>true</enabled>
      <dir>./logs</dir>
    </progress-trace>

Trace データは最大 1000 エントリまで記録され、古いデータは順次削除されます。最大サイズの変更や特定デバイス、特定ユーザのトランザクションに限定するといった設定も可能です。詳細は、https://developer.cisco.com/docs/nso/guides/#!progress-trace/progress-trace をご確認ください。

:santa: Progress Trace の分析

下記の Progress Trace の結果を分析し、時間のかかっている処理を特定してみます。

Progress Trace の出力例 
admin@ncs# config t
Entering configuration mode terminal
admin@ncs(config)# bgpmgr xr-1_xr-2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1 xr-1
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1-loop 1.1.1.1
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1-addr 10.2.1.2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2 xr-2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2-loop 2.2.2.2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2-addr 10.2.1.3
admin@ncs(config-bgpmgr-xr-1_xr-2)# as 100
admin@ncs(config-bgpmgr-xr-1_xr-2)# commit dry-run outformat native
native {
    device {
        name xr-1
        data router bgp 100
              bgp router-id 1.1.1.1
              address-family ipv4 unicast
               redistribute connected
              exit
              neighbor 10.2.1.3
               remote-as 100
               address-family ipv4 unicast
               exit
              exit
             exit
    }
    device {
        name xr-2
        data router bgp 100
              bgp router-id 2.2.2.2
              address-family ipv4 unicast
               redistribute connected
              exit
              neighbor 10.2.1.2
               remote-as 100
               address-family ipv4 unicast
               exit
              exit
             exit
    }
}
admin@ncs(config-bgpmgr-xr-1_xr-2)#
admin@ncs(config-bgpmgr-xr-1_xr-2)# commit | details ?
Possible completions:
  debug  verbose  very-verbose  <cr>
admin@ncs(config-bgpmgr-xr-1_xr-2)# commit | details verbose
dry run transaction for running datastore usid=157 tid=831
entering validate phase
 2023-12-18T17:09:53.413 creating rollback checkpoint... ok (0.000 s)
 2023-12-18T17:09:53.414 creating rollback file... ok (0.002 s)
 2023-12-18T17:09:53.416 run pre-transform validation... ok (0.004 s)
 2023-12-18T17:09:53.421 run transforms and transaction hooks...
 2023-12-18T17:09:53.423 taking service write lock... ok (0.000 s)
 2023-12-18T17:09:53.423 holding service write lock...
 2023-12-18T17:09:53.425 service /bgpmgr[name='xr-1_xr-2']: creating service...
 2023-12-18T17:09:53.425 service /bgpmgr[name='xr-1_xr-2']: pre-modification... ok (1.017 s)
 2023-12-18T17:09:54.443 service /bgpmgr[name='xr-1_xr-2']: create... ok (0.012 s)
 2023-12-18T17:09:54.465 service /bgpmgr[name='xr-1_xr-2']: post-modification... ok (0.000 s)
 2023-12-18T17:09:54.465 service /bgpmgr[name='xr-1_xr-2']: creating service: ok (1.040 s)
 2023-12-18T17:09:54.467 run transforms and transaction hooks: ok (1.045 s)
 2023-12-18T17:09:54.467 mark inactive... ok (0.001 s)
 2023-12-18T17:09:54.468 pre validate... ok (0.001 s)
 2023-12-18T17:09:54.469 run validation over the changeset... ok (0.003 s)
 2023-12-18T17:09:54.473 run dependency-triggered validation... ok (0.000 s)
 2023-12-18T17:09:54.473 check configuration policies... ok (0.000 s)
 2023-12-18T17:09:54.474 check for read-write conflicts... ok (0.000 s)
 2023-12-18T17:09:54.475 taking transaction lock... ok (0.000 s)
 2023-12-18T17:09:54.475 holding transaction lock...
 2023-12-18T17:09:54.475 check for read-write conflicts... ok (0.000 s)
 2023-12-18T17:09:54.476 applying service meta-data... ok (0.002 s)
leaving validate phase (1.065 s)
entering write-start phase
 2023-12-18T17:09:54.478 cdb: write-start
 2023-12-18T17:09:54.478 service-manager: write-start
 2023-12-18T17:09:54.479 device-manager: write-start
 2023-12-18T17:09:54.480 cdb: match subscribers... ok (0.000 s)
 2023-12-18T17:09:54.480 cdb: create pre commit running... ok (0.000 s)
 2023-12-18T17:09:54.481 cdb: write changeset... ok (0.001 s)
 2023-12-18T17:09:54.482 check data kickers... ok (0.000 s)
leaving write-start phase (0.004 s)
entering prepare phase
 2023-12-18T17:09:54.483 cdb: prepare
 2023-12-18T17:09:54.490 device-manager: prepare
 2023-12-18T17:09:54.500 device xr-2: calculating southbound diff...
 2023-12-18T17:09:54.500 device xr-1: calculating southbound diff...
 2023-12-18T17:09:54.520 device xr-2: calculating southbound diff: ok (0.020 s)
 2023-12-18T17:09:54.520 device xr-1: calculating southbound diff: ok (0.020 s)
 2023-12-18T17:09:54.521 device xr-2: connect...
 2023-12-18T17:09:54.521 device xr-1: connect...
 2023-12-18T17:09:54.825 device xr-2: connect: ok (0.304 s)
 2023-12-18T17:09:54.838 device xr-1: connect: ok (0.317 s)
 2023-12-18T17:09:54.838 device xr-1: push configuration...
 2023-12-18T17:09:54.838 device xr-2: push configuration...
 2023-12-18T17:09:54.838 device xr-1: initialize...
 2023-12-18T17:09:54.838 device xr-2: initialize...
 2023-12-18T17:09:54.954 device xr-1: initialize: ok (0.115 s)
 2023-12-18T17:09:54.971 device xr-2: initialize: ok (0.132 s)
 2023-12-18T17:09:54.971 device xr-1: prepare...
 2023-12-18T17:09:54.972 device xr-2: prepare... ok (0.473 s)
 2023-12-18T17:09:55.459 device xr-1: prepare: ok (0.487 s)
 2023-12-18T17:09:55.459 device xr-2: commit...
 2023-12-18T17:09:55.459 device xr-1: commit... ok (3.605 s)
 2023-12-18T17:09:59.103 device xr-2: commit: ok (3.643 s)
leaving prepare phase (4.620 s)
entering commit phase
 2023-12-18T17:09:59.103 cdb: commit
 2023-12-18T17:09:59.108 cdb: switch to new running... ok (0.002 s)
 2023-12-18T17:09:59.113 device-manager: commit
 2023-12-18T17:09:59.113 device xr-1: persist...
 2023-12-18T17:09:59.113 device xr-2: persist... ok (0.000 s)
 2023-12-18T17:09:59.113 device xr-2: push configuration: ok (4.275 s)
 2023-12-18T17:09:59.114 device xr-1: persist: ok (0.000 s)
 2023-12-18T17:09:59.114 device xr-1: push configuration: ok (4.275 s)
 2023-12-18T17:09:59.114 device xr-2: get-trans-id...
 2023-12-18T17:09:59.114 device xr-1: get-trans-id... ok (0.128 s)
 2023-12-18T17:09:59.258 device xr-2: get-trans-id: ok (0.143 s)
 2023-12-18T17:09:59.269 holding service write lock: ok (5.846 s)
 2023-12-18T17:09:59.270 holding transaction lock: ok (4.794 s)
leaving commit phase (0.166 s)
dry run transaction for running datastore usid=157 tid=831 (5.857 s)
Commit complete.
admin@ncs(config-bgpmgr-xr-1_xr-2)# end
admin@ncs#

今回 BGP 設定を２台の XR デバイスに対して実施するサービスインスタンスを作成しています。ログの最後に下記のようにトータルでの所要時間が出力され、この時は全ての処理に5.857秒かかったことがわかります。

dry run transaction for running datastore usid=157 tid=831 (5.857 s)

最も時間のかかっている処理は、"push configuration" ですが、これはデバイスへのコンフィグ投入時間となります。Progress Trace に出力される各ステップは、一つ一つ順番に実行しているわけではなく、デバイスへのコンフィグ投入は、下記のステップで２台並行して実施されています。

 2023-12-18T17:09:59.114 device xr-1: push configuration: ok (4.275 s)
 2023-12-18T17:09:59.114 device xr-1: push configuration: ok (4.275 s)

そして、上記の "push configuration" ステップの4.275秒という時間は、その上に表示されている下記のサブステップを含んだ時間となっています。ここを改善したい場合は、デバイスへの投入コンフィグを分割することなどで改善が見込めます。ただし、デバイス側で処理が遅い場合はあまり改善されない可能性がありますので、ご留意ください。

 2023-12-18T17:09:54.838 device xr-1: initialize...
 2023-12-18T17:09:54.838 device xr-2: initialize...
 2023-12-18T17:09:54.954 device xr-1: initialize: ok (0.115 s)
 2023-12-18T17:09:54.971 device xr-2: initialize: ok (0.132 s)
 2023-12-18T17:09:54.971 device xr-1: prepare...
 2023-12-18T17:09:54.972 device xr-2: prepare... ok (0.473 s)
 2023-12-18T17:09:55.459 device xr-1: prepare: ok (0.487 s)
 2023-12-18T17:09:55.459 device xr-2: commit...
 2023-12-18T17:09:55.459 device xr-1: commit... ok (3.605 s)
 2023-12-18T17:09:59.103 device xr-2: commit: ok (3.643 s)

また、"run transforms and transaction hooks (1.045s)" が次に時間を要していますが、これは "creating service (1.040s)" の時間を含み、"creating service (1.040s)" は "pre-modification (1.017s)" のステップを含んでいます。そのため、最下層の pre-modification ステップを改善すると、上位のパフォーマンスが改善されます。

 2023-12-18T17:09:53.425 service /bgpmgr[name='xr-1_xr-2']: creating service...
 2023-12-18T17:09:53.425 service /bgpmgr[name='xr-1_xr-2']: pre-modification... ok (1.017 s)
 2023-12-18T17:09:54.443 service /bgpmgr[name='xr-1_xr-2']: create... ok (0.012 s)
 2023-12-18T17:09:54.465 service /bgpmgr[name='xr-1_xr-2']: post-modification... ok (0.000 s)
 2023-12-18T17:09:54.465 service /bgpmgr[name='xr-1_xr-2']: creating service: ok (1.040 s)
 2023-12-18T17:09:54.467 run transforms and transaction hooks: ok (1.045 s)

例えば、サービスの main.py の pre_modification callback に下記のように sync-from を含む処理を記載していた場合、この pre-modification に時間を要します。sync-from を設定前に実行、もしくは Scheduler での sync-from の定期実行に変更することをお勧めします。

main.py
    @Service.pre_modification
    def cb_pre_modification(self, tctx, op, kp, root, proplist):
         self.log.info('Service premod(service=', kp, ')')
         with ncs.maapi.Maapi() as m:
            with ncs.maapi.Session(m, 'admin', 'python'):
                root = ncs.maagic.get_root(m)
                output = root.devices.sync_from()
                for result in output.sync_result:
                    self.log.info('sync-result {')
                    self.log.info('    device ',result.device)
                    self.log.info('    result ',result.result)
                    self.log.info('}')

このように CLI での Progress Trace の分析も可能ですが、並列処理やステップの階層構造などがわかりずらいと思います。これを Jaeger を用いて可視化をすると、このような問題が解決できます。

:santa: Jaeger による Progress Trace の可視化

Jaeger (イェーガー) とは、マイクロサービス環境のモニタリングを行うための OSS の分散トレースツールです。これを利用して先ほどの Progress Trace を可視化します。方法は下記の通りです。この実行に関して追加のライセンス購入は不要です。

  1. 必要な Python パッケージのインストール
    必要な Python パッケージ (parsedatetime、opentelemetry-exporter-otlp、influxdb) をインストールします。下記に Ubuntu での実行例を記載します。

    $ sudo apt install python3-pip
$ pip install parsedatetime
$ pip install opentelemetry-exporter-otlp
$ pip install influxdb

  2. Observability Exporter Package の読み込み
    Cisco Software Download (https://software.cisco.com/download/home) より、"Cisco NSO Observability-Exporter Package" をダウンロードし、packages フォルダに置き、packages reload で読み込みます。

    image.png


  3. Jaeger のインストール
    Jaeger は NSO が稼働しているサーバにインストールします。https://www.jaegertracing.io/download/ から Jaeger のバイナリをダウンロードします。

    image.png

    そして、下記のように展開し、"jaeger-all-in-one" バイナリに、"--collector.otlp.enabled" オプションをつけて実行します。

    $ tar zxvf jaeger-1.52.0-linux-amd64.tar.gz
$ cd jaeger-1.51.0-linux-amd64
$ ls
example-hotrod  jaeger-agent  jaeger-all-in-one  jaeger-collector  jaeger-ingester  jaeger-query
$ ./jaeger-all-in-one --collector.otlp.enabled

    ブラウザで http://192.168.4.104:16686 にアクセスすると、下記のような画面が表示されます。

    image.png


  4. OTLP (OpenTelemetry Protocol) データエクスポートの有効化
    Jaeger を実行したまま、別のターミナルから NSO CLI にて OTLP データエクスポートを有効にします。
    ”unhide debug” でデフォルトで非表示の progress コマンドを使用できるようにし、下記のように設定を投入します。

    admin@ncs# unhide debug
admin@ncs# config t
Entering configuration mode terminal
admin@ncs(config)# progress export otlp
admin@ncs(config)# commit
Commit complete.

    これで事前準備は完了です。

  5. 設定の投入
    先ほどと同様、BGP設定を２デバイスに投入するサービスインスタンスを作成する設定を投入してみます。

    admin@ncs# config t
Entering configuration mode terminal
admin@ncs(config)# bgpmgr xr-1_xr-2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1 xr-1
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1-loop 1.1.1.1
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev1-addr 10.2.1.2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2 xr-2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2-loop 2.2.2.2
admin@ncs(config-bgpmgr-xr-1_xr-2)# dev2-addr 10.2.1.3
admin@ncs(config-bgpmgr-xr-1_xr-2)# as 100
admin@ncs(config)# commit
Commit complete.

  6. Jaeger の確認

    ブラウザのページを更新、Service に NSO を選択し、Find Traces をクリックします。そうすると、Jeager では、取得したトレースのリストが表示されます。

    image.png

    上記のサービスインスタンス作成のトレースを選択すると、上にトータルの所要時間が表示されます。また、縦に開始から終了までに実行されたステップが順番に記載されており、それぞれ横軸にどの時点からどのくらいの時間その処理が実行されたかがバーで表示されます。そのため、並列処理しているステップや階層化されているステップがわかりやすくなります。

    image.png

    先ほどの push configuration ステップに関して、２デバイスが並行処理されていることがわかります。

    image.png

    また、push configuration が包含しているサブステップに関してもこのように確認できます。

    image.png

    詳細は、下記にも記載されています。

    https://developer.cisco.com/docs/nso/#!observability-exporter/minimal-tracing-example-with-jaeger

:santa: 最後に

今回は、Jaeger による NSO のパフォーマンス可視化を実施してみました。commit に時間がかかるなどパフォーマンスに課題をお持ちの方はぜひこの方法で分析してみてください。

下記の YouTube にて同内容に関する動画が投稿されています。Jaeger のインストールから実際の可視化までを３分半ほどでご紹介する動画となっていますので、ぜひ一度ご覧頂けたらと思います。

また、Cisco Customer Success では、ATX (Ask The Experts) というウェビナーを定期的に開催しています。12月7日に実施した「NSO の運用とメンテナンス」というセッションで今回の内容も含む様々な NSO 運用に役立つ機能をご紹介しました。ぜひ下記の録画と資料もご参照頂けたらと思います。

今後も様々なセッションを予定しています。直近では、2024年1月25日(木) 15:30-16:30 に NSO のスケールアウトと冗長構成の導入方法というセッションを実施予定です。その他のセッションは下記にてスケジュールを公開しております。現在どなたでも無償でご参加頂けます。

:santa: 免責事項

本サイトおよび対応するコメントにおいて表明される意見は、投稿者本人の個人的意見であり、シスコの意見ではありません。本サイトの内容は、情報の提供のみを目的として掲載されており、シスコや他の関係者による推奨や表明を目的としたものではありません。各利用者は、本Webサイトへの掲載により、投稿、リンクその他の方法でアップロードした全ての情報の内容に対して全責任を負い、本Web サイトの利用に関するあらゆる責任からシスコを免責することに同意したものとします。

10
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
10
1