GenomeLocProcessingTracker was using SimpleTimer in a non-thread safe way. No longer providing an interface to time parallel operations. Now issues warning if someone enables distributed GATK, as this is considered an unstable, experimental engine feature.

git-svn-id: file:///humgen/gsa-scr1/gsa-engineering/svn_contents/trunk@5842 348d0f76-0448-11de-a6fe-93d51630548a

java/src/org/broadinstitute/sting/gatk/executive/LinearMicroScheduler.java

@@ -71,15 +71,6 @@ public class LinearMicroScheduler extends MicroScheduler {
                 accumulator.accumulate(dataProvider,result);
                 dataProvider.close();
             }
-
-            if ( logger.isDebugEnabled() ) {
-                counter++;
-                logger.debug(String.format("At %s: processed %d shards.  %.2e s / lock (n=%d), %.2e s / read (n=%d), %.2e s / write (n=%d)",
-                        shard.getLocation(), counter,
-                        processingTracker.getTimePerLock(), processingTracker.getNLocks(),
-                        processingTracker.getTimePerRead(), processingTracker.getNReads(),
-                        processingTracker.getTimePerWrite(), processingTracker.getNWrites()));
-            }
         }
 
         Object result = accumulator.finishTraversal();

java/src/org/broadinstitute/sting/gatk/executive/MicroScheduler.java

@@ -165,6 +165,7 @@ public abstract class MicroScheduler implements MicroSchedulerMBean {
         // create the processing tracker
         //
         if ( engine.getArguments().processingTrackerFile != null ) {
+            logger.warn("Distributed GATK is an experimental engine feature, and is likely to not work correctly or reliably.");
             if ( engine.getArguments().restartProcessingTracker && engine.getArguments().processingTrackerFile.exists() ) {
                 engine.getArguments().processingTrackerFile.delete();
                 logger.info("Deleting ProcessingTracker file " + engine.getArguments().processingTrackerFile);

java/src/org/broadinstitute/sting/utils/threading/GenomeLocProcessingTracker.java

@@ -82,10 +82,13 @@ public abstract class GenomeLocProcessingTracker {
 
     //
     // Timers for recording performance information
+    // Note -- these cannot be used because this class isn't thread safe, and neither are the
+    // timers, so they result in invalid operations w.r.t. the SimpleTimer contract
     //
-    protected final SimpleTimer writeTimer = new SimpleTimer("writeTimer");
+//    protected final SimpleTimer writeTimer = new SimpleTimer("writeTimer");
-    protected final SimpleTimer readTimer = new SimpleTimer("readTimer");
+//    protected final SimpleTimer readTimer = new SimpleTimer("readTimer");
-    protected final SimpleTimer lockWaitTimer = new SimpleTimer("lockWaitTimer");
+//    protected final SimpleTimer lockWaitTimer = new SimpleTimer("lockWaitTimer");
+    protected final SimpleTimer timer = new SimpleTimer();
     protected long nLocks = 0, nWrites = 0, nReads = 0;
 
     // --------------------------------------------------------------------------------
@@ -318,10 +321,10 @@ public abstract class GenomeLocProcessingTracker {
     protected final Map<GenomeLoc, ProcessingLoc> updateAndGetProcessingLocs(String myName) {
         return new WithLock<Map<GenomeLoc, ProcessingLoc>>(myName) {
             public Map<GenomeLoc, ProcessingLoc> doBody() {
-                readTimer.restart();
+//                readTimer.restart();
                 for ( ProcessingLoc p : readNewLocs() )
                     processingLocs.put(p.getLocation(), p);
-                readTimer.stop();
+//                readTimer.stop();
                 nReads++;
                 return processingLocs;
             }
@@ -335,10 +338,10 @@ public abstract class GenomeLocProcessingTracker {
      * @param myName
      */
     protected final void registerNewLocsWithTimers(Collection<ProcessingLoc> plocs, String myName) {
-        writeTimer.restart();
+//        writeTimer.restart();
         registerNewLocs(plocs);
         nWrites++;
-        writeTimer.stop();
+//        writeTimer.stop();
     }
 
     private final void printStatusHeader() {
@@ -360,15 +363,15 @@ public abstract class GenomeLocProcessingTracker {
      * @param id the name of the process doing the locking
      */
     private final void lock(String id) {
-        lockWaitTimer.restart();
+        //lockWaitTimer.restart();
         boolean hadLock = lock.ownsLock();
         if ( ! hadLock ) {
             nLocks++;
-            printStatus(id, lockWaitTimer.currentTime(), GOING_FOR_LOCK);
+            //printStatus(id, lockWaitTimer.currentTime(), GOING_FOR_LOCK);
         }
         lock.lock();
-        lockWaitTimer.stop();
+        //lockWaitTimer.stop();
-        if ( ! hadLock ) printStatus(id, lockWaitTimer.currentTime(), HAVE_LOCK);
+        //if ( ! hadLock ) printStatus(id, lockWaitTimer.currentTime(), HAVE_LOCK);
     }
 
     /**
@@ -376,18 +379,18 @@ public abstract class GenomeLocProcessingTracker {
      * @param id the name of the process doing the unlocking
      */
     private final void unlock(String id) {
-        if ( lock.getHoldCount() == 1 ) printStatus(id, lockWaitTimer.currentTime(), RELEASING_LOCK);
+        if ( lock.getHoldCount() == 1 ) printStatus(id, timer.currentTime(), RELEASING_LOCK);
         lock.unlock();
-        if ( ! lock.ownsLock() ) printStatus(id, lockWaitTimer.currentTime(), RUNNING);
+        if ( ! lock.ownsLock() ) printStatus(id, timer.currentTime(), RUNNING);
     }
 
     // useful code for getting
     public final long getNLocks() { return nLocks; }
     public final long getNReads() { return nReads; }
     public final long getNWrites() { return nWrites; }
-    public final double getTimePerLock() { return lockWaitTimer.getElapsedTime() / Math.max(nLocks, 1); }
+//    public final double getTimePerLock() { return lockWaitTimer.getElapsedTime() / Math.max(nLocks, 1); }
-    public final double getTimePerRead() { return readTimer.getElapsedTime() / Math.max(nReads,1); }
+//    public final double getTimePerRead() { return readTimer.getElapsedTime() / Math.max(nReads,1); }
-    public final double getTimePerWrite() { return writeTimer.getElapsedTime() / Math.max(nWrites,1); }
+//    public final double getTimePerWrite() { return writeTimer.getElapsedTime() / Math.max(nWrites,1); }
 
     // --------------------------------------------------------------------------------
     //