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

[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 的代码已经添加了相关支持了