[hg] main-silver: Fixed counts in scan cancelled reports. Added ...

  • From: Svata Dedic < >
  • To:
  • Subject: [hg] main-silver: Fixed counts in scan cancelled reports. Added ...
  • Date: Tue, 04 Dec 2012 14:39:14 -0800

changeset cb3d967846a2 in main-silver ((none))
details: http://hg.netbeans.org/main-silver/rev/cb3d967846a2
description:
        Fixed counts in scan cancelled reports. Added timers for parsing and 
improved timing of unfinished indexers. Logged rescan all decisions

diffstat:

 csl.api/src/org/netbeans/modules/csl/core/ErrorFilterQuery.java              
     |   26 +
 parsing.api/src/org/netbeans/modules/parsing/impl/Installer.java             
     |    7 +
 parsing.api/src/org/netbeans/modules/parsing/impl/indexing/LogContext.java   
     |  294 +++++++++-
 
parsing.api/src/org/netbeans/modules/parsing/impl/indexing/RepositoryUpdater.java
 |   94 ++-
 4 files changed, 371 insertions(+), 50 deletions(-)

diffs (802 lines):

diff --git a/csl.api/src/org/netbeans/modules/csl/core/ErrorFilterQuery.java 
b/csl.api/src/org/netbeans/modules/csl/core/ErrorFilterQuery.java
--- a/csl.api/src/org/netbeans/modules/csl/core/ErrorFilterQuery.java
+++ b/csl.api/src/org/netbeans/modules/csl/core/ErrorFilterQuery.java
@@ -45,6 +45,9 @@
 import java.util.Collection;
 import java.util.LinkedList;
 import java.util.List;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
 import org.netbeans.modules.csl.api.Error;
 import org.netbeans.modules.csl.spi.ErrorFilter;
 import org.netbeans.modules.csl.spi.ParserResult;
@@ -58,18 +61,41 @@
  * @author marekfukala
  */
 public class ErrorFilterQuery {
+    private static final Logger UPDATER_BACKDOOR = 
Logger.getLogger("org.netbeans.modules.parsing.impl.indexing.LogContext.backdoor");
     
     public static List<? extends Error> getFilteredErrors(ParserResult 
parserResult, String featureName) {
         Collection<? extends ErrorFilter.Factory> factories = 
Lookup.getDefault().lookupAll(ErrorFilter.Factory.class);
         List<Error> filtered = new LinkedList<Error>();
         for(ErrorFilter.Factory factory : factories) {
             ErrorFilter filter = factory.createErrorFilter(featureName);
+            String fn = "TLIndexer:" + filterName(filter);
+            try {
+                LogRecord lr = new LogRecord(Level.INFO, "INDEXER_START");
+                lr.setParameters(new Object[] { fn });
+                UPDATER_BACKDOOR.log(lr);
             List<? extends Error> result = filter.filter(parserResult);
             if(result != null) {
                 filtered.addAll(result); 
             }
+            } finally {
+                LogRecord lr = new LogRecord(Level.INFO, "INDEXER_END");
+                lr.setParameters(new Object[] { fn });
+                UPDATER_BACKDOOR.log(lr);
+            }
         }
         return filtered.isEmpty() ? parserResult.getDiagnostics() :  
filtered;
     }
     
+    static String filterName(ErrorFilter f) {
+        Class c = f.getClass();
+        String n = c.getName();
+        int idx = n.indexOf(".modules.");
+        int last = n.lastIndexOf('.');
+        if (idx > -1) {
+            int n2 = n.indexOf('.', idx + 9);
+            return n.substring(idx + 9, n2 + 1) + n.substring(last + 1);
+        } else {
+           return n.substring(last + 1);
 }
+    }
+}
diff --git a/parsing.api/src/org/netbeans/modules/parsing/impl/Installer.java 
b/parsing.api/src/org/netbeans/modules/parsing/impl/Installer.java
--- a/parsing.api/src/org/netbeans/modules/parsing/impl/Installer.java
+++ b/parsing.api/src/org/netbeans/modules/parsing/impl/Installer.java
@@ -42,6 +42,7 @@
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeoutException;
 import java.util.concurrent.atomic.AtomicBoolean;
+import org.netbeans.modules.parsing.impl.indexing.LogContext;
 import org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater;
 import 
