Proposed replacement for progress PR (#1302)

* Made progress logger emit read-names if it detects that the coordinates are not strictly increasing.
Thanks @helgridly

src/main/java/htsjdk/samtools/util/AbstractProgressLogger.java

@@ -18,10 +18,14 @@ abstract public class AbstractProgressLogger implements ProgressLoggerInterface
     private long startTime;
     private final NumberFormat fmt = new DecimalFormat("#,###");
     private final NumberFormat timeFmt = new DecimalFormat("00");
-    private long processed;
-    private long lastStartTime;
-    private String lastChrom;
-    private int lastPos;
+    private long processed = 0;
+    // Set to -1 until the first record is added
+    private long lastStartTime = -1;
+    private String lastChrom = null;
+    private int lastPos = 0;
+    private String lastReadName = null;
+    private long countNonIncreasing = 0;
+    final static private long PRINT_READ_NAME_THRESHOLD = 1000;
 
     /**
      * Construct an AbstractProgressLogger.
@@ -60,18 +64,26 @@ private synchronized void record() {
         if (this.lastChrom == null) readInfo = "*/*";
         else readInfo = this.lastChrom + ":" + fmt.format(this.lastPos);
 
+        final String rnInfo;
+
+        if (lastReadName != null && countNonIncreasing > PRINT_READ_NAME_THRESHOLD) {
+            rnInfo = ".  Last read name: " + lastReadName;
+        } else {
+            rnInfo = "";
+        }
+
         final long n = (this.processed % this.n == 0) ? this.n : this.processed % this.n;
 
         log(this.verb, " ", processed, " " + noun + ".  Elapsed time: ", elapsed, "s.  Time for last ", fmt.format(n),
-                ": ", period, "s.  Last read position: ", readInfo);
+                ": ", period, "s.  Last read position: ", readInfo, rnInfo);
     }
 
     /**
      * Logs the last last record if it wasn't previously logged.
      * @return boolean true if logging was triggered, false otherwise
      */
     public synchronized boolean log() {
-        if (this.processed % this.n != 0) {
+        if (processed % this.n != 0) {
             record();
             return true;
         }
@@ -80,41 +92,53 @@ public synchronized boolean log() {
         }
     }
 
-    @Override
-    public synchronized boolean record(final String chrom, final int pos) {
-        this.lastChrom = chrom;
-        this.lastPos = pos;
-        if (this.lastStartTime == -1) {
-            this.lastStartTime = System.currentTimeMillis();
+    protected synchronized boolean record(final String chrom, final int pos, final String rname) {
+        if (chrom != null && chrom.equals(lastChrom) && pos < lastPos) {
+            countNonIncreasing++;
+            if (countNonIncreasing == PRINT_READ_NAME_THRESHOLD) {
+                log("Seen many non-increasing record positions. Printing Read-names as well.");
+            }
+        } else {
+            lastChrom = chrom;
+        }
+        lastPos = pos;
+        lastReadName = rname;
+        if (lastStartTime == -1) {
+            lastStartTime = System.currentTimeMillis();
         }
-        if (++this.processed % this.n == 0) {
+        if (++processed % n == 0) {
             record();
             return true;
-        }
-        else {
+        } else {
             return false;
         }
     }
 
+    @Override
+    public synchronized boolean record(final String chrom, final int pos) {
+        return record(chrom, pos, null);
+    }
+
     /**
      * Records that a given record has been processed and triggers logging if necessary.
      * @return boolean true if logging was triggered, false otherwise
      */
     @Override
     public synchronized boolean record(final SAMRecord rec) {
         if (SAMRecord.NO_ALIGNMENT_REFERENCE_NAME.equals(rec.getReferenceName())) {
-            return record(null, 0);
-        }
-        else {
-            return record(rec.getReferenceName(), rec.getAlignmentStart());
+            return record(null, 0, rec.getReadName());
+        } else {
+            return record(rec.getReferenceName(), rec.getAlignmentStart(), rec.getReadName());
         }
     }
 
     /** Records multiple SAMRecords and triggers logging if necessary. */
     @Override
     public boolean record(final SAMRecord... recs) {
         boolean triggered = false;
-        for (final SAMRecord rec : recs) triggered = record(rec) || triggered;
+        for (final SAMRecord rec : recs) {
+            triggered = record(rec) || triggered;
+        }
         return triggered;
     }
 
@@ -125,22 +149,25 @@ public boolean record(final SAMRecord... recs) {
     public long getElapsedSeconds() { return (System.currentTimeMillis() - this.startTime) / 1000; }
 
     /** Resets the start time to now and the number of records to zero. */
-    public void reset() {
+    public synchronized void reset() {
         startTime = System.currentTimeMillis();
         processed = 0;
         // Set to -1 until the first record is added
         lastStartTime = -1;
         lastChrom = null;
         lastPos = 0;
+        lastReadName = null;
+        countNonIncreasing = 0;
     }
 
     /** Left pads a string until it is at least the given length. */
-    private String pad (String in, final int length) {
-        while (in.length() < length) {
-            in = " " + in;
+    static String pad(final String in, final int length) {
+        final StringBuilder inBuilder = new StringBuilder(Math.max(length, in.length()));
+        while (inBuilder.length() < length - in.length()) {
+            inBuilder.append(" ");
         }
 
-        return in;
+        return inBuilder.append(in).toString();
     }
 
     /** Formats a number of seconds into hours:minutes:seconds. */

src/main/java/htsjdk/samtools/util/Log.java

@@ -117,7 +117,7 @@ public static final boolean isEnabled(final LogLevel level) {
      */
     private void emit(final LogLevel level, final Throwable throwable, final Object... parts) {
         if (isEnabled(level)) {
-        	StringBuffer tmp = new StringBuffer();
+            final StringBuffer tmp = new StringBuffer();
             tmp.append(level.name())
                     .append('\t')
                     .append(getTimestamp())
@@ -145,10 +145,10 @@ private void emit(final LogLevel level, final Throwable throwable, final Object.
 
             // Print out the exception if there is one
             if (throwable != null) {
-             	synchronized (this.out) {
+                synchronized (this.out) {
                     this.out.println(tmp.toString());
                     throwable.printStackTrace(this.out);
-             	}
+                }
             }
             else {
                 this.out.println(tmp.toString());

src/test/java/htsjdk/samtools/BAMFileWriterTest.java

@@ -78,10 +78,9 @@ private void testHelper(final SAMRecordSetBuilder samRecordSetBuilder, final SAM
         }
 
         final File tempMetrics = File.createTempFile("CGTagTest", ".validation_metrics");
-        try (
-                final SamReader samReader = SamReaderFactory.makeDefault().open(bamFile);
-                final OutputStream outputStream = new FileOutputStream(tempMetrics);
-                final PrintWriter printWriter = new PrintWriter(outputStream)) {
+        try (final SamReader samReader = SamReaderFactory.makeDefault().open(bamFile);
+             final OutputStream outputStream = new FileOutputStream(tempMetrics);
+             final PrintWriter printWriter = new PrintWriter(outputStream)) {
 
             new SamFileValidator(printWriter, 100).validateSamFileSummary(samReader, null);
         }

src/test/scala/htsjdk/samtools/fastq/FastqReaderWriterTest.scala

@@ -176,5 +176,4 @@ class FastqReaderWriterTest extends UnitSpec {
     an[Exception] shouldBe thrownBy { new FastqReader(noSeqHeader).iterator().toSeq }
     an[Exception] shouldBe thrownBy { new FastqReader(noQualHeader).iterator().toSeq }
   }
-
 }

src/test/scala/htsjdk/samtools/util/AbstractProgressLoggerTest.scala

@@ -0,0 +1,17 @@
+package htsjdk.samtools.util
+
+import htsjdk.UnitSpec
+
+class AbstractProgressLoggerTest extends UnitSpec {
+
+  "AbstractProgressLoggerTest.pad" should "pad the right amount of spaces in " in {
+    Seq(
+      ("hello", 10, "     hello"),
+      ("hello", 6, " hello"),
+      ("hello", 5, "hello"),
+      ("hello", 4, "hello"),
+      ("hello", -1, "hello")).foreach { case (in, len, expected) =>
+      AbstractProgressLogger.pad(in, len) shouldEqual expected
+    }
+  }
+}