はじめに

この記事は2022年CiscoSystems合同会社社員有志による Advent Calendar の記事の一つです。

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
2021年版: https://qiita.com/advent-calendar/2021/cisco
2021年版(2枚目): https://qiita.com/advent-calendar/2021/cisco2
2022年版: https://qiita.com/advent-calendar/2022/cisco

NSO 6.0 での新機能

これまでの NSO 4.x/5.x では、複数のトランザクションを投入した場合に、他のトランザクションを待ち続けるということが発生し、トランザクション処理のスループットが低下するということが発生していました。共有リソース (CDB の同じノード)への書き込みによって、意図しないデータが記録される場合があるため、このようなシリアライズ処理が必要でした。

NSO 6.0 では、複数のトランザクションを同時に実行することで処理スループットを上げることが出来るようになりました。これによって複数のトランザクションが同じノードへ書き込みが可能となりますが、一方でそのデータへの一貫性が失われてしまいます。そこで、NSO のトランザクションエンジンは読み込みを監視することで、書き込まれるデータが他のトランザクションのデータと競合する場合にはそれを検知することが出来るようになっています。Conflict 状態が検知された場合は自動的にトランザクションを再実行します。

NSO 5.x でのトランザクション

トランザクションの開始

ユーザはサービスパッケージを作成し、それをトランザクションから実行することが出来ます。サービスインスタンスの内容を入力し、commit コマンドを入力した際に上記フローが開始します。RESTCONF から実行する場合は、自動的にこれが開始します。

Critical Section は必ず直列的に実行されます。並列処理がされず、複数の Transaction が入力された場合は、逐次処理がされます。

onCreate メソッド

サービスコードには FASTMAP アルゴリズムを実装しますが、それは onCreate メソッドに作られます。トランザクション実行時には、Transaction Lockを取得完了し Critical Section に入った後、Hook 実行時にそれらが呼ばれ、サービスによって変更されるConfigの差分が作成されます。

この部分を如何に短い時間で終了させられるかということが重要ですが、ソフトウェア設計であったり、必要な処理にどうしても時間がかかる場合などもあり、短くすることが出来ないこともあります。

Prepare フェーズ

cisco-ios NED や cisco-iosxr NED など、CLI/Generic NED では Prepare フェーズにおいて実機へ設定が送られ即有効となります。接続の遅延や帯域、機器の反応速度などによっては、非常に長い時間がかかる場合があります。

問題点

トランザクションがロックされた上で実行されるこれらの動作が開始するためには新たにロックの確保が必要ですので、他のトランザクションが Critical Secion 内のステップを実行するためには待機する必要があります。例えば一つ10秒の処理がかかるトランザクションを 100個同時に実行する場合は、一つずつ順に実行されるため、完了までに 10 x 100 = 1000 秒かかります。つまり、100 番目のトランザクションは 990 秒待つ必要があります。

NSO 6.x でのトランザクション

NSO 6.0 での変更点

NSO 6.0 では、上記のように Transaction Hook や Validate がロックから外れました。つまり、これらのフェーズは複数の Transaction 実行時にも、同時に実行されます。これにより onCreate で実行に時間がかかる場合でも、全体としての処理時間を短くすることができるようになっています。つまり、スループットの向上が見込めます。

処理速度の向上がされたわけではありませんので、ご注意ください。処理速度の向上のためには、アルゴリズムの改良を行う他、実装されているCPUを高速なものに変更するといったことが必要です。

問題点

トランザクション処理がロックの外で行われるため、その計算内容が他のリソースに依存する場合に問題が発生することがあります。データベース内の値をインクリメントする処理について見てみましょう。

この例では Transaction 1 と Transaction 2 がそれぞれカウンタをインクリメントしているため、CDB上のデータは 3 とならなければいけません。

後から実行された Transaction 2 は Critical Section 外で実行されているため、Transaction 1 がCDB を更新したことを知らず、そのままデータをセットしています。Transaction 2 が、Transaction 1 も同じデータを更新することを知っていれば、やり直しが出来たのですが。

これが Transaction Critical Section 外で処理を行うことの弊害となります。

問題に対する対応

