lucene2.4优化索引过程中遇到的问题
最近开源项目compass升级至2.1版本,它的内核--开源项目lucene也升级到2.4版本,compass2.1 使用了最新版本的lucene, 据说性能提升了很多,我们决定对本公司网站中使用的compass组件进行升级。
工作进行的很顺利,但最后在索引优化环节出了问题,反复试验都问题依旧。具体表现如下:
我们的做法是把索引优化做为EJB服务组件放在jboss容器中运行,索引共有5个子索引。在其中的一部机器上,当优化进行到最后一个子索引时,程序似乎陷入死锁,长时间没有反应,且cpu的使用率很高,而客户端程序则在无限期等待。在另一部机器上,当索引优化进行到第三个子索引时就会出现上述问题。更加令人捉摸不定的是,在第一部机器上,整个优化过程有时又可顺利完成,而在第二部机器上,优化总是在进行到第三个子索引时陷入停顿。
进一步观察发现,在优化陷入停顿时,jboss服务器的控制台总是会打印出以下信息:
WARN [org.jboss.tm.TransactionImpl] Transaction TransactionImpl:XidImpl [FormatId=257, GlobalId=chengwenkan//15, BranchQual=] timed out. status=STATUS_ACTIVE
在网上搜了一下,这是jboss提示事务运行超时的信息。Jboss把EJB对外服务接口的每一个方法都做为一个事务来管理。如果方法执行超时,jboss会中断正在执行该方法的线程(调用线程的interrupt()方法)。缺省的超时时间是5分钟,可在server/conf/jboss-service.xml中进行设置。如下:
<mbean code="org.jboss.tm.TransactionManagerService"
name="jboss:service=TransactionManager"
xmbean-dd="resource:xmdesc/TransactionManagerService-xmbean.xml">
<attribute name="TransactionTimeout">300</attribute>
既然是方法执行时间超时导致了该问题,加长jboss事务的超时时间是否可以解决问题呢?我们把jboss事务的超时时间放大10倍,改为3000秒,即50分钟,这大大超出了优化整个索引所需的时间,应该可以解决问题。
重启jboss服务器,再次进行测试,优化果然顺利完成了。
然而,这并不是问题的全部。
之前我们使用compass1.2,索引更加庞大,优化所需的时间会更长,jboss服务器的事务超时时间也是缺省的5分钟,但优化每次都能顺利完成。
可见,一定是新版本的compass或lucene出了问题。
从网上下载了compass2.1和lucene2.4的源码,经过一番跟踪调试,终于发现了问题所在。
原来,老版本的lucene在对索引优化时用的是单线程模式,即在对某个索引优化时一直会等到优化完成才退出。而在2.4版本下,优化用的是多线程模式,在对某个(子)索引优化时,会启动一条线程在后台对索引进行优化,而前台线程则可以根据需要进行设置以决定是否等待,如果等待,前台线程会对优化过程进行监控,当优化结束后才退出;如果不需要等待,则前台线程会直接退出,后台线程则继续进行优化工作,直至完成。应用程序则可以继续启动下一个子索引的的优化。最多时,可能所有的子索引都处在优化过程之中。
正是由于前台线程和后台线程协同工作时的不严谨,导致了我们所遇到的问题。
为了解释这个问题,我们先来了解一下Thread类interrupt()方法的用法。
Interrupt()方法的作用是使线程退出阻塞状态。更为精确的讲,如果线程被阻塞在方法Object.wait()、Thread.join()或是Thread.sleep(),它将接收一个InterruptedException,从而提前终结阻塞方法。(在其它一些情况下线程也可终结阻塞状态,请参阅sun java api 文档。)Thread.interrupt()方法并没有中断一个正在运行的线程。
请看以下例子:
class Example1 extends Thread { public static void main(String args[]) throws Exception { Example1 thread = new Example1(); System.out.println("Starting thread..."); thread.start(); Thread.sleep(3000); System.out.println("Interrupting thread..."); thread.interrupt(); Thread.sleep(3000); System.out.println("Stopping application..."); System.exit(0); } public void run() { while (true) { System.out.println("Thread is running..."); synchronized(this){ try{ wait(1000); }catch(InterruptedException e){ return; } } } } }运行该示例可看出,在主线程调用了thread.interrupt()方法后,子线程收到了InterruptedException异常信号,它捕捉到此异常并且结束了自身运行。
现在我们再看lucene2.4优化索引时前后台线程配合的部分代码。
if (doWait) { synchronized(this) { while(true) { ... if (optimizeMergesPending()){ doWait(); } else break; } } ...}if (doWait)句:如果设置了doWait标志,则前台线程会等待后台线程完成。否则直接退出。
if (optimizeMergesPending()) 检查后台线程是否已优化完毕。如果没完成就调用doWait()等待,否则退出。
doWait()部分代码:
private synchronized void doWait() { try { // NOTE: the callers of this method should in theory // be able to do simply wait(), but, as a defense // against thread timing hazards where notifyAll() // falls to be called, we wait for at most 1 second // and then return so caller can check if wait // conditions are satisified: wait(1000); } catch (InterruptedException ie) { Thread.currentThread().interrupt();//将此行注释掉了就可以了 } }出问题的正是catch块中的Thread.currentThread().interrupt();这一语句。
设想:当前台线程处在wait(1000)中,此时优化过程在jboss中运行超时,于是jboss发出了中断线程信号,前台线程于是中止了wait(1000),它捕获到异常InterruptedException,但是它又调用了Thread.currentThread().interrupt()方法,使当前线程又一次收到InterruptedException信号,当再一次进入wait(1000)时,由于有InterruptedException异常,wait立即终止,进入到catch块,又一次发出中断当前线程的信号,从而陷入了死循环。
更为严重的是,由于一进入wait方法就立即退出,使得wait方法起不到作用。我们知道wait方法的作用是使线程进入睡眠,同时交出线程所占用的资源(对象锁),使其它线程有机会获得这些资源并展开运行。由于doWait()方法实际没有交出对象锁,而它外围的调用代码if (optimizeMergesPending())也恰好是一个同步方法,这就使这段代码绝大部分的运行时间内都拥有对象锁,使得后台线程无法获得对象锁进行运行,而始终处在死锁状态。
至此,所有的问题都已水落石出,之所以在有的机器上优化过程进行到最后一个子索引才死锁,而在另外的机器上只能进行到第三个子索引,是因为两部机器的速度不同,实际上两部机器都是运行到5分钟时出的问题,这是因为在第5分钟是jboss服务器发出了事务超时信号。而cpu之所以使用率高,是因为线程无法进入wait()而一直处于高速奔跑状态。