Merge pull request #803 from vladak/indexer_times

add elapsed time reporting for 2nd phase of indexing and report total ti...

Author: Vladimir Kotal

src/org/opensolaris/opengrok/history/HistoryGuru.java

@@ -42,6 +42,7 @@
 import org.opensolaris.opengrok.configuration.Configuration.RemoteSCM;
 import org.opensolaris.opengrok.configuration.RuntimeEnvironment;
 import org.opensolaris.opengrok.index.IgnoredNames;
+import org.opensolaris.opengrok.util.Statistics;
 import org.opensolaris.opengrok.util.StringUtils;
 
 /**
@@ -484,7 +485,7 @@ private void createCache(Repository repository, String sinceRevision) {
 
         if (repository.isWorking()) {
             boolean verbose = RuntimeEnvironment.getInstance().isVerbose();
-            long start = System.currentTimeMillis();
+            Statistics elapsed = new Statistics();
 
             if (verbose) {
                 log.log(Level.INFO, "Creating historycache for {0} ({1})",
@@ -500,10 +501,7 @@ private void createCache(Repository repository, String sinceRevision) {
             }
 
             if (verbose) {
-                long stop = System.currentTimeMillis();
-                String time_str = StringUtils.getReadableTime(stop - start);
-                log.log(Level.INFO, "Done historycache for {0} (took {1})",
-                    new Object[]{path, time_str});
+                elapsed.report(log, "Done historycache for " + path);
             }
         } else {
             log.log(Level.WARNING, "Skipping creation of historycache of "
@@ -512,7 +510,7 @@ private void createCache(Repository repository, String sinceRevision) {
     }
 
     private void createCacheReal(Collection<Repository> repositories) {
-        long start = System.currentTimeMillis();
+        Statistics elapsed = new Statistics();
         ExecutorService executor = RuntimeEnvironment.getHistoryExecutor();
         // Since we know each repository object from the repositories
         // collection is unique, we can abuse HashMap to create a list of
@@ -596,10 +594,7 @@ public void run() {
             OpenGrokLogger.getLogger().log(Level.WARNING,
                     "Failed optimizing the history cache database", he);
         }
-        long stop = System.currentTimeMillis();
-        String time_str = StringUtils.getReadableTime(stop - start);
-        log.log(Level.INFO, "Done historycache for all repositories (took {0})",
-            time_str);
+        elapsed.report(log, "Done historycache for all repositories");
         historyCache.setHistoryIndexDone();
     }
 

src/org/opensolaris/opengrok/index/IndexDatabase.java

@@ -322,7 +322,7 @@ public void update() throws IOException, HistoryException {
             }
         }
 
-        try {            
+        try {
             Analyzer analyzer = AnalyzerGuru.getAnalyzer();
             IndexWriterConfig iwc = new IndexWriterConfig(SearchEngine.LUCENE_VERSION, analyzer);
             iwc.setOpenMode(OpenMode.CREATE_OR_APPEND);

src/org/opensolaris/opengrok/index/Indexer.java

@@ -577,8 +577,14 @@ public static void main(String argv[]) {
 
     }
 
-    // PMD wants us to use length() > 0 && charAt(0) instead of startsWith()
-    // for performance. We prefer clarity over performance here, so silence it.
+    /*
+     * This is the first phase of the indexing where history cache is being
+     * generated for repositories (at least for those which support getting
+     * history per directory).
+     *
+     * PMD wants us to use length() > 0 && charAt(0) instead of startsWith()
+     * for performance. We prefer clarity over performance here, so silence it.
+     */
     @SuppressWarnings("PMD.SimplifyStartsWith")
     public void prepareIndexer(RuntimeEnvironment env,
             boolean searchRepositories,
@@ -743,9 +749,16 @@ public int compare(Project p1, Project p2) {
         }
     }
 
+    /*
+     * This is the second phase of the indexer which generates Lucene index
+     * by passing source code files through Exuberant ctags, generating xrefs
+     * and storing data from the source files in the index (along with history,
+     * if any).
+     */
     public void doIndexerExecution(final boolean update, int noThreads, List<String> subFiles,
             IndexChangedListener progress)
             throws IOException {
+        Statistics elapsed = new Statistics();
         RuntimeEnvironment env = RuntimeEnvironment.getInstance().register();
         log.info("Starting indexing");
 
@@ -826,7 +839,7 @@ public void run() {
             log.log(Level.SEVERE,
                 "destroying of renamed thread pool failed", ex);
         }
-        log.info("Done indexing");
+        elapsed.report(log, "Done indexing data of all repositories");
     }
 
     public void sendToConfigHost(RuntimeEnvironment env, String configHost) {
@@ -838,7 +851,8 @@ public void sendToConfigHost(RuntimeEnvironment env, String configHost) {
                     InetAddress host = InetAddress.getByName(cfg[0]);
                     env.writeConfiguration(host, Integer.parseInt(cfg[1]));
                 } catch (Exception ex) {
-                    log.log(Level.SEVERE, "Failed to send configuration to " + configHost + " (is web application server running with opengrok deployed?)", ex);
+                    log.log(Level.SEVERE, "Failed to send configuration to "
+                        + configHost + " (is web application server running with opengrok deployed?)", ex);
                 }
             } else {
                 log.severe("Syntax error: ");

src/org/opensolaris/opengrok/util/Statistics.java

@@ -35,6 +35,12 @@ public Statistics() {
       startTime = System.currentTimeMillis();    
   }
 
+  public void report(Logger log, String msg) {
+      long stopTime = System.currentTimeMillis();
+      String time_str = StringUtils.getReadableTime(stopTime - startTime);
+      log.log(Level.INFO, msg + " (took {0})", time_str);
+  }
+
   public void report(Logger log) {
     long stopTime = System.currentTimeMillis() - startTime;
     log.log(Level.INFO, "Total time: {0}", getReadableTime(stopTime));