requests.logの見るべきポイントとは？
| バージョン | 9.0.3 |
requests.log とは
requests.logは、WebFOCUS Clientが処理したURL（リクエスト）の処理情報を確認することができるログファイルです。レポート処理以外にもリポジトリ上のファイル参照（IBFSパスの参照）やINCLUDE等のClient側でしか行われない処理時間を確認できます。
リポジトリ上のファイルを参照している場合にレスポンスが低下する場合があるので、どこがボトルネックになっているのかをrequests.logから確認します。
requests.logを有効にする手順
製品のデフォルト設定では無効（オフ）になっているため、以下の設定を行ってください
- [管理コンソール] に管理者アカウントでログイン
- [構成]タブ – [アプリケーション設定] – [機能診断/トレース] メニューを開く
- [完了時にすべてのURLログを取得] の設定を “オフ" から “完全" に変更
- 「保存」ボタンをクリック
- 画面右上の [キャッシュのクリア] をクリック
- ポップアップが表示されるので「OK」ボタンをクリック
requests.log の閲覧手順
- [管理コンソール] に管理者アカウントでログイン
- [機能診断]タブ – [ログファイル] メニューを開く
- ログ一覧の中から「requests」のリンクをクリック
出力フォルダは、/ibi/WebFOCUS90/logs です
requests.log 出力例
[2021-12-10 15:24:11,742] INFO SesStr MonitorID= 08c2d41a88863eb ClientUser= admin
:
[2021-12-10 15:37:54,729] INFO SrvEnd MonitorID= 08c2d41a88863eb UrlID= URL5 Completed= 15.37.54 ClientUser= admin RequestID= URL5Req1 SrvTime= 1439 SrvDbmsTime= 99 Node= EDASERVE ServerUser= admin ReqType= RunFex ReqInfo="Run:Domain=:Fex=carinst" Mime= HTM
[2021-12-10 15:37:54,804] INFO UrlEnd MonitorID= 08c2d41a88863eb UrlID= URL5 Completed= 15.37.54 UrlStatus= 200 ClientUser= admin UrlTime= 1545 ClientCPU= 46 dummy= 0 dummy= 0 SrvReq= 1 SrvTime= 1439 SrvDbmsReq= 1 SrvDbmsTime= 99 OutputSizeK= 6 ipAddr= 192.168.195.1 Method= GET URL= “http://wfserver/ibi_apps/WFServlet?IBIF_ex=carinst"
:
[2021-12-10 15:42:26,196] INFO SesEnd MonitorID= 08c2d41a88863eb ClientUser= admin
requests.log の読み方
ユーザのセッション情報
- 開始（ログイン）SesStr
INFO SesStr MonitorID= 08c2d41a88863eb ClientUser= admin
- 終了（ログアウト）SesEnd
INFO SesEnd MonitorID= 08c2d41a88863eb ClientUser= admin
- リクエスト（URL）UrlEnd
INFO UrlEnd MonitorID= 08c2d41a88863eb UrlID= URL5 Completed= 15.37.54 UrlStatus= 200 ClientUser= admin UrlTime= 1545 ClientCPU= 46 dummy= 0 dummy= 0 SrvReq= 1 SrvTime= 1439 SrvDbmsReq= 1 SrvDbmsTime= 99 OutputSizeK= 6 ipAddr= 192.168.195.1 Method= GET URL= “http://wfserver/ibi_apps/WFServlet?IBIF_ex=carinst"
- リクエスト（ReportingServer側の処理）SrvEnd ※UrlIDは上記のURLのものと重複します
INFO SrvEnd MonitorID= 08c2d41a88863eb UrlID= URL5 Completed= 15.37.54 ClientUser= admin RequestID= URL5Req1 SrvTime= 1439 SrvDbmsTime= 99 Node= EDASERVE ServerUser= admin ReqType= RunFex ReqInfo="Run:Domain=:Fex=carinst" Mime= HTM
項目の説明
赤背景が重要な項目です。
| 項目名 | 値の例 | 説明 |
|---|---|---|
| MonitorID | 08c2d41a88863eb | セッションID |
| UrlID | URL5 | セッションID毎の実行されたURLのユニークID |
| Completed | 15.37.54 | 処理が終了した時分秒 |
| UrlStatus | 200 | URLのhttpステータスコード（200は正常終了） |
| ClientUser | admin | 実行ユーザID |
| UrlTime | 1545 | URL全体の合計処理時間（ミリ秒） |
| ClientCPU | 46 | WebFOCUS Client側の処理時間（ミリ秒） |
| SrvReq | 1 | Reporting Server へのリクエスト数 |
| SrvTime | 1439 | Reporting Server 側の処理時間（ミリ秒） |
| SrvDbmsTime | 99 | Reporting Server 側のDBMS処理時間（ミリ秒） |
| OutputSizeK | 6 | URLのアウトプットサイズ（キロバイト） |
| ipAddr | 192.168.195.1 | 実行ユーザのIPアドレス |
| Method | GET | HTTP リクエストのメソッドの種類 |
| URL | http://～（省略） | 実行されたURL（最大長1020文字） |
| RequestID | URL5Req1 | セッションID毎の実行された Reporting Server 処理のユニークID |
| Node | EDASERVE | 利用されたリモートサービス名 |
| ServerUser | admin | Reporting Server 側の実行ユーザID |
| ReqType | RunFex | リスエストの種類（RunFex はレポート実行） |
| ReqInfo | Run:Domain=:Fex=carinst | 実行処理のサマリ情報 |
| Mime | HTM | リクエストを返す拡張子 |
UrlTimeが大きいリクエストはレスポンスが遅いリクエストと判断できます。
その処理時間の内訳は、ClientCPU、SrvTime、SrvDbmsTimeになるので、どこがボトルネックになっているか確認します。
OutputSizeKが大きい場合は、そもそも処理負荷が高いリクエストの可能性があります。
Client CPU が大きい場合、リポジトリの処理が影響している可能性があります。
例えば、INCLUDEファイルが大量にあったりプロシジャのソース行数が多くなっていないかどうか確認します。
SrvDbmsTime が大きい場合、SQLの処理に時間が掛かっている場合があります。
プロシジャから実行されているSQLを確認して、処理時間の妥当性やWebFOCUSが発行したSQLが最適なものになっているかを確認します。
SrvTime が大きい場合、レポートサイズの大きさやプロシジャのコーディングに無駄が無いかどうかを確認します。
