bloom-dbg: steadier and less verbose progress messages

Output separate progress messages for the number of reads processed and the
number of bases assembled so far. This ensures that the user sees progress
updates at regular intervals.

At the same time, increase the step sizes of the progress messages so to keep
log files a reasonable size.

Author: Ben Vandervalk

BloomDBG/AssemblyCounters.h

@@ -16,18 +16,17 @@ namespace BloomDBG {
 	{
 		/** reads consisting entirely of solid k-mers */
 		size_t solidReads;
-		size_t allKmersVisited;
-		size_t allBranchKmersVisited;
-		size_t nonBranchingReads;
-		size_t nonBranchingContigs;
+		/**
+		 * reads consisting entirely of k-mers already
+		 * included in output contigs
+		 */
+		size_t visitedReads;
 		size_t readsProcessed;
 		size_t basesAssembled;
 		size_t contigID;
 
-		AssemblyCounters() : solidReads(0), allKmersVisited(0),
-			allBranchKmersVisited(0), nonBranchingReads(0),
-			nonBranchingContigs(0), readsProcessed(0),
-			basesAssembled(0), contigID(0) {}
+		AssemblyCounters() : solidReads(0), visitedReads(0),
+			readsProcessed(0), basesAssembled(0), contigID(0) {}
 
 		/** serialize counters as a TSV table */
 		friend std::ostream& operator<<(std::ostream& out,

BloomDBG/bloom-dbg.h

@@ -314,27 +314,23 @@ namespace BloomDBG {
 	};
 
 	/** Print an intermediate progress message during assembly */
-	void printProgressMessage(AssemblyCounters counters)
+	void readsProgressMessage(AssemblyCounters counters)
 	{
-#pragma omp critical(cerr)
 		std::cerr
 			<< "Processed " << counters.readsProcessed << " reads"
-			<< ", [solid: " << counters.solidReads
+			<< ", solid reads: " << counters.solidReads
 			<< " (" << std::setprecision(3) << (float)100
-		    * counters.solidReads / counters.readsProcessed << "%)"
-			<< ", all k-mers visited: " << counters.allKmersVisited
+			* counters.solidReads / counters.readsProcessed << "%)"
+			<< ", visited reads: " << counters.visitedReads
 			<< " (" << std::setprecision(3) << (float)100
-		    * counters.allKmersVisited / counters.readsProcessed << "%)"
-			<< ", all branch k-mers visited: " << counters.allBranchKmersVisited
-			<< " (" << std::setprecision(3) << (float)100
-		    * counters.allBranchKmersVisited / counters.readsProcessed << "%)"
-			<< ", non-branching: " << counters.nonBranchingReads
-			<< " (" << std::setprecision(3) << (float)100
-		    * counters.nonBranchingReads / counters.readsProcessed << "%)"
-			<< ", non-branching contigs: " << counters.nonBranchingContigs
-			<< " (" << std::setprecision(3) << (float)100
-			* counters.nonBranchingContigs / counters.readsProcessed << "%)"
-			<< "], assembled " << counters.basesAssembled << " bp in "
+			* counters.visitedReads / counters.readsProcessed << "%)"
+			<< std::endl;
+	}
+
+	/** Print an intermediate progress message during assembly */
+	void basesProgressMessage(AssemblyCounters counters)
+	{
+		std::cerr << "Assembled " << counters.basesAssembled << " bp in "
 			<< counters.contigID + 1 << " contigs"
 			<< std::endl;
 	}
@@ -793,7 +789,7 @@ namespace BloomDBG {
 		/* skip reads in previously assembled regions */
 		if (allKmersInBloom(seq, assembledKmerSet)) {
 #pragma omp atomic
-			counters.allKmersVisited++;
+			counters.visitedReads++;
 			return ReadRecord(rec.id, RR_ALL_KMERS_VISITED);
 		}
 
@@ -955,8 +951,6 @@ namespace BloomDBG {
 
 		/* per-thread I/O buffer (size is in bases) */
 		const size_t SEQ_BUFFER_SIZE = 1000000;
-		/* controls frequency of progress messages */
-		const unsigned PROGRESS_STEP = 1000;
 
 		if (params.verbose)
 			std::cerr << "Trimming branches " << params.trim
@@ -970,6 +964,18 @@ namespace BloomDBG {
 
 		KmerHash visitedBranchKmers;
 
+		/*
+		 * Print a progress message whenever `READS_PROGRESS_STEP`
+		 * reads have been processed or `BASES_PROGRESS_STEP`
+		 * bases have been assembled. The purpose of using
+		 * two measures of progess is to show steady updates
+		 * throughout the assembly process.
+		 */
+
+		const size_t READS_PROGRESS_STEP = 100000;
+		const size_t BASES_PROGRESS_STEP = 1000000;
+		size_t basesProgressLine = BASES_PROGRESS_STEP;
+
 		while (true)
 		{
 			size_t readsUntilCheckpoint = params.readsPerCheckpoint;
@@ -1005,10 +1011,23 @@ namespace BloomDBG {
 							contigEndKmers, visitedBranchKmers,
 							params, counters, streams);
 
-#pragma omp atomic
-					counters.readsProcessed++;
-					if (params.verbose && counters.readsProcessed % PROGRESS_STEP == 0)
-						printProgressMessage(counters);
+#pragma omp critical(readsProgress)
+					{
+						++counters.readsProcessed;
+						if (params.verbose && counters.readsProcessed
+							% READS_PROGRESS_STEP == 0)
+							readsProgressMessage(counters);
+					}
+
+					if (params.verbose)
+#pragma omp critical(basesProgress)
+					{
+						if (counters.basesAssembled >= basesProgressLine) {
+							basesProgressMessage(counters);
+							while (counters.basesAssembled >= basesProgressLine)
+								basesProgressLine += BASES_PROGRESS_STEP;
+						}
+					}
 
 					if (!params.readLogPath.empty()) {
 #pragma omp critical(readLog)
@@ -1034,7 +1053,8 @@ namespace BloomDBG {
 		assert(in.eof());
 
 		if (params.verbose) {
-			printProgressMessage(counters);
+			readsProgressMessage(counters);
+			basesProgressMessage(counters);
 			std::cerr << "Assembly complete" << std::endl;
 		}