近半年的项目实践让我们注意到了seam2.0.2的conversation的性能问题。测试人员抱怨系统速度慢的时候,我们一开始以为是由于数据库查询导致的性能问题。但是经过各方面排查,我们发现一个不做数据库操作的简单页面,就算是按照前文《优化richfaces,给seam提速》操作后,同样会很慢。于是我们开始怀疑起 seam本身了。一个无意中的试验发现,我把一个以前放在conversation scope内的组件换成 page scope后,速度一下子提高了五六倍。今天通过对日志的分细,证实了我的感觉。
我写了一个timefilter,记下服务器从接到http request到生成后http response后总共花掉了多少时间。被测试的action是一个普通的java bean,共有二十多个property, 里面有一个业务方法。在不改变其它代码,只改变这个java类前的annotation, 把 scope 从conversation改成page后,测试十次,page scope时要比conversation时快5到10倍!这个测试结果确实是非常地让我惊讶!conversation scope的组件到底有什么特殊的呢?
为了能够观查到seam内部的运作情况,我把org.jboss的log设成debug级别的,现在点一下页面,一个post->redirect->get,在使用page scope时会产生 1 万多行日志,而conversation scope时居然会产生 近 3 万条日志!光从这个日志的数目就可以看到 conversation 在背后不只是做了一点点工作呀!再仔细对比两者的日志,会发现,conversation scope里会多出许多处理事件的日志:instantiating Seam component: org.jboss.seam.core.events 。这句日志在conversation时出现了 3630次,而 page scope时只出现了 1464次。conversation的日志里多出了大量如下日志:
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.preRemoveVariable.supplierSearchAction.supplierName
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.postRemoveVariable.supplierSearchAction.supplierName
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.preRemoveVariable.supplierSearchAction.employee
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.postRemoveVariable.supplierSearchAction.employee
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.preRemoveVariable.supplierSearchAction.state
2008-06-24 14:23:32,592 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.Component] instantiating Seam component: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.Component] initializing new instance of: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.Component] done initializing: org.jboss.seam.core.events
2008-06-24 14:23:32,593 DEBUG [org.jboss.seam.core.Events] Processing event:org.jboss.seam.postRemoveVariable.supplierSearchAction.state
从日志中可以看出seam 处理了大量的 org.jboss.seam.preRemoveVariable 和 org.jboss.seam.postRemoveVariable 事件,类似的事件还有 org.jboss.seam.preSetVariable 和 org.jboss.seam.postSetVariable。Seam疯狂地为conversation scope里的组件里的property 都产生了一遍这些事件。更可怕的是,并不是处理一遍,而是会处理很多遍,在我的这个测试的例子中,它处理了47遍! 这一算,1 action * 30 properties * 2 events * N times * M event listners,不是一个小数目呀,在我这个没有event observer的例子中,N = 47, 会有 1 * 30 * 2 * 47 * 1 = 2847 次操作!通过日志还可以看出 把 supplierSearchAction的所有的properties走一遍事件,要花掉 208ms, 那么 47 次这样的操作,需要 47 * 208 = 9682ms ! 9秒多的时间,绝对不是一下小数目,改成page scope后快,就快在这里。(208 / 30) * 47 = 326ms,每个bean的property, 在这个例子中消耗掉了 0.3秒时间,好昂贵呀。幸好我们公司的服务器比较牛,能够把这个差距的绝对值缩到很小,但是,这无疑是一种对CPU的浪费。
这样看来,conversation是不能乱用的,不能随便把个组件就置成conversation scope的,能把逻辑用page scope, event scope, stateless scope搞定,就尽量不要用conversation。如果有多个页面交互等操作,适合于用conversation的,那也要尽量减少 conversation scope内组件的 properties, 把 conversation 内的组件做成功能明确单一的最好。
其实,我的项目中把 supplierSearchAction放在conversation scope里就是不必要的,因为search动作都是在一个页面内完成的,用 page scope就足够了。不仅如此,还把页面上的很多输入框等通过绑定,直接绑定到conversation scope的组件上。以后再用seam的时候,一定要小心使用conversation scope了。也期待着seam的新版本能把conversation scope的组件性能提高!