北京HS性能优化总结
这次在HS现场对几个主要单据做了性能问题的分析和优化,二次开发的和能现场解决的都做了优化,涉及到标准产品结构的只是分析出来了问题,优化工作只能由标准产品项目组来完成。
对这次的分析和优化总结了些经验和大家分享,希望能对大家有所启发和帮助。
一、 配餐单
配餐单是客户用得最多的一个模块,每天都有十几个客户端在使用,从上线至今,叙事簿刷新的速度越来越慢,1500行记录的叙事簿要半分钟左右才能刷出来,性能问题比较严重。
一开始还想叙事簿这么简单的界面用了这么多,怎么会这么慢,是不是框架出问题了?通过和研发EAS BOS部门的沟通和分析,排除了框架的问题,定位到了现场二次开发的代码上,我们来看看现场配餐单叙事簿有问题的代码:
protected void refresh(ActionEvent arg0) throws Exception {
super.refresh(arg0);
setColor();
}
public void setColor() {
try {
for (int i = 0; i < this.tblMain. getRowCount (); i++) {
if (this.tblMain.getRow(i).getCell("close").getValue().toString().equals("true")) {
continue;
}
/*PeicanInfo pi = new PeicanInfo();
pi = ipc.getPeicanInfo(new ObjectUuidPK(tblMain.getRow(i).getCell("id").getValue().toString()));
if(pi.getE6().size()>0){
this.tblMain.getRow(i).getStyleAttributes().setBackground(Color.yellow);
}*/
if (this.tblMain.getRow(i).getCell("quxiao").getValue().toString().equals("true")) {
this.tblMain.getRow(i).getStyleAttributes().setFontColor(Color.red);
}
}
} catch (Exception e) {
this.handUIException(e);
}
}
乍一看,没什么问题,就是对当前叙事簿的表格所有行循环设置颜色,不应该有性能影响,但仔细分析就发现问题了,叙事簿是虚模式的,每次只取100行数据回来,但tblMain的总行数是所有的符合条件的结果集行数,所以当以上循环走到第101行时红字行会取不到数值行了,触发tblMain取下个100行,所以又要做一次服务端取数,本例中共1500行所以总共要取15次,每次进入此叙事簿和刷新都会导致15次Rpc,加上同时运行的客户端较多,导致等待的时间更长。具体RPC调用时间如下:
com.kingdee.eas.pc.client.PeicanListUI.initUIObject() (no.1)
current thread: AWT-EventQueue-0
stack level: 1
==============rpcInvoke start==============
com.kingdee.eas.pc.ITable.createObject()
time: 110 ms request: 77 B response: 16 B
com.kingdee.eas.pc.ITable.getServerDate() java.util.Date
time: 0 ms request: 32 B response: 50 B
com.kingdee.eas.pc.IHangDuan.createObject()
time: 47 ms request: 80 B response: 16 B
com.kingdee.eas.pc.IFPlanNO.createObject()
time: 31 ms request: 79 B response: 16 B
com.kingdee.eas.ps.IMachineType.createObject()
time: 47 ms request: 83 B response: 16 B
com.kingdee.eas.pc.IPlan.createObject()
time: 47 ms request: 76 B response: 16 B
com.kingdee.eas.pc.IPeican.createObject()
time: 62 ms request: 78 B response: 16 B
com.kingdee.eas.pc.IPeicanEntry.createObject()
time: 47 ms request: 83 B response: 16 B
com.kingdee.eas.pc.ITable.getServerDate() java.util.Date
time: 0 ms request: 32 B response: 50 B
com.kingdee.eas.base.license.ILicenseSrvAgent.requestLicense(com.kingdee.eas.base.license.LicenseUserInfo, java.lang.String) int
time: 0 ms request: 419 B response: 85 B
com.kingdee.eas.base.permission.service.helper.IPermissionParameter.createObject()
time: 15 ms request: 169 B response: 16 B
com.kingdee.eas.base.permission.service.helper.IPermissionParameter.isIDAuthorizeEnabled() boolean
time: 0 ms request: 32 B response: 51 B
com.kingdee.eas.base.permission.IPermission.checkFunctionPermission(com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.metadata.IMetaDataPK) void
time: 0 ms request: 759 B response: 9 B
com.kingdee.eas.basedata.org.IOrgSwitchFacade.createObject()
time: 47 ms request: 97 B response: 16 B
com.kingdee.eas.basedata.org.IOrgSwitchFacade.getSwitchOrgs(java.lang.String) java.util.HashMap
time: 62 ms request: 79 B response: 4529 B
com.kingdee.eas.base.commonquery.IQuerySolutionFacade.createObject()
time: 63 ms request: 105 B response: 16 B
com.kingdee.eas.base.commonquery.IQuerySolutionFacade.getDefaultSolution(java.lang.String, java.lang.String) com.kingdee.eas.base.commonquery.QuerySolutionInfo
time: 46 ms request: 110 B response: 2382 B
----------com.kingdee.eas.base.commonquery.client.CommonQueryUI.initUIObject()
time: 0 ms request: 0 B response: 0 B
com.kingdee.eas.framework.config.IUserCustomConfig.getValue(com.kingdee.bos.dao.IObjectPK) com.kingdee.eas.framework.config.UserCustomConfigInfo
time: 15 ms request: 548 B response: 1060 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.createObject()
time: 94 ms request: 4646 B response: 16 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.doAllQueryTask(com.kingdee.util.Uuid, int, int, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, [Ljava.lang.String;, boolean) java.util.Map
time: 953 ms request: 1622 B response: 11001 B
com.kingdee.eas.base.permission.IPermission.getQueryFieldPermission(com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.dao.IObjectPK) com.kingdee.eas.base.permission.FieldPermission
time: 47 ms request: 771 B response: 1005 B
com.kingdee.eas.pc.IPeican.getType() com.kingdee.bos.util.BOSObjectType
time: 0 ms request: 32 B response: 66 B
com.kingdee.bos.metadata.bot.IBOTMapping.createObject()
time: 93 ms request: 92 B response: 16 B
com.kingdee.bos.metadata.bot.IBOTMapping.isCanVoucher(java.lang.String) boolean
time: 16 ms request: 43 B response: 51 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 797 ms request: 1678 B response: 11139 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 390 ms request: 1680 B response: 12265 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 844 ms request: 1680 B response: 12369 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 750 ms request: 1680 B response: 13225 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 390 ms request: 1680 B response: 12540 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 390 ms request: 1680 B response: 11894 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 468 ms request: 1680 B response: 11944 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 860 ms request: 1678 B response: 12387 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 485 ms request: 1680 B response: 13907 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 406 ms request: 1680 B response: 13503 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 375 ms request: 1680 B response: 13503 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 766 ms request: 1680 B response: 13535 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 453 ms request: 1680 B response: 14068 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 406 ms request: 1676 B response: 14009 B
com.kingdee.bos.dao.query.server.IVirtualModeDataAccess.getRowSet(com.kingdee.util.Uuid, com.kingdee.bos.metadata.IMetaDataPK, com.kingdee.bos.util.BOSObjectType, com.kingdee.bos.metadata.entity.EntityViewInfo, java.util.Map, java.util.Map, com.kingdee.bos.dao.query.QueryExecuteOption, int, int) com.kingdee.jdbc.rowset.IRowSet
time: 1250 ms request: 1680 B response: 13938 B
com.kingdee.bos.metadata.bot.IBOTMapping.isCanVoucher(java.lang.String) boolean
time: 0 ms request: 43 B response: 51 B
com.kingdee.bos.metadata.bot.IBOTMapping.isCanVoucher(java.lang.String) boolean
time: 15 ms request: 43 B response: 51 B
==============rpcInvoke end==============
RPC Number: 41 SubAction Number: 1
rpc time: 10887 ms request: 35422 B response: 214859 B
stack rpc time: 11198 ms stack request: 39291 B stack response: 222331 B
action time: 23484 ms
可以看到叙事簿取数分15次完成,耗费了约23秒。
问题明确就好优化了,主要是将setColor()方法改为只刷新当前取道的100行的颜色,之前和之后的都不管,这样不访问还没取道客户端的行就不会触发取数。修改后的代码如下:
首先给tblMain注册数据填充后处理的监听器:
public void onLoad() throws Exception {
//需模式填充后的处理 Add by qyw 2008-05-05
tblMain.addKDTDataFillListener(new KDTDataFillListener() {
public void afterDataFill(KDTDataRequestEvent e)
{
try
{
tblMain_afterDataFill(e);
}
catch(Exception exc)
{
handUIException(exc);
}
}
});
......
其次再实现后处理的监听:
//需模式下填充行数据后的处理 Add by qyw 2008-05-05
private void tblMain_afterDataFill(KDTDataRequestEvent e){
for (int i = e.getFirstRow(); i <= e.getLastRow(); i++) {
if (this.tblMain.getRow(i).getCell("close").getValue().toString().equals("true")) {
continue;
}
if (this.tblMain.getRow(i).getCell("quxiao").getValue().toString().equals("true")) {
this.tblMain.getRow(i).getStyleAttributes().setFontColor(Color.red);
}
}
}
注意红颜色的就是取当前虚模式下取到并填充到tblMain中的第一行和最后一行。
修改后再测试,首次进入用时约2秒,查询速度提高约10倍(Rpc日志略)。
二、 综合比例表
综合比例表叙事簿打开时要自动打开一个新的UI,为查询比例表,里面的记录是对综合比例表的再查询,如下图:
这样的不是很复杂的界面在进入时耗费的事件在15秒左右,性能较低,打开代码来分析,发现弹出界面没有采用叙事簿的开发方式来做,而是从BillEditUI继承的一个UI,表格上的数据采用先取ID,然后把ID作为条件来通过ORMapping的来取,从跟踪的情况来看,主要是ORMapping取数太慢,代码如下:
底层ListUI中的代码:
public void onLoad() throws Exception {
super.onLoad();
String className = "com.kingdee.eas.pc.client.ChaXunTableEditUI";
UIContext map = new com.kingdee.eas.common.client.UIContext(this);
FilterInfo filterInfo = new FilterInfo();
EntityViewInfo evi = new EntityViewInfo();
ITable it = TableFactory.getRemoteInstance();
IPeoplePrivilige ipp = PeoplePriviligeFactory.getRemoteInstance();
CommonBean cb = ipp.getCommonSql("select t_pc_table.FID from t_pc_table inner join t_pc_tableentry on t_pc_tableentry.fparentid = t_pc_table.fid AND t_pc_tableentry.FCOMPLETE=0 where t_pc_table.fstate = 1 GROUP BY t_pc_table.FID");
String strPeiCanID = "";
for(int i=0;i<cb.getRowNum();i++){
strPeiCanID += cb.getCellStr(i,"FID")+",";
}
if (strPeiCanID.endsWith(",")) {
strPeiCanID = strPeiCanID.substring(0, strPeiCanID.length() - 1);
}
filterInfo.getFilterItems().add(
new FilterItemInfo("id", strPeiCanID,
CompareType.INCLUDE));
evi.setFilter(filterInfo);
TableCollection pco = it.getTableCollection(evi);
if(pco.size()>0){
map.put("data",pco);
uiWindowShow(className,map);
}
}
这个里面是取了ID的集合,然后再取出要填到弹出界面上的记录,但这个地方没有具体指名取哪些属性。
下面是弹出界面装载数据的方法:
public void loadFields() {
super.loadFields();
try {
TableCollection pco = (TableCollection) this.getUIContext().get("data");
Object[] piA = pco.toArray();
Arrays.sort(piA,new Comparator(){
public int compare(Object arg0, Object arg1) {
TableInfo pi0 = (TableInfo)arg0;
TableInfo pi1 = (TableInfo)arg1;
if(pi0.getLastUpdateTime().before(pi1.getLastUpdateTime())){
return 0;
}else{
return 1;
}
}
});
for (int i = 0; i < piA.length; i++) {
System.out.println("第几个餐谱"+i);
TableInfo pci= TableFactory.getRemoteInstance().getTableInfo(new ObjectUuidPK(BOSUuid.read(((TableInfo)piA[i]).getId().toString())));
// TableInfo pci=(TableInfo)piA[i];
kdtEntrys.addRow();
kdtEntrys.getCell(i, "yinid").setValue(pci.getId().toString());
kdtEntrys.getCell(i, "number").setValue(pci.getNumber().toString());
kdtEntrys.getCell(i, "tablename").setValue(pci.getName());
CustomerInfo ci= CustomerFactory.getRemoteInstance().getCustomerInfo(new ObjectUuidPK(BOSUuid.read(pci.getCompany()==null?"":pci.getCompany().getId().toString())));
kdtEntrys.getCell(i, "Customer").setValue(ci.equals("")?"":ci.getName());
MTypeInfo mi = MTypeFactory.getRemoteInstance().getMTypeInfo(new ObjectUuidPK(BOSUuid.read(pci.getFoodtype()==null?"":pci.getFoodtype().getId().toString())));
kdtEntrys.getCell(i, "canshitype").setValue(mi.equals("")?"":mi.getName());
kdtEntrys.getCell(i, "cangwei").setValue(pci.getCangwei().toString());
CycleInfo pi = CycleFactory.getRemoteInstance().getCycleInfo(new ObjectUuidPK(BOSUuid.read(pci.getMenucycle()==null?"":pci.getMenucycle().getId().toString())));
kdtEntrys.getCell(i, "cycle").setValue(pi.equals("")?"":pi.getName());
}
} catch (Exception e) {
e.printStackTrace();
}
}
这个方法里面对每一个id都分别调了一次服务器方法取数,这样等于总体上做了三次的查询,最后一次(上面这个方法的)最慢。
针对这个模块的查询给的优化方案就是弹出UI继承ListUI来做,绑定一个Query。
于是在BOS中先做了一个query,又做了一个从ListUI继承的叙事簿,最后在底层UI的Onload方法中直接打开新作的叙事簿,最后测试发现同样的数据,用叙事簿的方式只需要不到2秒就可以完成,而且程序也非常简单,所以在实际开发中大家要会“偷懒”,尽量选择框架提供的用最简单最有效的方案来开发,这样以后维护也比较方便。
三、 综合比例表保存
综合比例表的编辑界面是一个H-D-D结构的单据编辑界面,如下图,有6条分录,每条分录对应人数的分录表格有300行,所以最明细表总共有1800行的记录:
保存的后台RPC日志如下:
com.kingdee.eas.base.btp.IBTPManager.saveRelations(com.kingdee.eas.framework.CoreBillBaseInfo, com.kingdee.bos.metadata.bot.BOTRelationCollection) com.kingdee.bos.dao.IObjectPK : 919 times
current thread: RPC-1
==============start sql==============
FROM dual
timespan: 0
FROM "T_PC_TABLE" "T0" WHERE "T0"."FID" = ? AND ROWNUM <= 1
timespan: 0
FROM dual
timespan: 0
FROM "T_PC_TABLE" "T0" WHERE "T0"."FID" = ? AND ROWNUM <= 1
timespan: 0
FROM dual
timespan: 0
FROM "T_PC_TABLE" "T0" WHERE "T0"."FID" = ?
timespan: 0
FROM "T_PC_TABLEENTRY" "T0" WHERE "T0"."FPARENTID" = ? ORDER BY "T0"."FPARENTID" ASC, "T0"."FSEQ" ASC
timespan: 0
FROM "T_PC_TABLEE2" "T0" LEFT OUTER JOIN "T_PC_TABLEENTRY" "T1" ON "T0"."FPARENTID" = "T1"."FID" WHERE "T1"."FPARENTID" = ? ORDER BY "T0"."FPARENTID" ASC, "T0"."FSEQ" ASC
timespan: 266
FROM "T_PC_TABLEE3" "T0" WHERE "T0"."FPARENTID" = ? ORDER BY "T0"."FPARENTID" ASC, "T0"."FSEQ" ASC
timespan: 0
UPDATE T_PC_TABLE SET FCREATORID = ?, FCREATETIME = ?, FLASTUPDATEUSERID = ?, FLASTUPDATETIME = ?, FNUMBER = ?, FBIZDATE = ?, FDESCRIPTION = ?, FAUDITORID = ?, FNAME = ?, FCOMPANYID = ?, FCANGWEI = ?, FFOODTYPEID = ?, FFIRST = ?, FLEVEL = ?, FSDATE = ?, FEDATE = ?, FMENUCYCLEID = ?, FSTATE = ?, FALINEID = ?, FOLDFID = ?, FJINGXUANJIANGE = ?, FPERDAYJINGXUAN = ?, FISCANSHIDINGJIA = ?, FJIXING = ?, FISHIGH = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEENTRY SET FSEQ = ?, FMATERIALNUMID = ?, FMATERIALNAME = ?, FSNOTE = ?, FCOMPLETE = ?, FPTYPEID = ?, FBILI = ?, FCHANGEMT = ?, FCLIENTNUMBER = ?, FRELATIONTABLEID = ?, FISDUOCANGWEI = ?, FJIINGID = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
(这里省去了约17990条更新记录)
… …
Statement.executeBatch
timespan: 0
Statement.executeBatch
timespan: 0
Statement.executeBatch
timespan: 300297
==============end sql==============
sql time: 300563
invoke time: 302578
总耗时为302秒,由于单据是从BILLEditUI继承的,保存时没有写额外的代码,都是走框架的,所以基本上可以排除程序的问题,最有可能就是数据库了。检查T_PC_TABLEE2表发现居然没有对FID做索引,加上再测试,结果如下:
(前面的日志略去)
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
UPDATE T_PC_TABLEE2 SET FSEQ = ?, FNUM = ?, FMANNUM = ? WHERE FID = ?
timespan: 0
Statement.executeBatch
timespan: 0
Statement.executeBatch
timespan: 31
==============end sql==============
sql time: 422
invoke time: 4113
耗时约4秒,性能提升约75倍。
四、 采购申请单下推生成采购订单
采购申请单批量选择生成采购订单,客户反馈生成过程中自动弹出订单编辑界面需要手工提交才可以正确保存,但由于会生成多张单据,所以一张单据提交后需要点击如下图的“前一”“后一”来打开下一张订单,问题就在于打开下一张单时速度很慢。
经过对采购订单编辑界面的代码进行分析发现,如果是BOTP生成过来的代码则要做分录数据的计算更新,为了能更清楚知道都做了哪些RPC,打开客户端的RPC日志如下:
com.kingdee.eas.scm.sm.pur.client.PurOrderEditUI.actionPre_actionPerformed
current thread: AWT-EventQueue-0
stack level: 1
==============rpcInvoke start==============
com.kingdee.eas.scm.sm.pur.IPurOrder.getValue(com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.metadata.entity.SelectorItemCollection) com.kingdee.eas.framework.CoreBaseInfo
time: 703 ms request: 1870 B response: 10445 B
com.kingdee.bos.metadata.bot.IBOTMapping.isCanVoucher(java.lang.String) boolean
time: 0 ms request: 43 B response: 51 B
com.kingdee.eas.basedata.master.material.IMultiMeasureUnit.getConvRatesByMaterial([Ljava.lang.String;, [Ljava.lang.String;) java.util.Map
time: 16 ms request: 764 B response: 502 B
com.kingdee.eas.basedata.master.material.IMultiMeasureUnit.getMultiMeasureUnitCollection(java.lang.String) com.kingdee.eas.basedata.master.material.MultiMeasureUnitCollection
time: 15 ms request: 259 B response: 1574 B
com.kingdee.eas.basedata.master.cssp.ISupplier.getCompanyInfo(com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.dao.IObjectPK, com.kingdee.bos.metadata.entity.SelectorItemCollection) com.kingdee.eas.basedata.master.cssp.SupplierCompanyInfoInfo
<此处省去了共29页日志行…>
com.kingdee.eas.basedata.master.material.IMultiMeasureUnit.getMultiUnit(java.lang.String, java.lang.String) com.kingdee.eas.basedata.master.material.MultiMeasureUnitInfo
time: 0 ms request: 94 B response: 1514 B
==============rpcInvoke end==============
RPC Number: 420 SubAction Number: 0
rpc time: 8734 ms request: 187546 B response: 784702 B
stack rpc time: 8734 ms stack request: 187546 B stack response: 784702 B
action time: 10297 ms
11条分录的采购订单显示出来要10秒左右,从上面的rpc log发现客户端和服务端有420次的rpc交互,尽管每次交互的时间都比较短,但420次累计下来就很长了,的确非常令人吃惊,这也就是性能问题所在,由于是标准产品的问题,现场无法进行优化,结论已发给了研发相关项目组,等待优化后的补丁。
五、 索引优化
这次对其它的几个表也增加了索引,性能有一定的提升,这里想要说明的是针对数据表增加索引的原则是经常更新和查询的表索引数一般不超过5个,因为过多的索引会导致更新表时因更新索引而付出更多的代价。对于大部分时间是用于查询的表可以增加多于5个索引。另外根据实际情况能建组合索引的尽量建成组合索引。
六、 系统宕机(非性能)
本次支持过程中现场发生了两次宕机事件,都是在中午11点左右,第一次宕机后因为现场非常着急用就直接重启了服务器,第二次发生了后紧急联系研发总体组陈钧远程分析,得出结论是连接泄漏,经过检查现场二次开发的代码发现确实有一些写法会可能导致内存泄漏,主要是现场要用PrepareStatement来执行存储过程,而最后没有释放掉Connection。关于内存泄漏的问题标准产品早期也出过,研发集中解决过,后来就没有再发现,没想到二次开发现场又碰到了。连接泄漏会导致应用服务器的数据库连接被用光,新的用户应用申请不到数据库连接而使得客户端处于灰屏的等待状态(而应用服务器的状态看起来是正常的),必须要重启服务器,这是非常严重的问题。
为了避免连接泄漏的问题再次发生,对现场的代码进行了排查,如果是直接执行KSql的要求直接用com.kingdee.eas.util.app.DbUtil.execute(…)方法;对于需要申请Connection做访问数据库的,要求在执行完后立即释放Connection和相关的对象,对Connection要求在哪里申请在哪里释放,不能在当前申请方法之外进行释放,具体代码如下:
Connection cn = null;
ResultSet rs = null;
PreparedStatement pst = null;
try{
cn = super.getConnection(ctx);
pst = cn.prepareStatement(…)
rs = getXXX(cn, ...);
...
}catch(SQLException e){
throw new SQLDataException(e);
}finally{
SQLUtils.cleanup(rs);
SQLUtils.cleanup(cn);
SQLUtils.cleanup(pst);
//也可以用一个方法三个参数来释放
}
七、 异常的处理(非性能)
在现场发现了一个问题,也是我们以前做EAS BOS培训时一再给学员强调的,客户端和服务端的异常一定不要随便吃掉,比如如下的例子:
protected CommonQueryDialog initCommonQueryDialog() {
try {
commonQueryDialog = super.initCommonQueryDialog();
PeicanfilterUI peicanfilterui = new PeicanfilterUI();
peicanfilterui.setPanelName("条件");
commonQueryDialog.addUserPanel(peicanfilterui);
} catch (Exception e) {
e. printStackTrace();
}
return commonQueryDialog;
}
如果程序在使用过程中try中抛出了异常,而异常被输出到了后台的log中,界面上什么都看不到而正常往下走了,这个异常也许是服务端抛出来的某个提示,也可能是某个sql异常,但这样处理就不能把这些真实的信息反馈给操作员,以致于不能及时做出正确的操作。虽然这样的情况比较少,但往往小概率事件会出大问题,所以有这种写法的要及时修改,正确的代码如下:
protected CommonQueryDialog initCommonQueryDialog() {
try {
commonQueryDialog = super.initCommonQueryDialog();
PeicanfilterUI peicanfilterui = new PeicanfilterUI();
peicanfilterui.setPanelName("条件");
commonQueryDialog.addUserPanel(peicanfilterui);
} catch (Exception e) {
this.handUIException(e);
}
return commonQueryDialog;
}
服务端也是一样,异常可以截获并处理,但处理完后要继续抛异常。
这种情况也不是绝对一定要这样来处理,比如try中抛的异常你是能判断出来是什么异常,而且处理后不需要继续再抛的,比如一些循环计算处理,字符型和数值型变量做运算抛异常,为了中间不停顿你需要将异常自行处理。
八、 总结
1、 遇到性能问题先冷静分析
性能问题无非就是环境的、程序的及框架的,环境的问题可以归结为操作系统、硬件、中间件及数据库,对于目前二次开发的应用,环境问题会有一些,但一般影响不是很大,这次在航食还真是发现有一台客户端很慢,别的都正常,机器上装的软件也很多,重新安装系统后正常,对于这种就是看如果大部门都是正常的,那么个别的可以判定为环境问题来解决。对于硬件、中间件和数据库等的环境问题,因为系统已经运行了很久了,所以出现问题的可能性不是很大,或者说不是真正问题的所在,当然以前也发现过Oracle数据库有bug。
从以往的经验来看,绝大多数的性能问题都出在了程序和数据表上,也就是说分析性能问题首先要想到的是自己的程序有没有问题,数据库表索引是不是已经优化过了。因为通常的性能问题都是随着系统的应用越来越慢,这是因为在开发期间或正式运行初期数据量都比较小,性能问题一般表现不出来,随着数据越来越多系统性能往往下降的非常快,像航食这次就是因为一行代码,以前我们也遇到过标准产品总账的一个sql执行了一个下午才出来的“惨状”,冷静分析找出问题的真正所在才是我们要做的。
2、 查找性能问题的方法-RPC日志
解决一个性能问题所花的时间通常都耗费在了找问题上,解决问题也许是很快的,所以掌握有效的分析方法是很重要的。
目前EAS为我们提供了客户端和服务端的RPC日志,以及服务端的KSQL日志,这都是很有效的直接分析性能问题的依据,客户端的RPC日志能够告诉我们客户端和服务端都做了哪些调用,每次和所有的调用分别花了多少时间,如果总的时间长那肯定是调用次数太多,我们可以分析为什么有这么多次的RPC,如果是单个的方法慢,那就要分析服务端的实现代码。
服务端的RPC日志能给我们提供客户端调用的服务端方法耗时以及产生的sql,KSql日志就是给出了具体的那个数据库执行的那个sql耗时是多少,我们既能拷到执行的sql也能看到它所好用的时间,时间长的应当引起注意,继而具体分析。
由于收集RPC和KSql是比较耗时的动作,所以EAS默认是关闭此功能的,如果因为性能问题要打开可以用以下方法:
服务端的RPC日志则需要动态打开,通过如下URL打开:
http://IP:6888/easupdater/logmanager?ksql=on&rpcsql=on&sqlplan=on,
关闭则通过URL:
http://ip:6888/easupdater/logmanager?ksql=off&rpcsql=off&sqlplan=off ,注意IP地址和端口号和需要跟踪的实例相匹配。
3、 查找性能的方法-sql跟踪
有的时候性能问题是出在了sql上,针对这些问题一方面可以通过上面的方法来分析ksql外,另外也可以通过数据库取得后台sql来分析。
对于Oracle数据库可以通过top Sql功能来列出最近执行过的sql,对耗时或访问磁盘较多的都应当进行分析,看是sql本身效率低还是该有的索引没加上而引起的;对于Sql Server数据库可以通过Sql Server Profiler工具来跟踪自己感兴趣的后台sql。
4、 性能优化是一项持续性的工作
性能优化是随着应用的不断深入而产生的需求,有时候一个阶段点上优化完成了,但之后可能打了补丁或做了功能的改进,也有可能产生新的性能问题,或者某些之前已经提交使用的功能客户一直没有大规模使用,那么这些都可能在后面发生性能问题, 所以应当引起现场开发和管理人员的注意,有问题及时解决。
《完》