NSO 6.x では、トランザクション中に CDB から Maapi でデータを読み込む動作について全て記録し、他のトランザクションが同じノードにデータを書く際、競合が発生していると判断します。この例では、Transaction 2 がカウンタをインクリメントし書き込む際に、NSO は Transaction 1 がそのデータを読み込み作業をしたということを知っているため、CONFLICT エラーを発生させます。

CONFLICT エラーが発生した場合は、状況によって、そのトランザクションは自動的に再実行されます。詳細は後の節を確認してください。

データを読み込む動作が CONFLICT の原因となりますので、不要な読み込みは行わないようにする必要があります。Debug　のために、本来処理とは不要な読み込みを行なっていることが多々ありますが、それらについては NSO 6.x では削除が必要です。

Validate フェーズでは、xpath を使った must/when 節や valication call-point を使用した validation コードによって、生成された Config の正当性が確認されます。この時 xpath が参照先のノード情報を読み込みますので、それもCONFLICT の原因となることに注意してください。

パッケージ開発時における注意点

サービスインスタンス作成時に、複数の Java/Python スレッドが同時に動作します。つまりアプリケーション (create callback) はスレッドセーフである必要があり、例えばクラスフィールドの参照・書き込みなどを行なっている場合は問題となり得ます。

dry-run の同時実行

NSO ではトランザクションを commit する前に、commit dry-run というコマンドにより、実際に実行せずに結果だけ確認するということができます。これは Validate フェーズまで実行し、その後Abortさせるという動作をしますので、NSO 5.x においては Critical Section の実行が発生します。つまり、commit dry-run を実行中は、他の Transaction はそれが完了するまで待つ必要があります。

NSO 6.x では、Validate フェーズ実行までは Critical Section 外で実施されますので、commit dry-run が他の Transaction へ影響することが無くなりました。

CONFLICT の発生と再実行（リトライ）

Transaction が Commit される際、Critical Section に入る前の Transaction Checkpoints として、5つのステップが定義されています。いずれかのステップで CONFLICT が検出された場合に、再実行が発生する際、毎度 Work ステップまで戻るのではなく、CONFLICT が発生したステップまで戻り、再度実行されます。

ただし、Work ステップは transaction apply される前となるため、NSO によって自動的に再実行はされず、その Transaction は Abort されます。自動再実行したい場合は、以下の Maapi API　を使用して再実行を行うような動作とすることが可能です。

Python
Maapi.run_with_retry()
Java
Maapi.ncsRunWithRetry()

サンプルコード

以下は製品に添付されているマニュアルより抜粋しています。root.mysvc_cns を読み込んでいます (内部的には get_elem 関数)。t.apply() が実行される直前に他のトランザクションが同じ読み込みを行なった場合、そのトランザクションは CONFLICT となります。

with ncs.maapi.single_write_trans('admin', 'system') as t:
 root = ncs.maagic.get_root(t)
 # Read a value that can change during this transaction
 dns_server = root.mysvc_dns
 # Now perform complex work... or time.sleep(10) for testing
 # Finally, write the result
 root.some_data = 'the result'
 t.apply()

Device Lock

一つの Transaction が Device A を変更する場合、Device B をロックすることがなくなりました。
つまり、その Transaction が Device A の設定を行なっている最中に、別の Transaction が Device B の設定を行うことができます。ただし、この場合でも Transaction 間で何らかの依存関係がある場合は、上で説明した CONFLICT が発生する可能性がありますので、それらの処理によっては待機が発生することはあります。

スループット向上のテスト

NSO 6.0 で変更された Critical Section の扱いの違いについて、同じテストを NSO 5.8 と NSO 6.0 で実行してみます。

create に時間のかかるサービスパッケージ test1 を以下のように作成しました。
実際に diff は作成しませんが、かならず　10 秒処理に時間がかかります。
このサービスでは、特にパラメータを使用していません。

class ServiceCallbacks(Service):
    @Service.create
    def cb_create(self, tctx, root, service, proplist):
        time.sleep(10)

このサービスのインスタンスを同時に 10 個作成します。

ランチャースクリプト

$ cat test.sh
for i in `seq 10`
do
CONFIG="
<config xmlns=\"http://tail-f.com/ns/config/1.0\">
  <test1 xmlns=\"http://example.com/test1\">
    <name>$i</name>
  </test1>
</config>
"
echo "Loading config for $i $(date)"
echo $CONFIG | ncs_load -lm &
done

