Performance 測定 は NRPC Trace を活用 -1-
これまでPerformance Design Tipsを幾つか紹介してきましたが、その中でNRPC Traceという言葉が何度か出てきたことは皆さん記憶に残っているでしょう。
今回はこのNRPC Traceについて紹介してみたいと思います。
Notes/DominoというのはClient/Server型のApplicationであり、Serverとのやりとりを行いながら動作しているのはこれまでも述べた通りです。
その際使われるのがNRPC (Notes Remote Procedure Call)なのです。
NRPC Traceを取得すると、Notes ClientとDomino Serverとのやりとりを見ることができるのです。
このNRPC Traceの機能はNotesに標準に装備されているのですが、通常はLotus Technical Supportから指示されない限り利用されないことが多いのです。
NRPC Traceは障害の解析のためだけに使うわけではありません。
DBのPerformance分析を行う時に非常に有用な情報となるのです。
Notes/DominoのHelpにはNRPC Traceの使い方やNRPC Commandの意味などは一切紹介されていませんし、通常はLotus Technical Supportの指示の下で使うものとされています。
もう知っているという方もいらっしゃるかも知れませんし、本来はLotus Technical Supportの指示で利用するものですが、非常に便利で有用な機能ですので、今回ここで紹介させて頂きます。
NRPC Traceは以下のような設定をNotes ClientのNotes.iniに行うことで取得できます。
括弧内はコメントですので、実際には括弧部分を除いた形で設定ください。
【R5以下】
Client_Clock=1 (NRPCトレース有効化)
Debug_Console=1 (コンソール表示)
Debug_OutFile=<File Path> (ログ格納先)
【6以降】
Client_Clock=1
Debug_Console=1
Console_Log_Enabled=1 (コンソール・ログの有効化)
Notes/Domino 6以降でもR5以下の設定を行っても問題はありません。
この設定を行った後、Notes Clientを終了して起動すると設定が有効になります。
実際に設定して試して見ると分かりますが、この設定を行うとNRPC Traceを表示するDOS 画面が開かれます。
このDOS画面は閉じてしまわないようにしてください。Notes Clientを終了すると自動的に閉じられます。
また、このDOS画面は表示しなくても問題はありませんが、Applicationの操作とNRPC Traceを関連付けて見たい場合は必須になります。
Applicationを操作しながらどのようなNRPC Commandが投げられているかReal Timeに参照することができるからです。
では、早速この設定を行い、Notes Clientを再起動して試してみましょう。
Notes Clientを起動後、Domino標準のDiscussion Templateから作成されたForum DBを開いてみましょう。
以下のような情報が記録されます。
(10-37 [10]) OPEN_DB(CN=Svr/O=Lotus!!Discuss.nsf): (Connect to Svr/Lotus 81 ms) (Exch names: 0 ms)(Authenticate: 0 ms.) (OPEN_SESSION: 10 ms) 10 ms. [138+294=432]
(11-37 [11]) GET_UNREAD_NOTE_TABLE: 0 ms. [294+48=342]
(12-37 [12]) OPEN_NOTE(REP49256DC9:00207823-NTFFFF0010,03000400): 0 ms. [52+1560=1612]
(13-38 [13]) OPEN_NOTE(REP49256DC9:00207823-NT000002B2,08400000): 10 ms. [52+1858=1910]
(14-38 [14]) OPEN_NOTE(REP49256DC9:00207823-NT0000029E,02400114): 0 ms. [52+1466=1518]
(15-38 [15]) OPEN_NOTE(REP49256DC9:00207823-NT000002AA,0A400116): 10 ms. [52+2244=2296]
(16-38 [16]) OPEN_NOTE(REP49256DC9:00207823-NT00000296,02400114): 0 ms. [52+3282=3334]
(17-38 [17]) OPEN_NOTE(REP49256DC9:00207823-NT0000020A,02400114): 10 ms. [52+3534=3586]
(18-38 [18]) OPEN_NOTE(REP49256DC9:00207823-NT000002BE,00400000): 20 ms. [52+28742=28794]
(19-38 [19]) OPEN_NOTE(REP49256DC9:00207823-NT00000206,00400000): 0 ms. [52+4148=4200]
(20-38 [20]) OPEN_NOTE(REP49256DC9:00207823-NT000002A2,02400114): 10 ms. [52+2440=2492]
(21-38 [21]) OPEN_NOTE(REP49256DC9:00207823-NT000002A6,0A400116): 10 ms. [52+1610=1662]
(22-38 [22]) OPEN_COLLECTION(REP49256DC9:00207823-NT00000142,0040,0000):
(23-38 [23]) OPEN_DB(CN=Svr/O=Lotus!!Discuss.nsf): (Connect to Svr/Lotus: 70 ms) (Exch names: 0 ms)(Authenticate: 0 ms.) (OPEN_SESSION: 10 ms) 0 ms. [138+294=432]
(24-38 [24]) CLOSE_DB(REP49256DC9:00207823): 0 ms. [18+0=18]
110 ms. [134+9014=9148]
(25-38 [25]) GET_NOTE_INFO: 0 ms. [22+106=128]
(26-38 [26]) SET_COLLATION: 0 ms. [16+18=34]
(27-38 [27]) OPEN_NOTE(REP49256DC9:00207823-NT000001F6,00400004): 10 ms. [52+12742=12794]
(28-38 [28]) READ_ENTRIES(REP49256DC9:00207823-NT00000142): 30 ms. [80+468=548]
(29-38 [29]) OPEN_NOTE(REP49256DC9:00207823-NT000002C6,00400000): 10 ms. [52+1704=1756]
(30-38 [30]) OPEN_NOTE(REP49256DC9:00207823-NT000002C2,00400000): 10 ms. [52+1718=1770]
(31-54 [31]) CLOSE_COLLECTION(REP49256DC9:00207823-NT00000142): 0 ms
このLogは以下のような形式になっています。
(Seq_No) NRPC Cmd (Repl_ID-NoteID): Time ms,[Upload_Bytes+Download_Bytes=Total_Bytes]
それぞれ以下のような意味になっています。
Seq_No |
シーケンス番号 |
NRPC Cmd |
NRPCコマンド |
Repl_ID |
DB Replica ID |
NoteID |
Note ID |
Time ms |
NRPC経過時間(ms) |
Upload_Bytes |
送信バイト数 |
Download_Bytes |
受信バイト数 |
Total_Bytes |
送受信バイト数 |
また、NRPC Trace取得はNotes 6以降で行うのが便利です。
というのも、R5までは上記のようにNoteIDが記録されないため、設計要素の特定が困難になります。
Notes 6以降では上記の形式で記録されますので非常に分かりやすくなっています。