ログにこだわるLastaflute

Lastafluteの特徴の一つです。

幾度となくログを見る
どの Request かわかりやすく
RequestパラメーターやSessionの状態など
最後の砦として例外メッセージを必ずログに
- アプリでは、基本的に catch せず throw
- 本当のエラーだけエラーログに (できるだけ)
例外メッセージにRequestの状態も
- Request状態のSNAPSHOT
SQL例外のときはトランザクション一覧も
例外メッセージにトランザクションの思い出も
ActionやJSPなどを一発で探せるように
SQLに呼び出しActionを埋め込み
RequestごとのSQLの発行回数
本番環境でのリクエストの全記録

幾度となくログを見る

インクリメンタル開発では、じっくりと腰を据えた開発がなかなかできないため、何度も何度もデバッグします。書いては動かして直しての繰り返しもしますし、デグレが発生する可能性もありますし、時には致命的なバグでなければ放置する判断もします。とにかく判断のスピードを速める必要があります。

そのとき、ログが判断のスピードに重要な影響を与えます。サッと見て情報が得られること、知りたいことを探せること、そして何より "ぜひ見たい" と思うようなログであること。何度も見ますから、やる気を損なわないためにもログは綺麗である必要があります。

どの Request かわかりやすく

どこからどこまでが、どの Request のログなのか？が理解しやすいように、以下のようにRequestごとに明確に分断されてログが出力されます。

e.g. どこからどこまでが、どの Request のログなのか？ @Log

... DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/list/
  requestClass=org.lastaflute.web.servlet.filter.hotdeploy.HotdeployHtt...
  ; url=http://localhost:8090/harbor/product/list/?productName=&product...
  ; method=GET ; protocol=HTTP/1.1 ; scheme=http ; secure=false ; remot...
  ; characterEncoding=UTf-8 ; contentLength=-1 ; contentType=null ; loc...