org.netbeans.modules.parsing.impl.indexing.lucene.DocumentBasedIndexManager;
 import org.netbeans.modules.parsing.impl.indexing.lucene.LuceneIndexFactory;
@@ -75,6 +76,12 @@
     }
 
     @Override
+    public boolean closing() {
+        LogContext.notifyClosing();
+        return super.closing();
+    }
+
+    @Override
     public void close() {
         super.close();
         final CountDownLatch done = new CountDownLatch(1);
diff --git 
a/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/LogContext.java 
b/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/LogContext.java
--- 
a/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/LogContext.java
+++ 
b/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/LogContext.java
@@ -67,6 +67,16 @@
     
     private static int serial;
     
+    /**
+     * Implemented as one-time flag. Not exactly correct, but will suffice 
since
+     * it only suppresses some error detection.
+     */
+    private static volatile boolean closing;
+    
+    public static void notifyClosing() {
+        closing = true;
+    }
+    
     public enum EventType {
         PATH(1, 10),
         FILE(2, 20),
@@ -160,9 +170,26 @@
         return sb.toString();
     }
     
+    private synchronized void checkConsistency() {
+        long total = 0;
+        for (RootInfo ri : scannedSourceRoots.values()) {
+            total += ri.spent;
+        }
+        if (total != totalScanningTime) {
+            System.err.println("total scanning time mismatch");
+        }
+    }
+    
     private synchronized void freeze() {
+        // finish all roots
+        this.timeCutOff = System.currentTimeMillis();
+        for (RootInfo ri : allCurrentRoots.values()) {
+            ri.finishCurrentIndexer(timeCutOff);
+            long diff = timeCutOff - ri.startTime;
+            ri.spent += diff;
+        }
         this.frozen = true;
-        this.timeCutOff = System.currentTimeMillis();
+        checkConsistency();
     }
     
     void log() {
@@ -227,6 +254,7 @@
     
     void recordFinished() {
         finished = System.currentTimeMillis();
+        freeze();
     }
     
     void setPredecessor(LogContext pred) {
@@ -245,6 +273,9 @@
         return finished;
     }
 
+    private static ThreadLocal<RootInfo>    currentlyIndexedRoot = new 
ThreadLocal<RootInfo>();
+    private static ThreadLocal<LogContext>    currentLogContext = new 
ThreadLocal<LogContext>();
+
     private int mySerial;
     private long storeTime;
     private final long timestamp;
@@ -259,6 +290,8 @@
     private String threadDump;
     private String secondDump;
     
+    private Map<URL, Set<String>> reindexInitiators = Collections.emptyMap();
+    private List<String> indexersAdded = Collections.emptyList();
     // various path/root informaation, which was the reason for indexing.
     private Set<String>  filePathsChanged = Collections.emptySet();
     private Set<String>  classPathsChanged = Collections.emptySet();
@@ -302,15 +335,21 @@
     
     private Map<String, Long>   totalIndexerTime = new HashMap<String, 
Long>();
     
+    private long crawlerStart;
+    
     private class RootInfo {
         private URL     url;
         private long    startTime;
         private long    spent;
         private Map<String, Long>   rootIndexerTime = new HashMap<String, 
Long>();
+        // indexer name and start time, to capture in statistics
+        private long    indexerStartTime;
+        private String  indexerName;
         private int count;
         private long    crawlerTime;
         private int     resCount = -1;
         private int     allResCount = -1;
+        private LinkedList<Object> pastIndexers = null;
 
         public RootInfo(URL url, long startTime) {
             this.url = url;
@@ -319,11 +358,18 @@
         
         public String toString() {
             long time = spent == 0 ? timeCutOff - startTime : spent;
-            return "< root = " + url.toString() + "; spent = " + time + "; 
crawler = " + crawlerTime + "; res = "
-                    + resCount + "; allRes = " + allResCount + " >";
+            String s = "< root = " + url.toString() + "; spent = " + time + 
"; crawler = " + crawlerTime + "; res = "
+                    + resCount + "; allRes = " + allResCount;
+            if (indexerName != null) {
+                s = s + "; indexer: " + indexerName;
+            }
+            return s + ">";
         }
         
         public void merge(RootInfo ri) {
+            if (this == ri) {
+                return;
+            }
             if (!url.equals(ri.url)) {
                 throw new IllegalArgumentException();
             }
@@ -335,6 +381,80 @@
             if (ri.allResCount > -1) {
                 this.allResCount = ri.allResCount;
             }
+            for (String id : ri.rootIndexerTime.keySet()) {
+                Long spent = ri.rootIndexerTime.get(id);
+                Long my = rootIndexerTime.get(id);
+                if (my == null) {
+                    my = spent;
+                } else {
+                    my += spent;
+                }
+                rootIndexerTime.put(id, my);
+            }
+        }
+        
+        void startIndexer(String indexerName) {
+            if (indexerStartTime != 0) {
+                if (pastIndexers == null) {
+                    pastIndexers = new LinkedList<Object>();
+                }
+                pastIndexers.add(Long.valueOf(indexerStartTime));
+                pastIndexers.add(this.indexerName);
+            }
+            this.indexerStartTime = System.currentTimeMillis();
+            this.indexerName = indexerName;
+        }
+        
+        long finishCurrentIndexer(long now) {
+            if (indexerStartTime == 0) {
+                return 0;
+            }
+            long time = now - indexerStartTime;
+            Long t = rootIndexerTime.get(indexerName);
+            if (t == null) {
+                t = Long.valueOf(0);
+            }
+            t += time;
+            rootIndexerTime.put(indexerName, t);
+            if (pastIndexers != null && !pastIndexers.isEmpty()) {
+                indexerName = (String)pastIndexers.removeLast();
+                indexerStartTime = (Long)pastIndexers.removeLast();
+            } else {
+                indexerStartTime = 0;
+            }
+            return time;
+        }
+        
+        long finishIndexer(String indexerName) {
+            if (frozen) {
+                return 0;
+            }
+            if (indexerStartTime == 0 || indexerName == null) {
+                return 0;
+            }
+            if (!indexerName.equals(this.indexerName)) {
+                boolean ok = false;
+                if (pastIndexers != null) {
+                    for (int i = 1; i < pastIndexers.size(); i += 2) {
+                        if (indexerName.equals(pastIndexers.get(i))) {
+                            long t = System.currentTimeMillis();
+                            // rollback past indexers to the currently 
finishing one
+                            while (pastIndexers.size() > i) {
+                                finishCurrentIndexer(t);
+                            }
+                            ok = true;
+                        }
+                    }
+                }
+                if (!ok) {
+                    throw new IllegalStateException("Mismatch in indexer: " 
+ indexerName);
+                }
+            }
+            long l = finishCurrentIndexer(System.currentTimeMillis());
+            if (indexerStartTime == 0) {
+                this.indexerName = null;
+            }
+            return l;
         }
     }
     
@@ -348,7 +468,29 @@
                     currentRoot,
                     System.currentTimeMillis()
         ));
-        scannedSourceRoots.put(currentRoot, ri);
+        currentlyIndexedRoot.set(ri);
+        currentLogContext.set(this);
+    }
+    
+    public synchronized void startCrawler() {
+        crawlerStart = System.currentTimeMillis();
+    }
+    
+    public synchronized void reportCrawlerProgress(int resCount, int 
allResCount) {
+        long t = System.currentTimeMillis();
+        
+        RootInfo ri = allCurrentRoots.get(Thread.currentThread());
+        if (ri == null) {
+            LOG.log(Level.FINE, "No root specified for crawler run", new 
Throwable());
+            return;
+        }
+        ri.crawlerTime = t - crawlerStart;
+        if (resCount != -1) {
+            ri.resCount = resCount;
+        }
+        if (allResCount != -1) {
+            ri.allResCount = allResCount;
+        }
     }
     
     public synchronized void addCrawlerTime(long time, int resCount, int 
allResCount) {
@@ -368,6 +510,7 @@
         if (allResCount != -1) {
             ri.allResCount = allResCount;
         }
+        checkConsistency();
     }
     
     public synchronized void addStoreTime(long time) {
@@ -391,6 +534,8 @@
         // support multiple entries
         ri.spent += diff;
         allCurrentRoots.remove(Thread.currentThread());
+        currentlyIndexedRoot.remove();
+        currentLogContext.remove();
 
         RootInfo ri2 = scannedSourceRoots.get(ri.url);
         if (ri2 == null) {
@@ -398,6 +543,36 @@
             scannedSourceRoots.put(ri.url, ri2);
         }
         ri2.merge(ri);
+        checkConsistency();
+    }
+    
+    public synchronized void startIndexer(String fName) {
+        if (frozen) {
+            return;
+        }
+        RootInfo ri = allCurrentRoots.get(Thread.currentThread());
+        if (ri == null) {
+            LOG.log(Level.FINE, "Unreported root for running indexer: " + 
fName, new Throwable());
+        } else {
+            ri.startIndexer(fName);
+        }
+    }
+    
+    public synchronized void finishIndexer(String fName) {
+        if (frozen) {
+            return;
+        }
+        RootInfo ri = allCurrentRoots.get(Thread.currentThread());
+        if (ri == null) {
+            LOG.log(Level.FINE, "Unreported root for running indexer: " + 
fName, new Throwable());
+        } else {
+            long addTime = ri.finishIndexer(fName);
+            Long t = totalIndexerTime.get(fName);
+            if (t == null) {
+                t = Long.valueOf(0);
+            }
+            totalIndexerTime.put(fName, t + addTime);
+        }
     }
     
     public synchronized void addIndexerTime(String fName, long addTime) {
@@ -408,17 +583,14 @@
         if (t == null) {
             t = Long.valueOf(0);
         }
-        totalIndexerTime.put(fName, t + addTime);
         RootInfo ri = allCurrentRoots.get(Thread.currentThread());
         if (ri == null) {
             LOG.log(Level.FINE, "Unreported root for running indexer: " + 
fName, new Throwable());
         } else {
-             t = ri.rootIndexerTime.get(fName);
-            if (t == null) {
-                t = Long.valueOf(0);
+            if (ri.indexerName != null) {
+                addTime = ri.finishIndexer(fName);
             }
-            t += addTime;
-            ri.rootIndexerTime.put(fName, t);
+            totalIndexerTime.put(fName, t + addTime);
         }
     }
     
@@ -543,30 +715,50 @@
         sb.append("\nCurrent indexer(s): ");
         for (RootInfo ri : allCurrentRoots.values()) {
             sb.append("\n\t").append(ri.url);
-            for (Map.Entry<String, Long> indexTime : 
ri.rootIndexerTime.entrySet()) {
-                sb.append("\n\t\t").append(indexTime.getKey()).
-                        append(": ").append(indexTime.getValue());
+            List<String> indexerNames = new 
ArrayList<String>(ri.rootIndexerTime.keySet());
+            Collections.sort(indexerNames);
+            for (String s : indexerNames) {
+                long l = ri.rootIndexerTime.get(s);
+                sb.append("\n\t\t").append(s).
+                        append(": ").append(l);
             }
         }
         sb.append("\nTime spent in indexers:");
         List<String> iNames = new 
ArrayList<String>(totalIndexerTime.keySet());
         Collections.sort(iNames);
-        for (Map.Entry<String, Long> indexTime : 
totalIndexerTime.entrySet()) {
-            sb.append("\n\t").append(indexTime.getKey()).
-                    append(": ").append(indexTime.getValue());
+        for (String s : iNames) {
+            long l = totalIndexerTime.get(s);
+            sb.append("\n\t").append(s).
+                    append(": ").append(l);
         }
         sb.append("\nTime spent in indexers, in individual roots:");
         for (Map.Entry<URL, RootInfo> rootEn : 
scannedSourceRoots.entrySet()) {
             sb.append("\n\t").append(rootEn.getKey());
             RootInfo ri = rootEn.getValue();
-            for (Map.Entry<String, Long> indexTime : 
ri.rootIndexerTime.entrySet()) {
-                sb.append("\n\t\t").append(indexTime.getKey()).
-                        append(": ").append(indexTime.getValue());
+            List<String> indexerNames = new 
ArrayList<String>(ri.rootIndexerTime.keySet());
+            Collections.sort(indexerNames);
+            for (String s : indexerNames) {
+                long l = ri.rootIndexerTime.get(s);
+                sb.append("\n\t\t").append(s).
+                        append(": ").append(l);
             }
         }
         
         sb.append("\nTime in index store: " + storeTime);
         sb.append("\nTime crawling: " + crawlerTime);
+        
+        if (!reindexInitiators.isEmpty()) {
+            sb.append("\nReindexing demanded by indexers:\n");
+            for (URL u : reindexInitiators.keySet()) {
+                List<String> indexers = new 
ArrayList<String>(reindexInitiators.get(u));
+                Collections.sort(indexers);
+                sb.append("\t").append(u).append(": 
").append(indexers).append("\n");
+            }
+        }
+        if (!indexersAdded.isEmpty()) {
+            sb.append("\nIndexers added: " + indexersAdded);
+        }
+        
         sb.append("\nStacktrace:\n");    //NOI18N
         for (StackTraceElement se : stackTrace) {
             sb.append('\t').append(se).append('\n'); //NOI18N
@@ -816,6 +1008,9 @@
             if (found == null) {
                 return;
             }
+            if (closing || RepositoryUpdater.getDefault().getState() == 
RepositoryUpdater.State.STOPPED) {
+                return;
+            }
             
             LOG.log(Level.WARNING, "Excessive indexing rate detected: " + 
dataSize(found.first, found.second) + " in " + minutes + "mins, treshold is " 
+ treshold + 
                     ". Dumping suspicious contexts");
@@ -909,4 +1104,65 @@
         
     private static final Stats STATS = new Stats();
 
+    synchronized void reindexForced(URL root, String indexerName) {
+        if (reindexInitiators.isEmpty()) {
+            reindexInitiators = new HashMap<URL, Set<String>>();
 }
+        Set<String> inits = reindexInitiators.get(root);
+        if (inits == null) {
+            inits = new HashSet<String>();
+            reindexInitiators.put(root, inits);
+        }
+        inits.add(indexerName);
+    }
+    synchronized void newIndexerSeen(String s) {
+        if (indexersAdded.isEmpty()) {
+            indexersAdded = new ArrayList<String>();
+        }
+        indexersAdded.add(s);
+    }
+    
+    private static final Logger BACKDOOR_LOG = 
Logger.getLogger(LogContext.class.getName() + ".backdoor");
+    
+    static {
+        BACKDOOR_LOG.addHandler(new LH());
+        BACKDOOR_LOG.setUseParentHandlers(false);
+    }
+    
+    private static class LH extends java.util.logging.Handler {
+        @Override
+        public void publish(LogRecord record) {
+            String msg = record.getMessage();
+            if (msg.equals("INDEXER_START")) {
+                String indexerName = (String)record.getParameters()[0];
+//                RootInfo ri = currentlyIndexedRoot.get();
+//                if (ri != null) {
+//                    ri.startIndexer(indexerName);
+//                }
+                LogContext lcx = currentLogContext.get();
+                if (lcx != null) {
+                    lcx.startIndexer(indexerName);
+                }
+            } else if (msg.equals("INDEXER_END")) {
+                String indexerName = (String)record.getParameters()[0];
+                LogContext lcx = currentLogContext.get();
+                if (lcx != null) {
+                    lcx.finishIndexer(indexerName);
+                }
+//                RootInfo ri = currentlyIndexedRoot.get();
+//                if (ri != null) {
+//                    ri.finishIndexer(indexerName);
+//                }
+            }
+            record.setLevel(Level.OFF);
+        }
+
+        @Override
+        public void flush() {
+        }
+
+        @Override
+        public void close() throws SecurityException {
+        }
+    }
+}
diff --git 
a/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/RepositoryUpdater.java
 
b/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/RepositoryUpdater.java
--- 
a/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/RepositoryUpdater.java
+++ 
b/parsing.api/src/org/netbeans/modules/parsing/impl/indexing/RepositoryUpdater.java
@@ -2246,7 +2246,7 @@
                     value = 
Pair.<SourceIndexerFactory,Context>of(factory,ctx);
                     ctxToFinish.put(key,value);
                 }
-                long time = System.currentTimeMillis();
+                logStartIndexer(factory.getIndexerName());
                 try {
                     boolean vote = factory.scanStarted(value.second);
                     votes.put(factory,vote);
@@ -2257,10 +2257,7 @@
                     votes.put(factory, false);
                     Exceptions.printStackTrace(t);
                 } finally {
-                    if (getLogContext() != null) {
-                        long timeSpan = System.currentTimeMillis() - time;
-                        
getLogContext().addIndexerTime(factory.getIndexerName(), timeSpan);
-                    }
+                    logFinishIndexer(factory.getIndexerName());
                 }
             }
         }
@@ -2295,7 +2292,7 @@
                         value = 
Pair.<SourceIndexerFactory,Context>of(eif,context);
                         ctxToFinish.put(key, value);
                     }
-                    long time = System.currentTimeMillis();
+                    logStartIndexer(eif.getIndexerName());
                     try {
                         boolean vote = eif.scanStarted(value.second);
                         votes.put(eif, vote);
@@ -2306,10 +2303,7 @@
                         votes.put(eif, false);
                         Exceptions.printStackTrace(t);
                     } finally {
-                        if (getLogContext() != null) {
-                            long timeSpan = System.currentTimeMillis() - 
time;
-                            
getLogContext().addIndexerTime(eif.getIndexerName(), timeSpan);
-                        }
+                        logFinishIndexer(eif.getIndexerName());
                     }
                 }
             }
