Hi Alan, We don't see such problems here on our machines, so first we need to know some things:
Do you open a new index reader before each search and close it afterwards? In normal Lucene usage you keep the IndexReaders open all the time and only reopen them when your underlying index changed. If you keep the IndexReader open, such close() calls with doPrivileged will not happen so often. The problem in Lucene 3.3 is that the default on 64 bit Linux is to use memory mapping, which is implemented by the operating system like a swap file mapped into virtual address space. This makes searches very fast, as the whole index is somehow in cache RAM and can be accessed like memory swapped out into a swap file. This memory mapping is much more expensive than simple opening a file and closing it after usage. If you reopen the indexreader all the time, this expensive mapping cost is what you see all the time. So I would suggest you check: a) Only open/close IndexReaders when you really need it. You can use one IndexReader and even handle multiple parallel searches on it (it's thread safe). b) If you need to reopen quite often, don't use the defaults FSDirectory.open(), but instead choose a Directory implementation yourself. To get the behavior of Lucene 3.2, use new NIOFSDirectory(...). But on Linux 64, searches will be slower than with MMap (if you keep readers open). c) Is your JVM somehow closed down in terms of security? These doPrivileged mappings are only effective, when you have a web application container that restricts web applications to run with low privileges (something like Windows Vista/7 UAC). In this case, doPrivileged may be expensive and is not simply a noop. For Lucene/Solr it's always recommened not to run it in restricted Java environments. Maybe OpenBD does this - I have no idea. Uwe ----- Uwe Schindler H.-H.-Meier-Allee 63, D-28213 Bremen http://www.thetaphi.de eMail: [email protected] > -----Original Message----- > From: Alan Williamson (aw2.0 cloud experts) [mailto:[email protected]] > Sent: Saturday, July 23, 2011 9:42 AM > To: [email protected] > Subject: Experiencing High CPU load with 3.3 > > Good day all. > > We area a long term user of Lucene with it powering our search engine inside > of the Java CFML runtime OpenBD (http://openbd.org). We've had no > complaints from it whatsoever. Until now that is. > > Since moving to 3.3 we have been experiencing extremely high CPU load > when searching against an index. The index is only 19MB in size with all of > 40,000 items in it. > > We have produced some very useful stack traces with CPU % load times. > Some other data points. This is not happening to just one machine, this is > happening to all the machines in the web farm. The actual traffic on the > machine is low, the stack traces i give you, the only threads that are actually > doing anything, are the ones were Lucene has gone into a tizzy. The > machines have all 3.5GB of memory. Running Java 1.6.23 > > Thanks > > alan > > ------- Sample #1 ----------------------------------------- > > "qtp274064735-1462" prio=10 tid=0x00002aaacaa62800 nid=19115 runnable > [0x000000004174d000] > java.lang.Thread.State: RUNNABLE > at java.security.AccessController.doPrivileged(Native Method) > at > org.apache.lucene.store.MMapDirectory.cleanMapping(MMapDirectory.jav > a:158) > at > org.apache.lucene.store.MMapDirectory$MMapIndexInput.close(MMapDir > ectory.java:383) > at > org.apache.lucene.index.CompoundFileReader.close(CompoundFileReader.j > ava:137) > - locked<0x0000000795b86520> (a > org.apache.lucene.index.CompoundFileReader) > at > org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:302) > at > org.apache.lucene.index.SegmentInfos$1.doBody(SegmentInfos.java:359) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:750) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:589) > at > org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:355) > at > org.apache.lucene.index.SegmentInfos.readCurrentVersion(SegmentInfos.j > ava:476) > at > org.apache.lucene.index.DirectoryReader.initialize(DirectoryReader.java:347 > ) > at > org.apache.lucene.index.DirectoryReader.<init>(DirectoryReader.java:130) > at > org.apache.lucene.index.DirectoryReader$1.doBody(DirectoryReader.java:8 > 3) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:750) > at > org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:75) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:428) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:288) > > "qtp274064735-764" prio=10 tid=0x00002aaabb15f000 nid=16453 runnable > [0x0000000041bd6000] > java.lang.Thread.State: RUNNABLE > at java.io.UnixFileSystem.list(Native Method) > at java.io.File.list(File.java:973) > at java.io.File.list(File.java:1004) > at org.apache.lucene.store.FSDirectory.listAll(FSDirectory.java:223) > at org.apache.lucene.store.FSDirectory.listAll(FSDirectory.java:241) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:637) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:589) > at > org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:355) > at > org.apache.lucene.index.SegmentInfos.readCurrentVersion(SegmentInfos.j > ava:476) > at > org.apache.lucene.index.DirectoryReader.initialize(DirectoryReader.java:347 > ) > at > org.apache.lucene.index.DirectoryReader.<init>(DirectoryReader.java:130) > at > org.apache.lucene.index.DirectoryReader$1.doBody(DirectoryReader.java:8 > 3) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:750) > at > org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:75) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:428) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:288) > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 16453 nobody 18 0 8149m 3.6g 80m R 57.4 47.3 4:45.53 java > 19115 nobody 18 0 8149m 3.6g 80m R 50.2 47.3 2:01.15 java > > ------- Sample #2 ----------------------------------------- > > "qtp2001061977-4696" prio=10 tid=0x00002aaac0816800 nid=4710 runnable > [0x0000000041950000] > java.lang.Thread.State: RUNNABLE > at > org.apache.lucene.index.TermInfosReader.<init>(TermInfosReader.java:121 > ) > at > org.apache.lucene.index.SegmentCoreReaders.<init>(SegmentCoreReaders > .java:75) > at > org.apache.lucene.index.SegmentReader.get(SegmentReader.java:114) > at > org.apache.lucene.index.SegmentReader.get(SegmentReader.java:92) > at > org.apache.lucene.index.DirectoryReader.<init>(DirectoryReader.java:113) > at > org.apache.lucene.index.DirectoryReader$1.doBody(DirectoryReader.java:8 > 3) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:750) > at > org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:75) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:428) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:288) > > "qtp2001061977-15" prio=10 tid=0x00002aaab8e07000 nid=28622 runnable > [0x0000000040c37000] > java.lang.Thread.State: RUNNABLE > at java.security.AccessController.doPrivileged(Native Method) > at > org.apache.lucene.store.MMapDirectory.cleanMapping(MMapDirectory.jav > a:158) > at > org.apache.lucene.store.MMapDirectory$MMapIndexInput.close(MMapDir > ectory.java:383) > at > org.apache.lucene.index.CompoundFileReader.close(CompoundFileReader.j > ava:137) > - locked<0x000000076e7bf9c0> (a > org.apache.lucene.index.CompoundFileReader) > at > org.apache.lucene.index.SegmentCoreReaders.decRef(SegmentCoreReader > s.java:191) > - locked<0x000000076e7bf960> (a > org.apache.lucene.index.SegmentCoreReaders) > at > org.apache.lucene.index.SegmentReader.doClose(SegmentReader.java:387) > at > org.apache.lucene.index.IndexReader.decRef(IndexReader.java:242) > at > org.apache.lucene.index.DirectoryReader.doClose(DirectoryReader.java:895 > ) > - locked<0x000000076e7bef98> (a > org.apache.lucene.index.DirectoryReader) > at > org.apache.lucene.index.IndexReader.decRef(IndexReader.java:242) > at > org.apache.lucene.index.IndexReader.close(IndexReader.java:1209) > - locked<0x000000076e7bef98> (a > org.apache.lucene.index.DirectoryReader) > > 4710 nobody 18 0 8172m 3.2g 82m R 79.1 42.6 4:22.84 java > 28622 nobody 18 0 8172m 3.2g 82m D 69.2 42.6 12:39.49 java > > ------- Sample #3 ----------------------------------------- > > > "qtp683347213-3129" prio=10 tid=0x00002aaac07fd000 nid=29916 runnable > [0x0000000042b73000] > java.lang.Thread.State: RUNNABLE > at > org.apache.lucene.index.IndexFileNames.fileNameFromGeneration(IndexFil > eNames.java:189) > at > org.apache.lucene.index.SegmentInfo.getNormFileName(SegmentInfo.java: > 508) > at > org.apache.lucene.index.SegmentReader.openNorms(SegmentReader.java: > 639) > at > org.apache.lucene.index.SegmentReader.get(SegmentReader.java:119) > at > org.apache.lucene.index.SegmentReader.get(SegmentReader.java:92) > at > org.apache.lucene.index.DirectoryReader.<init>(DirectoryReader.java:113) > at > org.apache.lucene.index.DirectoryReader$1.doBody(DirectoryReader.java:8 > 3) > at > org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfo > s.java:750) > at > org.apache.lucene.index.DirectoryReader.open(DirectoryReader.java:75) > at > org.apache.lucene.index.IndexReader.open(IndexReader.java:428) > > 29916 nobody 22 0 7922m 4.3g 92m R 73.1 57.7 5:53.96 java
