一、现象
因种种问题导致地方法院上传的十几万裁判文积压,wcm无法发布,使用Dataexchange每天导入的数据量由原先的6w下降到2-3w,并且插入一条数据的时间在1-2s之间。
二、问题分析
根据客户提供的信息,首先想到的问题解决步骤:
1、获取javacore信息
获取javacore信息可以看到当前wcm线程都在干什么,是不是由于Dataexchange批量推送数据导致wcm所在tomcat线程压力过大。
获取javacore信息的方法可参考:TRSWCM应用出现问题怎么办之javacore
(注意:在linux下有时候kill -3不一定能够获取得到javacore信息,这时候需要使用jstack pid去获取)
关于javacore的分析:
一般就是隔一段时间获取一次javacore信息,观察线程状态是否有所改变,是否有一些执行比较慢,阻塞的线程,在结合具体情况分析代码。
但从获取得到的javacore信息来看,发布线程ThreadPool$Worker$这是发布线程,都是等待状态,没有一个是正在运行的,表明当前的发布速度是没有问题的。
通过发布监控看了一下他们的发布性能,基本上发布一个细缆页面也都是在0.1s这样。
再看看tomcat线程数(http-port-Processor)这样的线程,也就在25个这样,那么可以看出DataExchange并没有说并发量很大的给wcm推送文章。
后来了解到他们的代码是采用单线程推送数据的,因为他们曾经也尝试过直接调用wcm的服务推送数据,但是由于用户上线网站时间比较集中,并发量很大,很容易导致wcm系统缓慢。
因此用户自己写了一个缓冲池,用于缓存上下线网站的请求,采用单线程24小时调用Dataexchange给wcm推送数据,根据他们打出的调试信息来看每次调用wcm的保存文档接口,都会消耗2s以上
2、生成oracle的awr报告:
如何生成awr分析报告:http://wiki.trs.org.cn/pages/viewpage.action?pageId=14189637
可以看到数据库基本上没什么压力,从top sql语句上看也没有看到有执行时间特别长的语句,但是有一条updata语句执行了7s但是是在14小时内才执行了一次而已,所以当时分析的时候就直接把这句语句的影响给忽略掉了,认为系统执行插入操作和这个Updata语句没什么关系,跟何况是14小时内才执行一次而已。(其实这正是问题所在)
1、2步骤基本上是解决效率问题的一般步骤,服务cpu消耗性能问题,基本上可以从javacore信息看出,数据库压力可以通过awr报告看出。
但是经过1、2步骤,当时却犯难了,既没有得到一个准确的性能消耗很大的sql语句,也没有得到任何关于wcm消耗很大的线程相关的数据。
三、深入wcm数据库缓冲池
这个时候我们可以尝试打开一下数据库缓冲池,观察一下wcm每条语句具体的执行效率。
如何打开数据库连接池执行sql堆栈:参考wiki:http://wiki.trs.org.cn/pages/viewpage.action?pageId=11343533。并且给BaseObj添加了一些调试信息,重新部署到wcm中,并设置其log4j调试状态为debug,再执行导出操作。
从catalina.out和TRSWCMLog.log日志文件中可以看到这样的语句:
UPDATE WCMCHNLDOC SET DocForm=1 WHERE DocId=4770951 use time=1334
基本上执行这样的语句都是1334ms也就是说基本上这个语句执行的时间都是 1s多以上,性能应该就是消耗在这里了这个update语句是由wcm监听器 执行了updata语句,并且每一条记录都会updata一次,并不是根据是否有图片才更新。
DocForm=1 文字类型
DocForm=2 图片类型
if (nDocType == Document.DOC_TYPE_FILE) { String sFileName = document.getPropertyAsString("DOCFILENAME"); nDocForm = analyzeExt(sFileName); } else if (nDocType == Document.DOC_TYPE_HTML) { // 对html型,解析dochtmlcon判断 String sHtmlCon = document.getHtmlContent(); nDocForm = analyzeDocForm(sHtmlCon); } else { // 对其他类型,默认返回文本型 nDocForm = Document.DOC_FORM_LITERY; }
而基本上执行的updata语句都是在1.5s以上,所以问题就出现在这里了,每次执行保存操作都触发了DocumentLCListenerForDocForm监听器去执行updata操作而这个updata的操作是耗时的,消耗事件1.5s以上。
再来看一下这个语句:UPDATE WCMCHNLDOC SET DocForm=1 WHERE DocId=4770951 use time=1334
条件 where DocId = 4770951就这样的一个条件。应该是走了全表扫描了。这个时候就要获取一些这个语句的执行计划。发现果然是全表扫描。