性能
性能的度量
构件点击统计(Artifact Hit)
Moqui根据配置XML文件中的server-stats.artifact-stats元素中的配置来保留关于构件使用(点击)和记时的统计。(MoquiDefaultConf.xml中的)有默认配置,你可以在运行时配置文件中覆盖。默认开发运行时配置文件(MoquiDevConf.xml)有比这记录更多信息的设置。
<server-stats bin-length-seconds="900" visit-enabled="true" visit-ip-info-on-login="true" visitor-enabled="true">
<artifact-stats type="AT_XML_SCREEN" persist-bin="true" persist-hit="true"/>
<artifact-stats type="AT_XML_SCREEN_CONTENT" persist-bin="true" persist-hit="false"/>
<artifact-stats type="AT_XML_SCREEN_TRANS" persist-bin="true" persist-hit="true"/>
<artifact-stats type="AT_SERVICE" persist-bin="true" persist-hit="false"/>
<artifact-stats type="AT_ENTITY" persist-bin="false"/>
</server-stats>
这些设置为页面、页面内容(页面下的内容)和页面转换的每次点击创建一条ArtifactHit记录。也为那些加上服务调用创建ArtifactHitBin记录。
这有一些ArtifactHit记录的例子,第一条是FindExample.xml页面的点击,第二条是tools应用中的DataExport.xml页面中的EntityExport.xml转换的点击。EntityExport.xml转换的点击有参数被记录在*parameterString8属性中。
<moqui.server.ArtifactHit lastUpdatedStamp="1519659626210" artifactType="AT_XML_SCREEN" hitId="120531" artifactSubType="text/html" runningTimeMillis="893.634543" userId="EX_JOHN_DOE" serverHostName="DEJCMBA3.local" startDateTime="1519659623359" visitId="100000" isSlowHit="N" artifactName="component://example/screen/ExampleApp/Example/FindExample.xml" requestUrl="http://localhost:8080/apps/example/Example/FindExample.vuet" wasError="N" serverIpAddress="172.16.7.38"/>
<moqui.server.ArtifactHit visitId="100001" userId="EX_JOHN_DOE" artifactType="transition" artifactName="component://tools/screen/Tools/Entity/DataExport.xml#EntityExport.xml" parameterString="moquiFormName=ExportData, output=file, filterMap=[artifactType:"screen"],entityNames=moqui.server.ArtifactHit" startDateTime="1519659645354" runningTimeMillis="45" wasError="N" requestUrl="http://localhost:8080/apps/tools/Entity/DataExport/EntityExport.xml" serverIpAddress="172.16.7.38" serverHostName="DEJCMBA3.local"
lastUpdatedStamp="1519659655367"/>
在一个web应用中,为每个会话有一条Visit记录,有关于会话的细节,和ArtifactHit记录通过visitId联系在一起。一旦一个用户登录,Visit将跟踪登录的userId,但是在这之前,访问被用visitorId关联在一起,visitorId在服务中用一条Visitor记录跟踪,在浏览器/客户端中用一个cookie和会话关联在一起,即使在会话中没有用户登录。
<moqui.server.Visit serverHostName="DEJCMBA3.local" visitId="100000" serverIpAddress="172.16.7.38" initialLocale="en_US" clientHostName="0:0:0:0:0:0:0:1" clientIpAddress="0:0:0:0:0:0:0:1" lastUpdatedStamp="1518105351875" initialUserAgent="Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.39 Safari/537.36" sessionId="HZ672180F154294278BDDE614BEC24F815" userId="EX_JOHN_DOE" fromDate="1518105335387" webappName="ROOT" initialRequest="http://localhost:8080/" visitorId="100000"/>
为一个构件上的每个点击创建一条记录,对性能会有影响,在繁忙的服务器上数据库规模会变得非常大。可以用例如OrientDB这样的低延迟插入数据库或其他的NoSQL数据库来减轻。如果你只想统计一段时间的性能,并且不需要单个的点击记录以审计或详细分析,ArtifactHitBin 记录就够了。
这些记录是在 binStartDateTime和binEndDateTime之间的一段时间内地一个构件的点击概要。bin的长度用server-stats.bin-length-seconds属性配置,默认为900秒(15分钟)。
这是一个create#moqui.entity.EntityAuditLog服务的点击箱的例子。在此例中,它被点击/使用了77次,总(累计)运行时间252毫秒,意味着这个箱子中的构件的平均运行时间是3.27毫秒。
<moqui.server.ArtifactHitBin hitBinId="100010" artifactType="service" artifactSubType="entity-implicit" artifactName="create#moqui.entity.EntityAuditLog" serverIpAddress="172.16.7.38" serverHostName="DEJCMBA3.local" binStartDateTime="1518022242341" binEndDateTime="1518023142341" hitCount="16" totalTimeMillis="0.866639" minTimeMillis="0.017091" totalSquaredTime="0.074119" slowHitCount="0" maxTimeMillis="26.408371" lastUpdatedStamp="1518023202408"/>
这些可以直接在Tools应用中用Artifact Bins和Artifact Summary页面查询数据库中的数据。
构件执行运行时分析
Java分析器例如JProfiler是分析Java方法的性能的很好的工具,但是不知道Moqui构件例如页面、转换、服务和实体。Moqui构件执行Facade在内存中为每个实例(每个ExecutionContext,例如一个web请求等)在它们运行时跟踪构件的性能详情。
数据被保存在当每个构件运行时创建的ArtifactExecutionInfo对象中,并被推上执行栈并保存到执行历史中。你可以用ec.artifactExecution.getStack()和ec.artifactExecution.getHistory()方法来访问这些。
从 ArtifactExecutionInfo 实例你可以获得它自身的运行时间(long getRunningTime()),调用它的构件(ArtifactExecutionInfo getParent()),它调用的构件(List<ArtifactExecutionInfo> getChildList()),它调用的所有构件的的运行时间(long getRunningTime()),基于那的只是这个构件的运行时间(long getThisRunningTime(),它是getRunningTime() - getChildrenRunningTime())。你也能用print(Writer writer, int level, boolean children)为当前构件信息和可选的它的递归的子构件的这些统计打印一个报表。
对于一个复杂的代码段,像下一个执行很多服务调用的订单,会有很多的数据。要让它易于跟踪到花了最多时间的部分,用ArtifactExecutionInfoImpl类上的这个方法来生成一个热点列表:
static List<Map> hotSpotByTime(List<ArtifactExecutionInfoImpl> aeiiList, boolean ownTime, String orderBy)
这个方法翻找执行历史中所有的ArtifactExecutionInfoImpl实例并合计以为每个构件创建一个有以下条目的Map: time, timeMin, timeMax, count, name, actionDetail, artifact type 和 artifact action。
另一个情况是你运行一个进程很多次来获得更好的平均统计时会有很多数据。这个场景中,在历史中会有成百或上千条构件执行信息。要把多个运行的数据合计到单个关于每个构件及其子构件执行的树中,用这个方法:
List<Map> consolidateArtifactInfo(List<ArtifactExecutionInfoImpl> aeiiList)
每个Map有这些条目: time, thisTime, childrenTime, count, name, actionDetail, childInfoList, key(它是: name + ':' + typeEnumId + ':' + actionEnumId + ':' + actionDetail), type 和 action。有了这些结果,你可以用这个方法以纯文本(最好是用等宽字体)的方式带缩进地打印出这棵树:
String printArtifactInfoList(List<Map> infoList)
使用这些方法的一个例子是POP商务应用中的TestOrders.xml页面。用一个像这样的URL并显示下了指定数量的订单并运送的代码的性能分析结果页面。
http://localhost:8080/popc/TestOrders?numOrders=10
这是运行测试代码并用上述方法获取性能统计的页面动作脚本的代码片段:
def artifactHistory = ec.artifactExecution.history ownHotSpotList = ArtifactExecutionInfoImpl.hotSpotByTime(artifactHistory, true, "-time")
totalHotSpotList = ArtifactExecutionInfoImpl.hotSpotByTime(artifactHistory, false, "-time")
List<Map> consolidatedList = ArtifactExecutionInfoImpl.consolidateArtifactInfo(artifactHistory)
String printedArtifactInfo = ArtifactExecutionInfoImpl.printArtifactInfoList(consolidatedList)
这是一个订购并运送25条订单的性能分析页面的Artifacts by Own Time部分的前几行的例子:
从这些结果我们可以看到,花时间最多的是在OrderItem实体上做一个实体查看(查找)列表操作。这次运行中,关闭了place#Order和ship#OrderPart服务的事务缓存,OrderItem实体没有被用实体缓存来缓存,所以它在运行中查询了801次。事务缓存时一个连续写入缓存,将缓存写入的记录并像这样读取。将其开启后,总的来说,每秒订单数从0.8左右到了1.4左右(我自己的便携电脑和Derby数据库),Artifacts by Own Time的输出看起来非常不一样:
下面是Consolidated Artifacts Tree部分的示例输出。它展示了在父、子构件的上下文中的每个构件的多次运行的合计和每次运行内的构件的层级信息。在解析这些结果时,注意每个构件的总计时间不仅仅是那个构件作为展示的父构件的子构件运行的信息,而是那个构件的所有运行信息。主要价值在于跟踪使用得最多、最繁忙的构件在哪里,并确切理解在运行时确实做了些什么,特别是对特定的服务。
在输出中,每行的格式是:
[${time}:${thisTime}:${childrenTime}][${count}] ${type} ${action} ${actionDetail} ${name}
这是示例输出,注意为了更好的格式,某些构件的名字被省略缩短了:
[ 16: 3: 13][ 2] Screen View component://webroot/screen/webroot.xml
| [ 13:-41: 54][ 3] Screen View component://PopCommerce/…/PopCommerceRoot.xml
| | [ 165:165: 0][126] Entity View one mantle.product.store.ProductStore
| | [ 0:-31263:31263][ 3] Screen View component://PopCommerce/…/TestOrders.xml
| | | [ 3: 3: 0][ 3] Entity View one moqui.security.UserAccount
| | | [ 5: 5: 0][ 1] Entity View one moqui.server.Visit
| | | [ 6: 1: 5][ 1] Service Create create#moqui.security.UserLoginHistory
| | | | [ 5: 5: 0][ 1] Entity Create moqui.security.UserLoginHistory
| | | [ 4700:269:4431][ 75] Service All …OrderServices.add#OrderProductQuantity
| | | | [ 632:632: 0][300] Entity View list mantle.order.OrderPart
| | | | [ 497:497: 0][375] Entity View one mantle.order.OrderPart
| | | | [ 165:165: 0][126] Entity View one mantle.product.store.ProductStore
| | | | [ 195:195: 0][ 25] Entity View list mantle.order.OrderHeaderAndPart
| | | | [ 328: 21:307][ 25] Service Create mantle.order.OrderServices.create#Order
| | | | | [ 146: 12:134][ 25] Service Create create#mantle.order.OrderHeader
| | | | | | [ 134: 97: 37][ 25] Entity Create mantle.order.OrderHeader
| | | | | | | [ 1564:406:1158][950] Service Create create#moqui.entity.EntityAuditLog
| | | | | | | | [ 83: 83: 0][ 30] Entity View one moqui.entity.SequenceValueItem
| | | | | | | | [ 90: 90: 0][ 30] Entity Update moqui.entity.SequenceValueItem
| | | | | | | | [ 1025:1025: 0][950] Entity Create moqui.entity.EntityAuditLog
| | | | | [ 161: 11:150][ 25] Service Create create#mantle.order.OrderPart
| | | | | | [ 632:632: 0][300] Entity View list mantle.order.OrderPart
| | | | | | [ 134: 99: 35][ 25] Entity Create mantle.order.OrderPart
| | | | | | | [ 1564:406:1158][950] Service Create create#moqui.entity.EntityAuditLog
| | | | | | | | [ 83: 83: 0][ 30] Entity View one moqui.entity.SequenceValueItem
| | | | | | | | [ 90: 90: 0][ 30] Entity Update moqui.entity.SequenceValueItem
| | | | | | | | [ 1025:1025: 0][950] Entity Create moqui.entity.EntityAuditLog
| | | | [ 1838:1838: 0][801] Entity View list mantle.order.OrderItem
| | | | [ 882:844: 38][ 75] Service All …PriceServices.get#ProductPrice
| | | | | [ 38: 38: 0][150] Entity View list mantle.product.ProductPrice
| | | | [ 2324: 83:2241][ 75] Service Create …OrderServices.create#OrderItem
| | | | | [ 430:430: 0][575] Entity View one mantle.product.Product
| | | | | [ 2747: 64:2683][100] Service Create create#mantle.order.OrderItem
| | | | | | [ 1838:1838: 0][801] Entity View list mantle.order.OrderItem
| | | | | | [ 2482:384:2098][100] Entity Create mantle.order.OrderItem
| | | | | | | [ 1564:406:1158][950] Service Create create#moqui.entity.EntityAuditLog
| | | | | | | | [ 83: 83: 0][ 30] Entity View one moqui.entity.SequenceValueItem
| | | | | | | | [ 90: 90: 0][ 30] Entity Update moqui.entity.SequenceValueItem
| | | | | | | | [ 1025:1025: 0][950] Entity Create moqui.entity.EntityAuditLog
| | | | | | | [ 1784: 89:1695][100] Service Update …OrderServices.update#OrderPartTotal
| | | | | | | | [ 1838:1838: 0][801] Entity View list mantle.order.OrderItem
| | | | | | | | [ 322:127:195][250] Service All …OrderServices.get#OrderItemTotal
| | | | | | | | | [ 1838:1838: 0][801] Entity View list mantle.order.OrderItem
| | | | | | | | [ 497:497: 0][375] Entity View one mantle.order.OrderPart
| | | | | | | | [ 1204:686:518][200] Entity Update mantle.order.OrderPart
| | | | | | | | | [ 224:224: 0][200] Entity View refresh mantle.order.OrderPart
| | | | | | | | | [ 1564:406:1158][950] Service Create create#…EntityAuditLog
| | | | | | | | | | [ 83: 83: 0][ 30] Entity View one moqui.entity.SequenceValueItem
| | | | | | | | | | [ 90: 90: 0][ 30] Entity Update moqui.entity.SequenceValueItem
| | | | | | | | | | [ 1025:1025: 0][950] Entity Create moqui.entity.EntityAuditLog
| | | | | | | | [ 629: 56:573][100] Service Update …update#OrderHeaderTotal
| | | | | | | | | [ 632:632: 0][300] Entity View list mantle.order.OrderPart
| | | | | | | | | [ 349:349: 0][450] Entity View one mantle.order.OrderHeader
| | | | | | | | | [ 884:592:292][175] Entity Update mantle.order.OrderHeader
| | | | | | | | | | [ 181:181: 0][175] Entity View refresh mantle.order.OrderHeader
| | | | | | | | | | [ 1564:406:1158][950] Service Create create#…EntityAuditLog
| | | | | | | | | | | [ 83: 83: 0][ 30] Entity View one …SequenceValueItem
| | | | | | | | | | | [ 90: 90: 0][ 30] Entity Update …SequenceValueItem
| | | | | | | | | | | [ 1025:1025: 0][950] Entity Create moqui.entity.EntityAuditLog
提升性能
一旦一个构件或代码块被识别出运行花了很多时间,下一步就是回顾看看哪部分能改善。有时操作就是要花时间没什么好改善的。甚至在那种情况,那些部分可以被改成异步或用其他实现方式来至少最小化对用户或系统资源的影响。
最慢的操作通常涉及数据库或文件访问,对此内存缓存能帮上很多忙。Moqui的Cache Facade被用在框架的各个部分,并且可以被你的代码直接按需用于缓存。Moqui默认使用ehcache做实际的缓存,Moqui配置XML文件中的配置设置被直接传给它。其他的缓存配置是ehcache特定的,可用它的文件(注意是ehcache.xml)来设置。这特别有用于设置像在一个app服务集群中的分布式缓存的内容。
在开发的运行时配置(MoquiDevConf.xml),对于像实体、服务定义、XML页面、脚本和模板的构件的缓存的过期时间比较短,这样它们被频繁加载,以便改变文件后的测试。在生产配置(MoquiProductionConf.xml),缓存被全面使用以获得最好的性能。当执行性能测试时,确保运行时缓存被全面使用,即使用生产设置,这样数字不会因为虽然非常慢但不会在生产环境中发生的事情带偏。
ResourcesFacade有很多缓存。getLocationText(String location, boolean cache)方法在cache参数设置为true时使用resource.text.location 缓存。还使用了其他的缓存,包括(如果可能,用脚本解释器或模板渲染器)编译后的脚本和模板,甚至ResourceFacade完成的Groovy表单式和扩展后的字符串。如上所述,这些不会被“禁止”,要帮助运行时的重载,最简单的方式时在期望的缓存上使用超时。
另一个常见的缓存是由EntityFacade管理的实体缓存。单个记录、列表结果和计数结果都有缓存。这些缓存在记录被通过EntityFacade创建、更新、或删除时被自动清理。要使得缓存清理更有效,默认使用了一个反向关联缓存来按记录的实体名和主键值查找缓存条目。在其他的场景中(例如创建一条记录),必需对缓存条目上的条件做一个扫描,以找到匹配的要清理的条目,特别是列表和计数缓存。更多细节请查看 数据和资源 章节。
处理实体读缓存外,有一个直写(write-through)的事务前(pre-transaction)缓存,能用service.transaction属性通过设置它为cache或force-cache来开启。这个的实现在 TransactionCache.groovy 文件中。
基本的想法是当创建、更新或删除一条记录时,在一个于事务关联的对象中记下来,而不是真实地写到数据库。当事务提交时,但是在实际提交前,把变更写到数据库。当查找操作完成时,直接使用缓存中的值或用缓存中的值增加到来自数据库的查询结果中。
它甚至聪明到指定当用一个约束查找时,只匹配(通过它创建的)TX缓存中的值。完全无需去到数据库,查询完全在内存中处理。例如如果你创建一条OrderHeader记录,然后多个OrderItem记录,然后再用orderId查询所有的OrderItem记录,它将看是否这条OrderHeader记录是通过事务缓存创建的,如果是,就从TX缓存中得到OrderItem记录,不在数据库中查询它们。
对于实体的查找操作,另一个有价值的工具是视图实体的自动最小化。当你在一个很大的视图实体上做查找时,例如FindPartyView实体,务必要指定选择的字段并限制它为只是你需要的字段。EntityFacade将自动查看被选择的、用在条件中的和用来排序结果的字段,并只包括它们必要的的别名字段和成员实体。有了这个实现,无需使用动态视图实体(EntityDynamicView)来条件地添加成员实体和别名字段。回到FindPartyView的例子,find#Party服务(在findParty.groovy中实现)使用这个用非常少的代码提供很多的选项。
一般的指导原则,当查询有非常多数据的表时,不要让数据库做多余的事情。在一个视图实体中联结太多的成员实体就非常的壮观,因为创建巨大的临时表是非常昂贵的操作。
另一个常见的场景是执行一个会返回非常大数量结果的查找,然后一次只展示一页结果(例如20条)。最好是在主查询中不选择要为每条记录显示的所有的数据,因为这使得联结的临时表非常大。只查询数据库只获取20条或将显示的条数而不是所有。更好的方法是只擦好像足够世博记录的字段,然后再单独查询那些要显示的字段。这一般会更快,很少情况下不是,所以用真实数据测试一下这些和其他的查询变化看看对于特定场景哪个性能最好,仍然是很好的。
在高容量的生产电子商务和ERP系统中,另一个常见的问题是同步和锁延迟。这些会发生在用Java同步的应用服务器中,或用所和锁等待的数据库中。你也会发现死锁,但那是另一个问题(即和性能分开)。确实发现这些的唯一办法是性能测试,特别是使用尽可能同样的资源,像同一个产品的大量订单,以尽可能地接近实际的时间。
有一些办法来提高改善。Java同步层面,使用非阻塞算法和数据结构,区别会非常大。有许多库在朝这个方向改进。Brian Goetz的《Java Concurrency in Practice》是关于这个话题的一本好书。
除了这些基本事情外,要留意有无数的方法来提高性能。对于重要的代码,特别是使用最多或对性能最敏感的功能,在合理约束的范围内,它能运行多快的唯一限制通常是能投入性能测试和优化的时间和努力。
有时这涉及重要的创新和使用非常不同的架构、工具来处理像大量用户、非常大量的数据、数据分散在许多地方等等这些事情。对于某些问题,像Hadoop和OrientDB(和无数其他这些)这样的分布式处理或数据存储工具会是你想要的,即使使用它们会需要更多努力,并且它们只对某些非常特殊的功能有用。
当用像JProfiler这样的工具进行Java分析时,除了查看Moqui构件执行性能数据以外,你一般查看影响性能的各种不同的东西。上面那些在更高层次上优化业务逻辑上做得更多,处理那些,要优化Java方法(和为内存使用的类),也有许多不同的工具和指导原则。