Hi Mike, System.nanoTime is a syscall and heavy on some O/S. The times are only used when inforstream is enabled, so the calls to nanotime should only be inside "if (infostream)" blocks. Some of them are outside this check.
Uwe ----- Uwe Schindler H.-H.-Meier-Allee 63, D-28213 Bremen http://www.thetaphi.de eMail: [email protected] > -----Original Message----- > From: [email protected] [mailto:[email protected]] > Sent: Friday, January 04, 2013 5:08 PM > To: [email protected] > Subject: svn commit: r1428947 - in > /lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index: > IndexFileDeleter.java SegmentMerger.java > > Author: mikemccand > Date: Fri Jan 4 16:07:54 2013 > New Revision: 1428947 > > URL: http://svn.apache.org/viewvc?rev=1428947&view=rev > Log: > add infoStream verbosity > > Modified: > > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/IndexFile > Deleter.java > > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/Segment > Merger.java > > Modified: > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/IndexFile > Deleter.java > URL: > http://svn.apache.org/viewvc/lucene/dev/trunk/lucene/core/src/java/org/ > apache/lucene/index/IndexFileDeleter.java?rev=1428947&r1=1428946&r2=1 > 428947&view=diff > ========================================================== > ==================== > --- > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/IndexFile > Deleter.java (original) > +++ > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/IndexF > +++ ileDeleter.java Fri Jan 4 16:07:54 2013 > @@ -436,7 +436,7 @@ final class IndexFileDeleter implements > assert locked(); > > assert Thread.holdsLock(writer); > - > + long t0 = System.nanoTime(); > if (infoStream.isEnabled("IFD")) { > infoStream.message("IFD", "now checkpoint \"" + > writer.segString(writer.toLiveInfos(segmentInfos)) + "\" [" + > segmentInfos.size() + " segments " + "; isCommit = " + isCommit + "]"); > } > @@ -467,6 +467,10 @@ final class IndexFileDeleter implements > // Save files so we can decr on next checkpoint/commit: > lastFiles.add(segmentInfos.files(directory, false)); > } > + if (infoStream.isEnabled("IFD")) { > + long t1 = System.nanoTime(); > + infoStream.message("IFD", ((t1-t0)/1000000) + " msec to checkpoint"); > + } > } > > void incRef(SegmentInfos segmentInfos, boolean isCommit) throws > IOException { > > Modified: > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/Segment > Merger.java > URL: > http://svn.apache.org/viewvc/lucene/dev/trunk/lucene/core/src/java/org/ > apache/lucene/index/SegmentMerger.java?rev=1428947&r1=1428946&r2=1 > 428947&view=diff > ========================================================== > ==================== > --- > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/Segment > Merger.java (original) > +++ > lucene/dev/trunk/lucene/core/src/java/org/apache/lucene/index/Segmen > +++ tMerger.java Fri Jan 4 16:07:54 2013 > @@ -31,7 +31,6 @@ import org.apache.lucene.codecs.StoredFi import > org.apache.lucene.codecs.TermVectorsWriter; > import org.apache.lucene.store.Directory; > import org.apache.lucene.store.IOContext; > -import org.apache.lucene.util.Bits; > import org.apache.lucene.util.IOUtils; > import org.apache.lucene.util.InfoStream; > > @@ -99,20 +98,46 @@ final class SegmentMerger { > mergeState.segmentInfo.setDocCount(setDocMaps()); > mergeDocValuesAndNormsFieldInfos(); > setMatchingSegmentReaders(); > + long t0 = System.nanoTime(); > int numMerged = mergeFields(); > + if (mergeState.infoStream.isEnabled("SM")) { > + long t1 = System.nanoTime(); > + mergeState.infoStream.message("SM", ((t1-t0)/1000000) + " msec to > merge stored fields [" + numMerged + " docs]"); > + } > assert numMerged == mergeState.segmentInfo.getDocCount(); > > final SegmentWriteState segmentWriteState = new > SegmentWriteState(mergeState.infoStream, directory, > mergeState.segmentInfo, > > mergeState.fieldInfos, termIndexInterval, > null, context); > + t0 = System.nanoTime(); > mergeTerms(segmentWriteState); > + if (mergeState.infoStream.isEnabled("SM")) { > + long t1 = System.nanoTime(); > + mergeState.infoStream.message("SM", ((t1-t0)/1000000) + " msec to > merge postings [" + numMerged + " docs]"); > + } > + > + t0 = System.nanoTime(); > mergePerDoc(segmentWriteState); > + if (mergeState.infoStream.isEnabled("SM")) { > + long t1 = System.nanoTime(); > + mergeState.infoStream.message("SM", ((t1-t0)/1000000) + " msec to > merge doc values [" + numMerged + " docs]"); > + } > > if (mergeState.fieldInfos.hasNorms()) { > + t0 = System.nanoTime(); > mergeNorms(segmentWriteState); > + if (mergeState.infoStream.isEnabled("SM")) { > + long t1 = System.nanoTime(); > + mergeState.infoStream.message("SM", ((t1-t0)/1000000) + " msec to > merge norms [" + numMerged + " docs]"); > + } > } > > if (mergeState.fieldInfos.hasVectors()) { > + t0 = System.nanoTime(); > numMerged = mergeVectors(); > + if (mergeState.infoStream.isEnabled("SM")) { > + long t1 = System.nanoTime(); > + mergeState.infoStream.message("SM", ((t1-t0)/1000000) + " msec to > merge vectors [" + numMerged + " docs]"); > + } > assert numMerged == mergeState.segmentInfo.getDocCount(); > } > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
