This is a cache of http://dbflute.seasar.org/ja/manual/function/helper/saflute/friendlylogging.html. It is a snapshot of the page at 2024-11-01T00:23:32.982+0000.
ログにこだわるSAFlute (Friendly Logging) | <strong>dbflute</strong>

ログにこだわるSAFlute

SAFluteの特徴の一つです。

SAFlute

幾度となくログを見る

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

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

どの Request かわかりやすく

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

e.g. どこからどこまでが、どの 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; chars...
  , toString()=HTTP/1.1 200  Content-Type: text/html; charset=utf-8 Expir...
  [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]


...-DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/edit/3/
  Request class=org.seasar.framework.container.hotdeploy.HotdeployHttpSer...
  , REQUEST_URI=/dockside/member/edit/3/, SERVLET_PATH=/member/edit/3/...
...
...

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

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

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

[header]
Requestヘッダー
[param]
Requestパラメーター
[request]
Request属性
[cookie]
Cookie
[session]
Session
e.g. Requestパラメーターやセッションの状態など @Log

...-DEBUG (...#before():268) - * * * * * * * * * * {BEGIN}: /member/list/
  Request class=org.seasar.framework.container.hotdeploy.HotdeployHttpServletRequest, RequestedSessionId=1iwgg3g3f5qz1b6m3q5n3picu
  , REQUEST_URI=/dockside/member/list/, SERVLET_PATH=/member/list/, CharacterEncoding=UTF-8, ContentLength=113
  , ContentType=application/x-www-form-urlencoded, Locale=ja, Locales=ja, en_US, en, es, ko, Scheme=http, isSecure=false
  , SERVER_PROTOCOL=HTTP/1.1, REMOTE_ADDR=0:0:0:0:0:0:0:1%0, REMOTE_HOST=0:0:0:0:0:0:0:1%0, SERVER_NAME=localhost, SERVER_PORT=8088
  , ContextPath=/dockside, REQUEST_METHOD=POST, PathInfo=null, RemoteUser=null
  , REQUEST_URL=http://localhost:8088/dockside/member/list/
  , QUERY_STRING=null
  [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] doSearch=検索
  [param] memberName=S
  ...
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  [cookie] MLE=Y
  ...
  [session] org.apache.struts.action.LOCALE=ja
  [session] org.dbflute.maihama.domainfw.action.DocksideUserBean={userId=1, sync=2014/04/06 19:34:29, locale=null, timeZone=null}

...
...

  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...
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  [cookie] MLE=Y
  ...
  [request] memberStatusMap={=選択してください, FML=正式会員, WDL=退会会員, PRV=仮会員}
  [request] member_memberListAction=org.dbflute.maihama.app.web.member.MemberListAction$$EnhancedByS2AOP$$2771f735@4a5f634c
  [request] pageNumber=1
  ...
  [session] org.apache.struts.action.LOCALE=ja
  [session] org.dbflute.maihama.domainfw.action.DocksideUserBean={userId=1, sync=2014/04/06 19:34:29, locale=null, timeZone=null}
* * * * * * * * * * {END}: /member/list/ [00m00s247ms]

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

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

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

アプリ内でthrowされた例外は、最後の最後の ServletFilter のところで catch され、ERRORレベルで例外メッセージとスタックトレースが出力されます。 HTTPステータスコードは 500 として扱われ、500.html が表示されるような仕組みになっています(単にweb.xmlでそう設定しているだけですが)。 500.htmlはアプリごとに適切なデザインに修正します。

よって、例外が発生しても、アプリ内で自前で catch して ERROR を出す必要はありません。 (もちろん、例外が発生しても処理を続行したい場合などは catch します)

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

本当のエラーだけ 500 に

ユーザーのミスオペや、ちょっとしたいたずらなどで、簡単に500エラーが発生しないような工夫をしています。 インクリメンタル開発では、システムエラーはなかなか避けられないため、その分エラーログは重要です。 そこにあまり重要ではないエラーが混じっていると本当に緊急性の高いエラーを見逃してしまいます。

  • GETパラメーターを受け取るFormのプロパティの型違いエラー
  • GETパラメーターを受け取るFormの配列プロパティのindexパースエラー
  • GETパラメーターを受け取るFormのJSONパースエラー
  • などなど

もちろん、開発中はエラー内容がデバッグログでしっかり出力されます。

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

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

Request状態のSNAPSHOT

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

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

-ERROR (...#logError():512) - *ServletException occurred.
/= = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =: /member/list/
  Request class=org.seasar.framework.container.hotdeploy.HotdeployHttpServletRequest, RequestedSessionId=1uyu0x3fblbvbcr8mi9bmo5gl
  , REQUEST_URI=/dockside/member/list/, SERVLET_PATH=/member/list/, CharacterEncoding=UTF-8, ContentLength=113
  , ContentType=application/x-www-form-urlencoded, Locale=ja, Locales=ja, en_US, en, es, ko, Scheme=http, isSecure=false
  , SERVER_PROTOCOL=HTTP/1.1, REMOTE_ADDR=0:0:0:0:0:0:0:1%0, REMOTE_HOST=0:0:0:0:0:0:0:1%0, SERVER_NAME=localhost, SERVER_PORT=8088
  , ContextPath=/dockside, REQUEST_METHOD=POST, PathInfo=null, RemoteUser=null
  , REQUEST_URL=http://localhost:8088/dockside/member/list/
  , QUERY_STRING=null
  Response class=org.mortbay.jetty.Response, ContentType=text/html, Committed=true
  , toString()=HTTP/1.1 500  Content-Type: text/html Accept-Ranges: bytes Content-Length: 116 Last-Modified: Fri, 28 Mar 2014 14:33:35 ...
  [header] Accept=text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
  [header] Accept-Encoding=gzip,deflate,sdch
  ...
  [param] doSearch=検索
  [param] memberName=S
  ...
  [cookie] JSESSIONID=1iwgg3g3f5qz1b6m3q5n3picu
  [cookie] MLE=Y
  ...
  [session] org.apache.struts.action.LOCALE=ja
  [session] org.dbflute.maihama.domainfw.action.DocksideUserBean={userId=1, sync=2014/04/06 19:34:29, locale=null, timeZone=null}
= = = = = = = = = =/ [00m01s851ms] #2bbe82a4
java.lang.NullPointerException
    at org.dbflute.maihama.app.web.member.MemberListAction.doSearch(MemberListAction.java:89)
	at org.dbflute.maihama.app.web.member.MemberListAction$$EnhancedByS2AOP$$73795327.$$doSearch$$invokeSuperMethod$$(MemberListAction$$EnhancedByS2AOP$$73795327.java)
	at org.dbflute.maihama.app.web.member.MemberListAction$$EnhancedByS2AOP$$73795327$$MethodInvocation$$doSearch1.proceed(MethodInvocationClassGenerator.java)
	at org.seasar.extension.tx.DefaultTransactionCallback.execute(DefaultTransactionCallback.java:58)
	at org.seasar.extension.tx.adapter.JTATransactionManagerAdapter.required(JTATransactionManagerAdapter.java:65)
	at org.seasar.extension.tx.RequiredInterceptor.invoke(RequiredInterceptor.java:50)
	at org.dbflute.maihama.app.web.member.MemberListAction$$EnhancedByS2AOP$$73795327$$MethodInvocation$$doSearch1.proceed(MethodInvocationClassGenerator.java)
	at org.seasar.framework.aop.interceptors.ThrowsInterceptor.invoke(ThrowsInterceptor.java:79)
    ...

例外として終わった処理が、リクエストの時点から何秒くらいかかって落ちたのかもわかるようになっています。 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.dbflute.saflute.db.dbcp.HookedConnectionPool@7cfba6c5
freePool=2, activePool=0, txActivePool=8
{00m03s243ms, 1424243415266/1(21), web.mypage.MypageIndexAction#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.login.LoginIndexAction#doLogin(), {userId=null}, map:{MEMBER = list:{selectList}}, /login/doLogin}
{00m01s632ms, 1424243415266/9(75), web.mypage.MypageIndexAction#index(), {userId=22}, map:{PURCHASE = list:{selectCount}}, /mypage/}
/- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - (SQL now: PURCHASE#selectCount [00m00s003ms])
select count(*)
  from PURCHASE dfloc
-- org.dbflute.maihama.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.PurchaseIndexAction#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.dbflute.maihama.app.web.login.LoginIndexAction#index(): (via LoginIndexAction$$Lambda$12/475753501)
- - - - - - - - - -/
{00m01s633ms, 1424243415266/6(3), web.login.LoginIndexAction#index(), {userId=null}, map:{PRODUCT = list:{selectCount}}, /login/}
* * * * * * * * * */
  • それぞれのトランザクションが、開始されてからどのくらい経過しているのか？ e.g. 00m01s634ms
  • 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に乗ってないため)。

こちらは、後から追加された機能です(2015/02/24)。SAFluteの src/main/resources に jta+TransactionManager.dicon が存在すること、jdbc.diconで ConnectionPoolImpl の代わりに HookedConnectionPool が設定されていることが前提です。 (なければ、最新のSAFluteを参考に)

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]

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

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だけをみてもなかなかわかりません。

そこで、SAFluteでは、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}]

TypicalBaseAction の ActionCallback の before の中で SqlStringFilter が設定され、このログ出力が行われています。

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] saflute.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]

TypicalBaseAction の ActionCallback の before の中で SqlStringFilter が設定され、このログ出力が行われています。

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

e.g. あまりにひどい発行回数はWARNで警告 @Log

...-WARN (...) - *Too many SQL executions: {total=81, selectCB=3, entityUpdate=78, queryUpdate=0, outsideSql=0, procedure=0} in MemberListAction.doSearch()

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