@@ -2326,7 +2320,7 @@
                         TEST_LOGGER.log(Level.FINEST, 
"scanFinishing:{0}:{1}", 
                                 new Object[] { entry.first.getIndexerName(), 
entry.second.getRootURI().toExternalForm() });
                     }
-                    long time = System.currentTimeMillis();
+                    logStartIndexer(entry.first.getIndexerName());
                     SPIAccessor.getInstance().putProperty(entry.second, 
ClusteredIndexables.DELETE, null);
                     SPIAccessor.getInstance().putProperty(entry.second, 
ClusteredIndexables.INDEX, null);
                     cancelRequest.setResult(finished);
@@ -2341,12 +2335,7 @@
                     } finally {
                         cancelRequest.setResult(null);
                     }
-
-
-                    if (getLogContext() != null) {
-                        long timeSpan = System.currentTimeMillis() - time;
-                        
getLogContext().addIndexerTime(entry.first.getIndexerName(), timeSpan);
-                    }
+                    logFinishIndexer(entry.first.getIndexerName());
                     if (TEST_LOGGER.isLoggable(Level.FINEST)) {
                         TEST_LOGGER.log(Level.FINEST, 
"scanFinished:{0}:{1}", 
                                 new Object[] { entry.first.getIndexerName(), 
entry.second.getRootURI().toExternalForm() });
@@ -2464,6 +2453,9 @@
                         final boolean forceReindex = votes.get(factory) == 
Boolean.FALSE && allResources != null;
                         final boolean allFiles = cifIsChanged || 
forceReindex || (allResources != null && allResources.size() == 
resources.size());
                         if (ae && forceReindex && 
LOGGER.isLoggable(Level.INFO) && resources.size() != allResources.size() && 
!cifInfo.getMimeTypes().isEmpty()) {
+                            if (getLogContext() != null) {
+                                getLogContext().reindexForced(root, 
factory.getIndexerName());
+                            }
                             LOGGER.log(Level.INFO, "Refresh of custom 
indexer ({0}) for root: {1} forced by: {2}",    //NOI18N
                                     new Object[]{
                                         cifInfo.getMimeTypes(),
@@ -2501,17 +2493,18 @@
 
                         final CustomIndexer indexer = 
factory.createIndexer();
                         long tm1 = -1, tm2 = -1;
+                        logStartIndexer(factory.getIndexerName());
                         SPIAccessor.getInstance().putProperty(value.second, 
ClusteredIndexables.INDEX, usedCi);
                         try {
                             tm1 = System.currentTimeMillis();
                             SPIAccessor.getInstance().index(indexer, 
indexables, value.second);
-                            tm2 = System.currentTimeMillis();
-                            logIndexerTime(factory.getIndexerName(), 
(int)(tm2-tm1));
                         } catch (ThreadDeath td) {
                             throw td;
                         } catch (Throwable t) {
                             LOGGER.log(Level.WARNING, null, t);
                         }
+                        tm2 = System.currentTimeMillis();
+                        logIndexerTime(factory.getIndexerName(), 
(int)(tm2-tm1));
                         if (LOGGER.isLoggable(Level.FINE)) {
                             StringBuilder sb = 
printMimeTypes(cifInfo.getMimeTypes(), new StringBuilder());
                             LOGGER.fine("Indexing source root " + root + " 
using " + indexer
@@ -2534,11 +2527,17 @@
                         
for(Set<IndexerCache.IndexerInfo<EmbeddingIndexerFactory>> eifInfos : 
indexers.eifInfosMap.values()) {
                             
for(IndexerCache.IndexerInfo<EmbeddingIndexerFactory> eifInfo : eifInfos) {
                                 if (indexers.changedEifs != null && 
indexers.changedEifs.contains(eifInfo)) {
+                                    if (getLogContext() != null) {
+                                        
getLogContext().newIndexerSeen(eifInfo.getIndexerFactory().getIndexerName());
+                                    }
                                     containsNewIndexers = true;
                                 }
                                 EmbeddingIndexerFactory eif = 
eifInfo.getIndexerFactory();
                                 boolean indexerVote = votes.get(eif) == 
Boolean.FALSE;
                                 if (indexerVote) {
+                                    if (getLogContext() != null) {
+                                        getLogContext().reindexForced(root, 
eif.getIndexerName());
+                                    }
                                     reindexVoters.add(eif);
                                 }
                                 forceReindex |= indexerVote;
@@ -2646,6 +2645,7 @@
                 SPIAccessor.getInstance().setAllFilesJob(ctx, !upToDate);
                 parkWhileSuspended();
                 long st = System.currentTimeMillis();
+                logStartIndexer(bif.getIndexerName());
                 boolean vote;
                 try {
                     startedIndexers.set(index);
@@ -2677,6 +2677,7 @@
                 for (Map.Entry<BinaryIndexerFactory, Context> entry : 
contexts.entrySet()) {
                     parkWhileSuspended();
                     long st = System.currentTimeMillis();
+                    logStartIndexer(entry.getKey().getIndexerName());
                     try {
                         if (startedIndexers.get(index)) {
                             entry.getKey().scanFinished(entry.getValue());
@@ -2786,16 +2787,17 @@
                 if (LOGGER.isLoggable(Level.FINE)) {
                     LOGGER.fine("Indexing binary " + root + " using " + 
indexer); //NOI18N
                 }
+                long st = System.currentTimeMillis();
+                logStartIndexer(f.getIndexerName());
                 try {
-                    long st = System.currentTimeMillis();
                     SPIAccessor.getInstance().index(indexer, ctx);
-                    long et = System.currentTimeMillis();
-                    logIndexerTime(f.getIndexerName(), (int)(et-st));
                 } catch (ThreadDeath td) {
                     throw td;
                 } catch (Throwable t) {
                     LOGGER.log(Level.WARNING, null, t);
                 }
+                long et = System.currentTimeMillis();
+                logIndexerTime(f.getIndexerName(), (int)(et-st));
             }
             return !getCancelRequest().isRaised();
         }
@@ -2829,6 +2831,8 @@
 
                     Source src = Source.create(fileObject);
                     try {
+                        // log parsing for the mimetype:
+                        logStartIndexer(src.getMimeType());
                         ParserManager.parse(Collections.singleton(src), new 
UserTask() {
                             @Override
                             public void run(ResultIterator resultIterator) 
throws Exception {
@@ -2836,8 +2840,10 @@
                                 final Collection<? extends 
IndexerCache.IndexerInfo<EmbeddingIndexerFactory>> infos = 
eifInfosMap.get(mimeType);
 
                                 if (infos != null && infos.size() > 0) {
+                                    boolean finished = false;
                                     for 
(IndexerCache.IndexerInfo<EmbeddingIndexerFactory> info : infos) {
                                         if (getCancelRequest().isRaised()) {
+                                            logFinishIndexer(mimeType);
                                             return;
                                         }
 
@@ -2847,6 +2853,11 @@
                                         }
 
                                         final Parser.Result pr = 
resultIterator.getParserResult();
+                                        // must follow getParserResult(), as 
resultIterators are lazy
+                                        if (!finished) {
+                                            logFinishIndexer(mimeType);
+                                            finished = true;
+                                        }
                                         if (pr != null) {
                                             final String indexerName = 
indexerFactory.getIndexerName();
                                             final int indexerVersion = 
indexerFactory.getIndexVersion();
@@ -2872,30 +2883,35 @@
                                             final EmbeddingIndexer indexer = 
indexerFactory.createIndexer(dirty, pr.getSnapshot());
                                             if (indexer != null) {
                                                 
SPIAccessor.getInstance().putProperty(value.second, 
ClusteredIndexables.INDEX, usedCi);
+                                                long st = 
System.currentTimeMillis();
+                                                logStartIndexer(indexerName);
                                                 try {
-                                                    long st = 
System.currentTimeMillis();
                                                     
SPIAccessor.getInstance().index(indexer, dirty, pr, value.second);
-                                                    long et = 
System.currentTimeMillis();
-                                                    
logIndexerTime(indexerName, (int)(et-st));
                                                 } catch (ThreadDeath td) {
                                                     throw td;
                                                 } catch (Throwable t) {
                                                     
LOGGER.log(Level.WARNING, null, t);
                                                 }
-                                            }
-                                        }
-                                    }
+                                                long et = 
System.currentTimeMillis();
+                                                logIndexerTime(indexerName, 
(int)(et-st));
+                                            }
+                                        }
+                                    }
+                                } else {
+                                    
logFinishIndexer(resultIterator.getSnapshot().getMimeType());
                                 }
 
                                 for (Embedding embedding : 
resultIterator.getEmbeddings()) {
                                     if (getCancelRequest().isRaised()) {
                                         return;
                                     }
+                                    logStartIndexer(embedding.getMimeType());
                                     
run(resultIterator.getResultIterator(embedding));
                                 }
                             }
                         });
                     } catch (final ParseException e) {
+                        logFinishIndexer(src.getMimeType());
                         LOGGER.log(Level.WARNING, null, e);
                     }
                 }
@@ -3011,10 +3027,24 @@
                     ac == null ? -1 : ac.size());
         }
 
+        protected final void logStartIndexer(String iName) {
+            if (getLogContext() != null) {
+                getLogContext().startIndexer(iName);
+            }
+        }
+        
+        protected final void logFinishIndexer(String iName) {
+            if (getLogContext() != null) {
+                getLogContext().finishIndexer(iName);
+            }
+        }
+
         protected final void logIndexerTime(
                 final @NonNull String indexerName,
                 final int time) {
             if (getLogContext() != null) {
+                // a relic, but since time is also counted in 
indexerStatistic, 
+                // it's less code than to finish indexer separately
                 getLogContext().addIndexerTime(indexerName, time);
             }
             if (!reportIndexerStatistics) {
@@ -3654,16 +3684,17 @@
                                                     });
                                             }
                                             
SPIAccessor.getInstance().putProperty(ctx.second, ClusteredIndexables.INDEX, 
ci);
+                                            long st = 
System.currentTimeMillis();
+                                            
logStartIndexer(factory.getIndexerName());
                                             try {
-                                                long st = 
System.currentTimeMillis();
                                                 
SPIAccessor.getInstance().index(indexer, indexables, ctx.second);
-                                                long et = 
System.currentTimeMillis();
-                                                
logIndexerTime(factory.getIndexerName(), (int)(et-st));
                                             } catch (ThreadDeath td) {
                                                 throw td;
                                             } catch (Throwable t) {
                                                 LOGGER.log(Level.WARNING, 
null, t);
                                             }
+                                            long et = 
System.currentTimeMillis();
+                                            
logIndexerTime(factory.getIndexerName(), (int)(et-st));
                                         } else {
                                             LOGGER.log(
                                                 Level.WARNING, 
"RefreshCifIndices ignored recently added factory: {0}", //NOI18N
@@ -4858,6 +4889,7 @@
                         LOGGER.fine("Fake indexing: indexer=" + indexer); 
//NOI18N
                     }
                     long start = System.currentTimeMillis();
+                    logStartIndexer(info.getIndexerName());
                     try {
                         final Pair<String,Integer> indexerKey = 
Pair.<String,Integer>of(factory.getIndexerName(),factory.getIndexVersion());
                         final Pair<SourceIndexerFactory,Context> ctx = 
transactionContexts.get(indexerKey);

[hg] main-silver: Fixed counts in scan cancelled reports. Added ...

Svata Dedic 12/04/2012

Project Features

About this Project

Editor was started in November 2009, is owned by Martin Ryzl, and has 147 members.
By use of this website, you agree to the NetBeans Policies and Terms of Use (revision 20140418.2d69abc). © 2013, Oracle Corporation and/or its affiliates. Sponsored by Oracle logo
 
 
Close
loading
Please Confirm
Close