NSO 5.8 でのテスト

同時にトランザクションが開始していますが、それぞれを直列に一つずつ実行するため、その完了までにかかる時間が 10x10=100 秒かかっています。実際のユースケースとしては、例えば RESTCONF で NMS などから同時に NSO Northbound API へアクセスがあった場合等、二つ目以降のリクエストは前のリクエストが完了するまで待つ必要があります。

実行

$ sh test.sh
Loading config for 1 Sun Dec 11 02:37:36 JST 2022
Loading config for 2 Sun Dec 11 02:37:36 JST 2022
Loading config for 3 Sun Dec 11 02:37:36 JST 2022
Loading config for 4 Sun Dec 11 02:37:36 JST 2022
Loading config for 5 Sun Dec 11 02:37:36 JST 2022
Loading config for 6 Sun Dec 11 02:37:36 JST 2022
Loading config for 7 Sun Dec 11 02:37:36 JST 2022
Loading config for 8 Sun Dec 11 02:37:36 JST 2022
Loading config for 9 Sun Dec 11 02:37:36 JST 2022
Loading config for 10 Sun Dec 11 02:37:36 JST 2022

devel.log

<INFO> 11-Dec-2022::02:37:37.332 ncs progress usid=50 tid=51 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.332 ncs progress usid=45 tid=48 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.335 ncs progress usid=41 tid=42 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.335 ncs progress usid=47 tid=45 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.335 ncs progress usid=43 tid=44 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.336 ncs progress usid=46 tid=49 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.336 ncs progress usid=44 tid=47 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.337 ncs progress usid=42 tid=43 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.337 ncs progress usid=48 tid=46 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:37.337 ncs progress usid=49 tid=50 datastore=running context=system applying transaction
<INFO> 11-Dec-2022::02:37:47.539 ncs progress usid=50 tid=51 datastore=running context=system applying transaction: ok (10.205 s)
<INFO> 11-Dec-2022::02:37:57.576 ncs progress usid=45 tid=48 datastore=running context=system applying transaction: ok (20.242 s)
<INFO> 11-Dec-2022::02:38:07.861 ncs progress usid=41 tid=42 datastore=running context=system applying transaction: ok (30.492 s)
<INFO> 11-Dec-2022::02:38:17.861 ncs progress usid=47 tid=45 datastore=running context=system applying transaction: ok (40.651 s)
<INFO> 11-Dec-2022::02:38:27.936 ncs progress usid=43 tid=44 datastore=running context=system applying transaction: ok (50.709 s)
<INFO> 11-Dec-2022::02:38:37.984 ncs progress usid=46 tid=49 datastore=running context=system applying transaction: ok (60.652 s)
<INFO> 11-Dec-2022::02:38:48.035 ncs progress usid=44 tid=47 datastore=running context=system applying transaction: ok (70.699 s)
<INFO> 11-Dec-2022::02:38:58.084 ncs progress usid=42 tid=43 datastore=running context=system applying transaction: ok (80.748 s)
<INFO> 11-Dec-2022::02:39:08.198 ncs progress usid=48 tid=46 datastore=running context=system applying transaction: ok (90.862 s)
<INFO> 11-Dec-2022::02:39:18.240 ncs progress usid=49 tid=50 datastore=running context=system applying transaction: ok (100.905 s)

NSO 6.0 でのテスト

同様に同時にトランザクションが開始していますが、それぞれのサービスコードが並列に処理されているため、
すべての処理が実行される時間が大幅に短くなっています。

実行

$ sh test.sh
Loading config for 1 Sun Dec 11 03:33:11 JST 2022
Loading config for 2 Sun Dec 11 03:33:11 JST 2022
Loading config for 3 Sun Dec 11 03:33:11 JST 2022
Loading config for 4 Sun Dec 11 03:33:11 JST 2022
Loading config for 5 Sun Dec 11 03:33:11 JST 2022
Loading config for 6 Sun Dec 11 03:33:11 JST 2022
Loading config for 7 Sun Dec 11 03:33:11 JST 2022
Loading config for 8 Sun Dec 11 03:33:11 JST 2022
Loading config for 9 Sun Dec 11 03:33:11 JST 2022
Loading config for 10 Sun Dec 11 03:33:11 JST 2022