新增完整执行时间统计的建议

[superbase-zz]

sql输出执行时间是个很不错的功能，弥补性能调优中代码中执行SQL代码段大量存在计算耗时的代码，非常实现。 在web性能调优中，大致需求如下： 1，输出整个页面从用户进入到页面输出的总时间； 2，在Jfinal的应用中，我们还会经常使用Directive自定义指令，还需要知道每个Directive输出耗时，便于知道耗时在哪 3，部分Render也会定义一些function,比如#define paginate，虽然一般耗时短，但也想明明白白知道耗时。 目前我的简单思路是： 1，写一个Handler,把优先级调到最高，这样所有的请求都包含在里面， Stopwatch watch = Stopwatch.createStarted(); next.handle(target, request, response, isHandled); long time = watch.elapsed(TimeUnit.MILLISECONDS); logger.error("spendTime:{},{}", time, target); 2，在JbootDirectiveBase中 @Override public void exec(Env env, Scope scope, Writer writer) { Stopwatch watch = Stopwatch.createStarted(); scope = new Scope(scope); scope.getCtrl().setLocalAssignment(); exprList.eval(scope); onRender(env, scope, writer); long time = watch.elapsed(TimeUnit.MILLISECONDS); //需要反射获取子类的@JFinalDirective名称和类名 //logger.error("spendTime:{},{}", time, target); } 3,写一个public class TimeRender extends TemplateRender @Override public void render() { Stopwatch watch = Stopwatch.createStarted(); super.render(); long time = watch.elapsed(TimeUnit.MILLISECONDS); logger.error("spendTime:{},{}", time, this.getView()); } 海哥看看能否增加.

[superbase-zz]

如果想在页面上输出这个总的执行时间，这方式貌似有问题，在next.handle(target, request, response, isHandled)前后记录时间差。差值是在handle之后，页面已经处理完了。

[yangfuhai]

这个之前早就支持了，jboot 中已经输出了整个请求执行的时间。

[superbase-zz]

这个之前早就支持了，jboot 中已经输出了整个请求执行的时间。

你那仅仅输出了调用controller之前到方法invoke后的时间，后面还有render的解析时间。 if (devMode) { long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time);

[yangfuhai]

这个之前早就支持了，jboot 中已经输出了整个请求执行的时间。

你那仅仅输出了调用controller之前到方法invoke后的时间，后面还有render的解析时间。 if (devMode) { long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time);

开发工具中输出的时间就是整个 Controller执行的时间 + 所有 html 质量渲染的时间 + 输出到网络的时间。如果您这边确定要知道 每个方法的时间，建议引入 skywalking 之类的第三方 APM 框架才是正确的选择。

[superbase-zz]

这个之前早就支持了，jboot 中已经输出了整个请求执行的时间。

你那仅仅输出了调用controller之前到方法invoke后的时间，后面还有render的解析时间。 if (devMode) { long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time);

开发工具中输出的时间就是整个 Controller执行的时间 + 所有 html 质量渲染的时间 + 输出到网络的时间。如果您这边确定要知道 每个方法的时间，建议引入 skywalking 之类的第三方 APM 框架才是正确的选择。

实际情况并非如此，理由如下： if (devMode) { //计时开始 long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time); //sb.append("----------------------------------- taked " + (System.currentTimeMillis() - time) + " ms ------ //上一句中仅仅输出了controller里的invoke后的时间。，然而看看JbootActionHandler后面的部分， } } else { invocation.invoke(); }

        **Render render = controller.getRender();**

render.setContext(request, response, action.getViewPath()).render(); 如果页面里面使用了自定义函数或Directive等内容，则消耗的时间完全没有包含在内。 我现在作法就是，定义一个handler,进入时封装，并将guava的Stopwatch初始后存在Handler的ThreadLocal中。 一直到handler的next.handle(target, request, response, isHandled); 结束，才输出总共的耗时。 因为我在controller中几乎没有什么业务代码，仅仅接收几个参数，主要业务都变成了多个Directive的调用，整个过程最后输出的耗时和Jboot中 taked xx ms的时间相差非常大。

[yangfuhai]

这个之前早就支持了，jboot 中已经输出了整个请求执行的时间。

你那仅仅输出了调用controller之前到方法invoke后的时间，后面还有render的解析时间。 if (devMode) { long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time);

开发工具中输出的时间就是整个 Controller执行的时间 + 所有 html 质量渲染的时间 + 输出到网络的时间。如果您这边确定要知道 每个方法的时间，建议引入 skywalking 之类的第三方 APM 框架才是正确的选择。

实际情况并非如此，理由如下： if (devMode) { //计时开始 long time = System.currentTimeMillis(); try { invocation.invoke(); } finally { JbootActionReporter.report(target, controller, action, invocation, time); //sb.append("----------------------------------- taked " + (System.currentTimeMillis() - time) + " ms ------ //上一句中仅仅输出了controller里的invoke后的时间。，然而看看JbootActionHandler后面的部分， } } else { invocation.invoke(); }

        **Render render = controller.getRender();**

render.setContext(request, response, action.getViewPath()).render(); 如果页面里面使用了自定义函数或Directive等内容，则消耗的时间完全没有包含在内。 我现在作法就是，定义一个handler,进入时封装，并将guava的Stopwatch初始后存在Handler的ThreadLocal中。 一直到handler的next.handle(target, request, response, isHandled); 结束，才输出总共的耗时。 因为我在controller中几乎没有什么业务代码，仅仅接收几个参数，主要业务都变成了多个Directive的调用，整个过程最后输出的耗时和Jboot中 taked xx ms的时间相差非常大。

render.setContext(request, response, action.getViewPath()).render(); 这行代码，就已经包含了指令（Directive）、和自定义函数的执行时间了。你可以自己测试下看，比如自定义一个指令，让这个指令里休眠 几秒钟。然后看看结果。

[superbase-zz]

完全同意你上面的前一段，问题是你这段代码是输出take time之后才执行的，还能统计？

[yangfuhai]

完全同意你上面的前一段，问题是你这段代码是输出take time之后才执行的，还能统计？

确实是我理解有问题了，之前的代码并不包含 指令 的消耗时间，刚刚 push 的代码已经添加了相关支持了