Performance 測定 は NRPC Trace を活用 -2-
＜話題の履歴＞
Performance 測定 は NRPC Trace を活用 -1-
前回はNRPC Traceの設定と取得について説明しました。
今回は実際にNRPC Traceを使ってPerformance解析を行ってみることにします。
前回 Discussion Templateから作成されたDBを開いた場合のNRPC Traceの例を紹介しました。
そこには様々なNRPC Commandが記録されていますが、これらのNRPC Commandの意味は公開されているわけではわりません。
以下によく使われるNRPC Commandの意味を私の知る範囲で紹介させていただきます。
Commandを見ただけである程度は処理内容が想像できるのではないでしょうか?
NRPCコマンドの処理内容
NRPCコマンド |
処理内容 |
Open_DB(File Path) |
DBを開く |
Open_Collection |
View/Folderを開く |
Update_Collection |
View/Folderの更新 |
Open_Note |
設計要素(文書)の取得 |
Update_Note |
設計要素(文書)の更新 |
Find_By_Key |
View/Folderの検索 |
Read_Entries |
View/Folderの読込 |
Get_Named_Object_ID |
Profile文書の取得 |
Close_DB |
DBを閉じる |
では、前回例として出したDiscussoion Templateから作成したDBのNTPC Traceを例に見てみることにしましょう。
①(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. [16+0=16]
⑬(32-55 [32]) CLOSE_DB(32-55 [32]) CLOSE_DB(REP49256DC9:00207823): 0 ms. [18+0=18]
さて、これを見ていくと、①のOpen_DBでDtabaseを開いた後、②のGET_UNREAD_NOTE_TABLEで未読文書Tableを読んでいることが分かります。
DBを開く瞬間にDB ICONの未読文書数が更新される動きは皆さんも普段経験されているでしょうから、納得できると思います。
その後③のOPEN_NOTEで設計要素を取得しています。この数で設計がどれだけ多段階に構成されているかを判断することができます。
R5や6.xのDiscussion TemplateはFramesetで構成されているため、このように何度かOpen_Noteを発行して設計要素を取得するのです。
ただ、この動きはLocalに設計がCacheされていない場合ですので、NRPC TraceをとるときにはCache.ndkを削除して取得した場合とCacheが有効な状態で取得した場合とを取るとよいでしょう。
このOpen_Noteに注目すると、設計要素のDownload Bytesおよび時間から設計要素のサイズが大きすぎないかといった判断も可能となります。
次は、④のOPEN_COLLECTIONですが、これはViewを開いている動作となります。
ここで見られるように、NRPCが複数Sessionで行われた場合は経過時間が離れた位置に記録される場合がありますので注意してください。
その後⑩のREAD_ENTRIESでViewの情報を読み込んでいることが分かります。
例えばこのREAD_ENTRIESで時間が掛かっていたとすると、Viewの読み込みに時間が掛かっているということが分かるわけです。
どうでしょう?
NRPC Traceを取ることで、このように、Notes ClientとDomino Serverとのやりとりを理解することができますし、この情報を元にPerformance Tuningのヒントにすることができるのです。
前回、NRPC Traceを表示するConsole表示をOnするためのNotes.ini設定を行っています。
この設定をしておくと、Actionボタンを押した時とかを記録することにより、利用者の操作とResponseの関係を計ることができるのです。
本来はDebug用の設定ですが、Performance測定には大きな威力を発揮してくれるのです。