...
...
...

  responseClass=org.eclipse.jetty.server.Response ; committed=true
  ; httpStatus=500 ; contentType=text/html ; locale=ja_JP
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  ...
  [request] lastaflute.action.ACTION_RUMTIME=runtime:{/product/list/, pu...
  [request] lastaflute.dbflute.SQL_COUNT={total=2, selectCB=2, entityUpd...
  ...
  [session] lastaflute.action.USER_BEAN={userId=1, sync=2015/12/23 20:46...
  [session] lastaflute.action.USER_LOCALE=ja
* * * * * * * * * * {END}: /product/list/ [00m00s247ms]


... DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/edit/3/
  requestClass=org.lastaflute.web.servlet.filter.hotdeploy.HotdeployHtt...
  ; url=http://localhost:8090/harbor/product/list/?productName=&product...
  ; method=GET ; protocol=HTTP/1.1 ; scheme=http ; secure=false ; remot...
  ; characterEncoding=UTf-8 ; contentLength=-1 ; contentType=null ; loc...
...
...

RequestLoggingfilter にて、このログ出力が行われています。

RequestパラメーターやSessionの状態など

RequestパラメーターやRequest属性、Sessionの状態などが出力されます。

[header]: Requestヘッダー
[param]: Requestパラメーター
[request]: Request属性
[cookie]: Cookie
[session]: Session

e.g. Requestパラメーターやセッションの状態など @Log

...-DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /product/list/
  requestClass=org.lastaflute.web.servlet.filter.hotdeploy.HotdeployHttpServletRequest ; sessionId=1jd3fpprgg97yx28iu7maf184
  ; url=http://localhost:8090/harbor/product/list/?productName=&productStatus=&purchaseMemberName=
  ; method=GET ; protocol=HTTP/1.1 ; scheme=http ; secure=false ; remoteAddr=127.0.0.1 ; remoteHost=127.0.0.1
  ; characterEncoding=UTf-8 ; contentLength=-1 ; contentType=null ; locale=ja ; locales=ja,en_US,en,es,ko
  [header] Accept=text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
  [header] Accept-Encoding=gzip, deflate, sdch
  [header] Accept-Language=ja,en-US;q=0.8,en;q=0.6,es;q=0.4,ko;q=0.2
  ...
  [param] productName=sea
  [param] productStatus=
  [param] purchaseMemberName=
  ...
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  ...
  [session] lastaflute.action.USER_LOCALE=ja

...
...

  responseClass=org.eclipse.jetty.server.Response ; committed=true
  ; httpStatus=500 ; contentType=text/html ; locale=ja_JP
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  ...
  [request] lastaflute.action.ACTION_RUMTIME=runtime:{/product/list/, public HtmlResponse ProductListAction@index(OptionalThing, ProductSearchform), urlParam:{{0=opt:{null}}}, *IllegalStateException}
  [request] lastaflute.dbflute.SQL_COUNT={total=2, selectCB=2, entityUpdate=0, queryUpdate=0, outsideSql=0, procedure=0}
  ...
  [session] lastaflute.action.USER_BEAN={userId=1, sync=2015/12/23 20:46:27}@74538453
  [session] lastaflute.action.USER_LOCALE=ja
* * * * * * * * * * {END}: /product/list/ [00m00s247ms]

RequestLoggingfilter にて、このログ出力が行われています。

最後の砦として例外メッセージを必ずログに

アプリでは、基本的に catch せず throw

アプリ内でthrowされた例外は、最後の最後の Servletfilter (RequestLoggingfilter) で catch され、ERRORレベルで例外メッセージとスタックトレースが出力されるようになっています。

HTTPステータスコードは 500 として扱われ、500.html が表示されるような仕組み(単にweb.xmlでそう設定しているだけ)になっています。その 500.html はアプリごとに適切なデザインに修正しましょう。

よって、例外が発生しても、アプリ内で自前で catch してエラーログを出す必要はありません。エラーログが統一的でなかったり、ノイズが入ってしまったりするのもトラブルシューティングする人にとっては困るのです。 (もちろん、例外が発生しても処理を続行したい場合や例外翻訳して再度throwするときは catch します)

e.g. Action内ではシステムエラーはthrowすればOK @Java
@Execute
public HtmlResponse index(OptionalThing<Integer> pageNumber, ProductSearchform form) {
    // *no need to catch and log about system error handling
    //try {
    validate(form, messages -> {} , () -> {
        return asHtml(path_Product_ProductListHtml);
    });
    PagingResultBean<Product> page = selectProductPage(pageNumber.orElse(1), form);
    List<ProductSearchRowBean> beans = page.mappingList(product -> {
        return mappingToBean(product);
    });
    ...
    } catch (SeaException e) {
        logger.error(..., e);
    }
}

本当のエラーだけエラーログに (できるだけ)

ユーザーのミスオペや、ちょっとしたアドレスバーでのURL修正いたずらなどで、簡単に500エラーが発生しないような工夫をしています。以下のエラーは、400 もしくは 404 として扱われます。もちろん、バグかもしれないので、開発中はエラー内容がDEBUGログでしっかり出力されます。

Pathパラメーターの型違いエラー (404) e.g. /list/3 を期待するところ /list/a が飛んできた
formのプロパティの型違いエラー (400) e.g. Integer なのに "a" が飛んできた
formの配列プロパティのindexパースエラー (400) e.g. sea[a] が飛んできた
JSON BodyリクエストのJSONパースエラー (400)
などなど

インクリメンタル開発では本番でのシステムエラーはなかなか完璧には予防できない ため、その分エラーログは重要です。エラーログにあまり重要ではないエラーが混じっていると本当に緊急性の高いエラーを見逃してしまいます。

例外メッセージにRequestの状態も

通常、本番環境ではデバッグログは出力しません。ですが、インクリメンタル開発では、本番環境でも基本的な例外が発生する可能性を想定する必要があります。そのとき、例えば NullPointerException だけでは原因を追求するのはとても厳しいです。その例外が発生したときの Request のもろもろの情報が欲しいものです。

Request状態のSNAPSHOT

ということで、例外メッセージに Request の状態が一緒に出力されます。

e.g. Requestパラメーターやセッションの状態など @Log

 ERROR (...#logError():895) - *ServletException occurred.
/= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =: /product/list/
  requestClass=org.lastaflute.web.servlet.filter.hotdeploy.HotdeployHttpServletRequest ; sessionId=1jd3fpprgg97yx28iu7maf184
  ; url=http://localhost:8090/harbor/product/list/?productName=&productStatus=&purchaseMemberName=
  ; method=GET ; protocol=HTTP/1.1 ; scheme=http ; secure=false ; remoteAddr=127.0.0.1 ; remoteHost=127.0.0.1
  ; characterEncoding=UTf-8 ; contentLength=-1 ; contentType=null ; locale=ja ; locales=ja,en_US,en,es,ko
  [header] Accept=text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
  [header] Accept-Encoding=gzip, deflate, sdch
  ...
  [param] productName=sea
  [param] productStatus=
  [param] purchaseMemberName=
  ...
  [cookie] JSESSIONID=1jd3fpprgg97yx28iu7maf184
  ...
  [request] lastaflute.action.ACTION_RUMTIME=runtime:{/product/list/, public HtmlResponse ProductListAction@index(OptionalThing, ProductSearchform), urlParam:{{0=opt:{null}}}, *IllegalStateException}
  [request] lastaflute.dbflute.SQL_COUNT={total=2, selectCB=2, entityUpdate=0, queryUpdate=0, outsideSql=0, procedure=0}
  ...
  [session] lastaflute.action.USER_BEAN={userId=1, sync=2015/12/23 20:46:27}@74538453
  [session] lastaflute.action.USER_LOCALE=ja
  responseClass=org.eclipse.jetty.server.Response ; committed=true
  ; httpStatus=500 ; contentType=text/html ; locale=ja_JP
  [header] Accept-Ranges=bytes
  ...
= = = = = = = = = =/ [00m00s107ms] #6fc09463
java.lang.IllegalStateException: test error
    at org.docksidestage.app.web.product.ProductListAction.index(ProductListAction.java:56)
    ...

例外として終わった処理が、リクエストの時点から何秒くらいかかって落ちたのかもわかるようになっています。 DBのロックを長く持っていたとか、通信で時間がかかったとか、例外で落ちたリクエストが起因して別のリクエストに影響を与えたかどうかなどを推測しやすいように。

RequestLoggingfilter にて、このログ出力が行われています。

SQL例外のときはトランザクション一覧も

SQL例外が発生したときに、一緒に "その瞬間のトランザクション一覧" が、warningログとして出力されます。これにより、DBのロック待ち例外とかのとき、どの処理が起因になっているのかの推測がしやすくなります。

e.g. SQL例外のときのトランザクション一覧 @Log
2015-02-18 16:10:16,919 [1685538367@qtp-186276003-0]-WARN  (ExceptionTranslator#warnSQLfailureState():90) - Look! Read the message below.
/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *
SQL failure State, here!

[Advice]
This state is for the SQL failure exception: #1553847

[ConnectionPool View]
org.lastaflute.db.dbcp.HookedConnectionPool@7cfba6c5
freePool=2, activePool=0, txActivePool=8
{00m03s243ms, 1424243415266/1(21), web.mypage.MypageAction@index(), {userId=3}, map:{MEMBER = list:{selectCount} ; PURCHASE = list:{selectCount}}, /mypage/}
{00m01s131ms, 1424243415266/10(7), web.product.ProductListAction@index(), {userId=null}, map:{PRODUCT = list:{selectList}}, /product/list/}
{00m00s239ms, 1424243415266/2(34), web.signin.SigninAction@doLogin(), {userId=null}, map:{MEMBER = list:{selectList}}, /login/doLogin}
{00m01s632ms, 1424243415266/9(75), web.mypage.MypageAction@index(), {userId=22}, map:{PURCHASE = list:{selectCount}}, /mypage/}
/- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - (SQL now: PURCHASE#selectCount [00m00s003ms])
select count(*)
  from PURCHASE dfloc
-- org.docksidestage.app.web.login.LoginIndexAction#index(): (via LoginIndexAction$$Lambda$8/1635799099)
- - - - - - - - - -/
{00m01s634ms, 1424243415266/5(26), web.product.ProductListAction@index(), {userId=83}, map:{MEMBER = list:{selectList}}, /product/}
{00m07s637ms, 1424243415266/3(31), web.purchase.PurchaseAction@index(), {userId=9}, map:{MEMBER = list:{selectList ; selectCount}}, /purchase/}
{00m01s632ms, 1424243415266/8(41), web.profile.ProfileEditAction@index(), {userId=732}, map:{MEMBER = list:{updateNonstrict}}, /profile/edit/}
/- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - (SQL now: MEMBER#updateNonstrict [00m00s016ms])
update MEMBER set BIRTHDATE = null, UPDATE_DATETIME = '2015-02-24 11:06:36.205', UPDATE_USER = 'M:-1,DCK,LoginIndexAction', VERSION_NO = VERSION_NO + 1
 where MEMBER_ID = 3
-- org.docksidestage.app.web.signin.SigninAction#index(): (via LoginIndexAction$$Lambda$12/475753501)
- - - - - - - - - -/
{00m01s633ms, 1424243415266/6(3), web.login.LoginIndexAction@index(), {userId=null}, map:{PRODUCT = list:{selectCount}}, /login/}
* * * * * * * * * */

それぞれのトランザクションが、開始されてからどのくらい経過しているのか？ e.g. 00m01s634ms
トランザクションを特定するユニークなコード e.g. 1424243415266/5
DBMS側のどのプロセスと紐づいているか？ e.g. xxx/x(21) ※2015/02/26時点でMySQLのみ
どのActionから呼ばれたものなのか？ e.g. MypageIndexAction#index()
どのログインユーザーで実行されているものなのか？ e.g. {userId=83}
そのトランザクションがどのテーブルにどんな操作をしたか？ e.g. map:{MEMBER = ...}
その瞬間、どんなSQLが実行されていたのか？ (どのくらい時間がかかっているのか？)

...がわかります。ただ、Tomcatが複数台構成になっていると、その例外が発生したインスタンス内のトランザクションだけに限りますが、それでも原因を追及する上での貴重な情報になるかと。また、Adviceの欄に、ハッシュ値が表示されていますが、これは対応するエラーログとリンクしていて、このハッシュ値でエラーログを探すと、このWarningログのきっかけとなった例外メッセージが参照できます。

その瞬間実行されているSQLの表示用SQL (DisplaySql) は、例外発生時に初めて生成されるので、正常時に文字列生成コストがかかるわけではありません(その辺のパフォーマンス考慮、最大限しているつもり)。また、トランザクションが開始されていても、まだ一度もDBアクセスしていないトランザクションは表示されません(ConnectionPoolに乗ってないため)。

例外メッセージにトランザクションの思い出も

本番環境でのシステム例外は、例外メッセージとスタックトレースだけで原因を突き止めるのはなかなか難しいこともあります。一つ前二つ前の検索結果が影響して例外が発生していることもあり、その検索結果が知りたいものです。

そこで、例外メッセージ時に、トランザクションの思い出 を載せ、落ちたトランザクションがどんな検索、更新をしてきたのか？ がわかるようにしています。

e.g. トランザクションの思い出、お見せします @Log

/= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =: /product/list/
  requestClass=org.lastaflute.web.servlet.filter.hotdeploy.HotdeployHttpServletRequest ; sessionId=1jd3fpprgg97yx28iu7maf184
  ; url=http://localhost:8090/harbor/product/list/?productName=&productStatus=&purchaseMemberName=
  ; method=GET ; protocol=HTTP/1.1 ; scheme=http ; secure=false ; remoteAddr=127.0.0.1 ; remoteHost=127.0.0.1
  ; characterEncoding=UTf-8 ; contentLength=-1 ; contentType=null ; locale=ja ; locales=ja,en_US,en,es,ko
  [header] Accept=text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
  [header] Accept-Encoding=gzip, deflate, sdch
  ...
  [param] productName=sea
  [param] productStatus=
  [param] purchaseMemberName=
  ...
  [cookie] JSESSIONID=1jd3fpprgg97yx28iu7maf184
  ...
  [request] lastaflute.action.ACTION_RUMTIME=runtime:{/product/list/, public HtmlResponse ProductListAction@index(OptionalThing, ProductSearchform), urlParam:{{0=opt:{null}}}, *IllegalStateException}
  [request] lastaflute.dbflute.SQL_COUNT={total=2, selectCB=2, entityUpdate=0, queryUpdate=0, outsideSql=0, procedure=0}
  [request] lastaflute.dbflute.TRANSACTION_MEMORIES=wholeShow:
   *RomanticTransaction@4dca5628
   << Transaction Current State >>
   beginning time: 2015/12/23 20:46:29.444
   table command: map:{PRODUCT = list:{selectList ; selectCount ; updateNonstrict} ; PURCHASE = list:{selectEntity} ; MEMBER_LOGIN = list:{insert}}
   ending: rollback
   << Transaction Recent Result >>
   1. (2015/12/23 20:46:29.479) [00m00s016ms] PRODUCT@selectList => List:{size=4, first={PRODUCT_ID=6}}
   2. (2015/12/23 20:46:29.497) [00m00s001ms] PRODUCT@selectCount => Integer:{count=20}
   3. (2015/12/23 20:46:29.511) [00m00s002ms] PRODUCT@updateNonstrict => Integer:{updated=1, key={PRODUCT_ID=9}}
   4. (2015/12/23 20:46:29.520) [00m00s006ms] PURCHASE@selectEntity => Purchase:{PURCHASE_ID=3}
   5. (2015/12/23 20:46:29.565) [00m00s003ms] MEMBER_LOGIN@insert => Integer:{inserted=1, key={MEMBER_LOGIN_ID=65}}
  [request] lastaflute.hotdeploy.CLASS_LOADER=org.lastaflute.di.core.smart.hot.HotdeployClassLoader@65ffb01f
  ...
  [session] lastaflute.action.USER_BEAN={userId=1, sync=2015/12/23 20:46:27}@74538453
  [session] lastaflute.action.USER_LOCALE=ja
  responseClass=org.eclipse.jetty.server.Response ; committed=true
  ; httpStatus=500 ; contentType=text/html ; locale=ja_JP
  [header] Accept-Ranges=bytes
  ...
= = = = = = = = = =/ [00m00s107ms] #6fc09463
java.lang.IllegalStateException: test error
    at org.docksidestage.app.web.product.ProductListAction.index(ProductListAction.java:56)
    ...

そのトランザクションがどのテーブルにどんなアクセスをしたか？
そのトランザクションの直近30のアクセス履歴、検索結果の件数やPKの値なども少し

これらが本番でわかるのであれば、トラブルシューティングする人が少しでも助かるのではないかと。

beginning time: トランザクション開始時間
table command: アクセスしたテーブルとそのコマンド (順不同)
ending: commit したか rollback したか
Recent Result: 直近30個のDBアクセス情報、テーブル名や結果の一部

ActionやJSPなどを一発で探せるように

インクリメンタル開発では、ドキュメントを充実させる時間があまりありません。書いてもすぐに修正しなければならないため、メンテコストが高いのです。

この画面は何のActionが呼ばれているのか？どのJSPが評価されているのか？画面を動かすことで、それらをすぐにデバッグログで探せるようにしています。それぞれのハッシュタグが含まれています。

#action: Action呼び出しログのハッシュタグ
#jsp: JSP遷移ログのハッシュタグ
#before: ActionCallbackのbeforeタイミングのハッシュタグ
#finally: ActionCallbackのfinallyタイミングのハッシュタグ
#flow: それらもろもろの流れのハッシュタグ

Eclipseであれば、コンソールログで ctrl + f を押して、#action と入力すれば、Actionクラスの呼び出し部分に飛びます。処理の多い Request で #flow で流れを追っていくのもよいでしょう。 (...残念なことに、#beforeは一箇所かぶっています)

e.g. ActionやJSPの呼び出しログのハッシュタグ @Log

...-DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/list/
  Request class=org.seasar.framework.container.hotdeploy.HotdeployHttpSer...
  , REQUEST_URI=/dockside/member/list/, SERVLET_PATH=/member/list/, Chara...
  , ContentType=application/x-www-form-urlencoded, Locale=ja, Locales=ja,...
...
...) - ...Saving user locale to session: ja
...) - #flow ...Calling back #before for MemberListAction
...
...) - #flow ...Beginning #action MemberListAction.doSearch()
...
...) - トランザクションを開始しました。tx=[formatI...
...) - トランザクションをコミットしました。tx=[for...
...
...) - #flow ...Calling back #finally for MemberListAction
...
...) - #flow ...forwarding to #jsp /WEB-INf/view/member/member_list.jsp
...
  [session] javax.servlet.jsp.jstl.fmt.request.charset=UTf-8
  [session] member_memberListform=org.dbflute.maihama.app.web.member.Memb...
  [session] org.apache.struts.action.LOCALE=ja
  [session] org.dbflute.maihama.domainfw.action.DocksideUserBean={userId=...
* * * * * * * * * * {END}: /member/list/ [00m00s247ms]

GodHandableAction で、このログ出力が行われています。

SQLに呼び出しActionを埋め込み

このSQLが、どの Action やどの Logic から呼ばれたものか？

そもそも DBflute には、デバッグログでそういった情報が出力されます。

e.g. DBfluteのデバッグログの呼び出し階層 @Log
- /===========================================================================
-                                                       MemberBhv.selectList()
-                                                       =====================/
- MemberListAction.doSearch():89 -> MemberListAction.selectMemberPage():159 -> ...
- select dfloc.MEMBER_ID as MEMBER_ID, dfloc.MEMBER_NAME as MEMBER_NAME, dfloc.MEMBER_ACCOUNT as MEMBER_ACCOUNT, dfloc.MEMBER_STATUS_CODE as MEMBER_STATUS_CODE, dfloc.fORMALIZED_DATETIME as fORMALIZED_DATETIME, dfloc.BIRTHDATE as BIRTHDATE, dfloc.REGISTER_DATETIME as REGISTER_DATETIME, dfloc.REGISTER_USER as REGISTER_USER, dfloc.REGISTER_PROCESS as REGISTER_PROCESS, dfloc.UPDATE_DATETIME as UPDATE_DATETIME, dfloc.UPDATE_USER as UPDATE_USER, dfloc.UPDATE_PROCESS as UPDATE_PROCESS, dfloc.VERSION_NO as VERSION_NO, dfrel_0.MEMBER_STATUS_CODE as MEMBER_STATUS_CODE_0, dfrel_0.MEMBER_STATUS_NAME as MEMBER_STATUS_NAME_0, dfrel_0.DISPLAY_ORDER as DISPLAY_ORDER_0
-   from MEMBER dfloc
-     left outer join MEMBER_STATUS dfrel_0 on dfloc.MEMBER_STATUS_CODE = dfrel_0.MEMBER_STATUS_CODE
-  where dfloc.MEMBER_NAME like 'S%' escape '|'
-  order by dfloc.MEMBER_ID asc
- ===========/ [00m00s016ms - Selected list: 6 first={1,Stojkovic,Pixy,fML,2007-12-01 02:01:10.0,1965-03-02 15:00:00.0,2008-01-23 13:38:25.989,replace-schema,replace-schema,2008-01-23 13:38:25.991,replace-schema,replace-schema,1}]

ですが、例えばデータベース側で遅いSQLやロック待ちのSQLを抽出したときに(MySQLのSlowQueryなど)、SQLにはデバッグログは含まれていませんので、SQLだけをみてもなかなかわかりません。

そこで、Lastafluteでは、SQL自体にSQLコメントとしてActionクラス名が自動で付与されるようになっています。これで、データベース側でのSQL抽出でも、どこの画面から発行されたSQLなのかがすぐに判別できます。

e.g. SQLコメントとしてActionクラス名が自動で付与される @Log
- /===========================================================================
-                                                       MemberBhv.selectList()
-                                                       =====================/
- MemberListAction.doSearch():89 -> MemberListAction.selectMemberPage():159 -> ...
- select dfloc.MEMBER_ID as MEMBER_ID, dfloc.MEMBER_NAME as MEMBER_NAME, dfloc.MEMBER_ACCOUNT as MEMBER_ACCOUNT, dfloc.MEMBER_STATUS_CODE as MEMBER_STATUS_CODE, dfloc.fORMALIZED_DATETIME as fORMALIZED_DATETIME, dfloc.BIRTHDATE as BIRTHDATE, dfloc.REGISTER_DATETIME as REGISTER_DATETIME, dfloc.REGISTER_USER as REGISTER_USER, dfloc.REGISTER_PROCESS as REGISTER_PROCESS, dfloc.UPDATE_DATETIME as UPDATE_DATETIME, dfloc.UPDATE_USER as UPDATE_USER, dfloc.UPDATE_PROCESS as UPDATE_PROCESS, dfloc.VERSION_NO as VERSION_NO, dfrel_0.MEMBER_STATUS_CODE as MEMBER_STATUS_CODE_0, dfrel_0.MEMBER_STATUS_NAME as MEMBER_STATUS_NAME_0, dfrel_0.DISPLAY_ORDER as DISPLAY_ORDER_0
-   from MEMBER dfloc
-     left outer join MEMBER_STATUS dfrel_0 on dfloc.MEMBER_STATUS_CODE = dfrel_0.MEMBER_STATUS_CODE
-  where dfloc.MEMBER_NAME like 'S%' escape '|'
-  order by dfloc.MEMBER_ID asc
- -- org.dbflute.maihama.app.web.member.MemberListAction#doSearch(): (M, DCK)
- ===========/ [00m00s016ms - Selected list: 6 first={1,Stojkovic,Pixy,fML,2007-12-01 02:01:10.0,1965-03-02 15:00:00.0,2008-01-23 13:38:25.989,replace-schema,replace-schema,2008-01-23 13:38:25.991,replace-schema,replace-schema,1}]

TypicalAction の ActionHook の before の中で SqlStringfilter が設定され、それによりDBfluteがSQLに画面情報を付与するようになります。 (そこから追っていくと見つかります)

RequestごとのSQLの発行回数

インクリメンタル開発では、最初の時点では開発スピード重視で、パフォーマンス考慮を置き去りにされることがよくあります。実際に、最初はデータ件数も少なく問題にならないことも多く、わざとそれを狙って実装する場合もあります。 (考慮できるにこしたことはありませんが、考慮実装に時間がかかる場合など)

そして、だんだんつらくなってきます。そろそろ直さないといけないという段階で何がボトルネックなのかを知るために、一つのRequest内で発行されたSQLの回数がデバッグログに出力されます。 Requestの最後のログで、Request属性として出力されます。

e.g. SQLの発行回数がRequest属性として出力される @Log

...-DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/list/
  Request class=org.seasar.framework.container.hotdeploy.HotdeployHttpSer...
  , REQUEST_URI=/dockside/member/list/, SERVLET_PATH=/member/list/, Chara...
  , ContentType=application/x-www-form-urlencoded, Locale=ja, Locales=ja,...

...
...
...

  Response class=org.mortbay.jetty.Response, ContentType=text/html; charset=utf-8, Committed=true
  , toString()=HTTP/1.1 200  Content-Type: text/html; charset=utf-8 Expires: Thu, 01 Dec 1994 16:00:00 GMT Pragma: no-cache Cache-Contr...
  ...
  [request] lastaflute.dbflute.SQL_COUNT={total=1, selectCB=1, entityUpdate=0, queryUpdate=0, outsideSql=0, procedure=0}
  ...
  [session] javax.servlet.jsp.jstl.fmt.request.charset=UTf-8
  [session] member_memberListform=org.dbflute.maihama.app.web.member.Memb...
  [session] org.apache.struts.action.LOCALE=ja
  [session] org.dbflute.maihama.domainfw.action.DocksideUserBean={userId=...
* * * * * * * * * * {END}: /member/list/ [00m00s247ms]

TypicalAction の ActionHook の before の中で SqlStringfilter が設定され、それによりDBfluteがSQLの発行回数を数えるようになります。実際にログを出力するところは、finally の中で行われています。(そこから追っていくと見つかります)

また、SQL発行回数がある一定のしきい値(デフォルトで30)を超えると、WARNレベルのログが出力されます。エラーにはなりませんが、本番環境でもチェックされて検出しやすくなっています。

e.g. あまりにひどい発行回数はWARNで警告、123回実行しているケース @Log

...-WARN (...) - *Too many SQL executions: 123/30 in MemberListAction.doSearch()

TypicalBaseAction の ActionCallback の finally の中で SqlStringfilter の結果を見て、このログ出力が行われています。

本番環境でのリクエストの全記録

こちらはオプションです。もし、リクエストの全記録を本番環境で残したいのであれば、InOutログというものを出力することができます。

リクエストの全記録、InOutログ

e.g. in-out logging contents @inout_[app].log
// これは、HtmlResponseのときのログ
2017-08-20 00:16:08,784 [qtp2068434592-11] INfO  (InOutLogger@log():50) - GET /signin/ SigninAction@index() (2017-08-20 00:16:06.834) [00m01s950ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...forwarding to /signin/signin.html)
2017-08-20 00:16:34,321 [qtp2068434592-15] INfO  (InOutLogger@log():50) - GET /member/list/ MemberListAction@index() (2017-08-20 00:16:33.946) [00m00s375ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...forwarding to /member/member_list.html) sqlCount:{total=2, selectCB=2}
2017-08-20 00:16:49,572 [qtp2068434592-11] INfO  (InOutLogger@log():50) - POST /member/edit/ MemberEditAction@update() (2017-08-20 00:16:49.491) [00m00s081ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} *ValidationErrorException #5fd42ca requestParameter:{lastaflute.action.TRANSACTION_TOKEN=a30cdf490b0f7b831507d84730d8d288, birthdate=1965-03-03, versionNo=0, memberName=, memberStatus=fML, update=Update, memberAccount=Pixy, memberId=1, previousStatus=fML} responseBody:(...forwarding to /member/member_edit.html)

// これは、JsonResponseのときのログ
2017-08-20 01:16:36,433 [qtp2068434592-17] INfO  (InOutLogger@log():50) - POST /wx/request/json/body/ WxRequestJsonBodyAction@index() (2017-08-20 01:16:36.312) [00m00s121ms] {Apache-HttpClient/4.5.2 (Java/1.8.0_131)}
requestBody:
{sea: "mystic"}

responseBody:
{
  "body": {
    "sea": "mystic",
    "land": null,
    "piari": null,
    "bonvo": null,
    "dstore": null
  }
}