Add new AnalysisDurationFormatter to ensure correct reporting of elap…

…sed analysis time for long-running batch jobs in logs.

exomiser-cli/src/main/java/org/monarchinitiative/exomiser/cli/ExomiserCommandLineRunner.java

@@ -20,9 +20,12 @@
 
 package org.monarchinitiative.exomiser.cli;
 
+import com.google.protobuf.InvalidProtocolBufferException;
+import com.google.protobuf.util.JsonFormat;
 import org.apache.commons.cli.CommandLine;
 import org.monarchinitiative.exomiser.api.v1.JobProto;
 import org.monarchinitiative.exomiser.core.Exomiser;
+import org.monarchinitiative.exomiser.core.analysis.AnalysisDurationFormatter;
 import org.monarchinitiative.exomiser.core.analysis.AnalysisResults;
 import org.monarchinitiative.exomiser.core.writers.AnalysisResultsWriter;
 import org.slf4j.Logger;
@@ -71,11 +74,19 @@ private void runJobs(List<JobProto.Job> jobs) {
             }
             Duration duration = Duration.between(timeStart, Instant.now());
             long ms = duration.toMillis();
-            logger.info("Finished batch of {} samples in {}m {}s ({} ms)", jobs.size(), (ms / 1000) / 60 % 60, ms / 1000 % 60, ms);
+            String formatted = AnalysisDurationFormatter.format(duration);
+            logger.info("Finished batch of {} samples in {} ({} ms)", jobs.size(), formatted, ms);
         }
     }
 
     private void runJob(JobProto.Job job) {
+        if (logger.isDebugEnabled()) {
+            try {
+                logger.debug("Running job {}", JsonFormat.printer().print(job));
+            } catch (InvalidProtocolBufferException e) {
+                throw new IllegalStateException(e);
+            }
+        }
         AnalysisResults analysisResults = exomiser.run(job);
         logger.info("Writing results...");
         AnalysisResultsWriter.writeToFile(analysisResults, job.getOutputOptions());

exomiser-core/src/main/java/org/monarchinitiative/exomiser/core/analysis/AbstractAnalysisRunner.java

@@ -150,11 +150,8 @@ public AnalysisResults run(Sample sample, Analysis analysis) {
 
         Duration duration = Duration.between(timeStart, Instant.now());
         long ms = duration.toMillis();
-        int hoursPart = duration.toHoursPart();
-        if (hoursPart > 0) {
-            logger.info("Finished analysis in {}h {}m {}s {}ms ({} ms)", hoursPart, duration.toMinutesPart(), duration.toSecondsPart(), duration.toMillisPart(), ms);
-        }
-        logger.info("Finished analysis in {}m {}s {}ms ({} ms)", duration.toMinutesPart(), duration.toSecondsPart(), duration.toMillisPart(), ms);
+        String formatted = AnalysisDurationFormatter.format(duration);
+        logger.info("Finished analysis in {} ({} ms)", formatted, ms);
         return analysisResults;
     }
 

exomiser-core/src/main/java/org/monarchinitiative/exomiser/core/analysis/AnalysisDurationFormatter.java

@@ -0,0 +1,44 @@
+package org.monarchinitiative.exomiser.core.analysis;
+
+import java.time.Duration;
+
+public class AnalysisDurationFormatter {
+
+    private AnalysisDurationFormatter() {
+    }
+
+    /**
+     * Outputs a simple duration format for easy human parsing of run times in the Exomiser logs.
+     * <p>
+     * Formats the input duration to the form:
+     * <pre>
+     *     1d 23h 59m 59s 999ms
+     *     1d 0h 59m 59s 999ms
+     *     23h 59m 59s 999ms
+     *     59m 59s 999ms
+     *     0m 59s 999ms
+     * </pre>
+     *
+     * @param duration
+     * @return A string representation of the input duration in days, hours, minutes, seconds, milliseconds.
+     */
+    public static String format(Duration duration) {
+        // e.g. 1d 23h 59m 59s 999ms
+        StringBuilder stringBuilder = new StringBuilder(20);
+
+        long days = duration.toDaysPart();
+        int hours = duration.toHoursPart();
+        if (days != 0) {
+            stringBuilder.append(days).append("d ");
+            // include hours, even if zero
+            stringBuilder.append(hours).append("h ");
+        } else if (hours != 0) {
+            stringBuilder.append(hours).append("h ");
+        }
+        // always retain m s ms
+        stringBuilder.append(duration.toMinutesPart()).append("m ");
+        stringBuilder.append(duration.toSecondsPart()).append("s ");
+        stringBuilder.append(duration.toMillisPart()).append("ms");
+        return stringBuilder.toString();
+    }
+}

exomiser-core/src/test/java/org/monarchinitiative/exomiser/core/analysis/AnalysisDurationFormatterTest.java

@@ -0,0 +1,47 @@
+package org.monarchinitiative.exomiser.core.analysis;
+
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.CsvSource;
+
+import java.time.Duration;
+import java.time.temporal.ChronoUnit;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.equalTo;
+
+class AnalysisDurationFormatterTest {
+
+    @ParameterizedTest
+    @CsvSource({
+            "0, 0, 0, 0, 0, 0m 0s 0ms",
+            "0, 0, 0, 0, 1, 0m 0s 1ms",
+            "0, 0, 0, 0, 999, 0m 0s 999ms",
+            "0, 0, 0, 0, 1000, 0m 1s 0ms",
+            "0, 0, 0, 1, 1000, 0m 2s 0ms",
+            "0, 0, 0, 2, 1, 0m 2s 1ms",
+            "0, 0, 3, 2, 1, 3m 2s 1ms",
+            "0, 4, 3, 2, 1, 4h 3m 2s 1ms",
+            "5, 4, 3, 2, 1, 5d 4h 3m 2s 1ms",
+            "5, 0, 3, 2, 1, 5d 0h 3m 2s 1ms",
+            "5, 25, 3, 2, 1, 6d 1h 3m 2s 1ms",
+            "5, 23, 59, 59, 999, 5d 23h 59m 59s 999ms",
+            "5, 23, 59, 59, 1000, 6d 0h 0m 0s 0ms",
+            "5, 25, 60, 60, 1000, 6d 2h 1m 1s 0ms",
+    })
+    void format(long days, int hrs, int mins, int secs, int millis, String expected) {
+        long sec = 1000;
+        long min = sec * 60;
+        long hour = min * 60;
+        long day = hour * 24;
+        Duration duration = Duration.of(days * day + hrs * hour + mins * min + secs * sec + millis, ChronoUnit.MILLIS);
+
+        assertThat(AnalysisDurationFormatter.format(duration), equalTo(expected));
+    }
+
+    @Test
+    void formatFromHours() {
+        Duration duration = Duration.of(2, ChronoUnit.HOURS);
+        assertThat(AnalysisDurationFormatter.format(duration), equalTo("2h 0m 0s 0ms"));
+    }
+}