More verbose output from command-line example

cmd/Makefile

@@ -2,7 +2,9 @@ all: out/stretch
 
 out/stretch: ../signalsmith-stretch.h main.cpp util/*.h util/*.hxx ../dsp/*.h
 	mkdir -p out
-	g++ main.cpp -o out/stretch -std=c++11 -O3 -g
+	g++ -std=c++11 -O3 -g \
+		-Wall -Wextra -Wfatal-errors -Wpedantic -pedantic-errors \
+		main.cpp -o out/stretch
 
 examples: out/stretch
 	inputs/run-all.sh out/d1- out/stretch --semitones=-1

cmd/main.cpp

@@ -1,10 +1,9 @@
+#include "util/stopwatch.h"
 #include "util/memory-tracker.hxx"
 
 #include <iostream>
 #define LOG_EXPR(expr) std::cout << #expr << " = " << (expr) << "\n";
 
-#include <ctime>
-
 #include "../signalsmith-stretch.h"
 #include "util/simple-args.h"
 #include "util/wav.h"
@@ -20,6 +19,11 @@ int main(int argc, char* argv[]) {
 	double time = args.flag<double>("time", "time-stretch factor", 1);
 	bool exactLength = args.hasFlag("exact", "trims the start/end so the output has the correct length");
 	args.errorExit();
+	
+	std::cout << Console::Bright << inputWav << Console::Reset;
+	std::cout << " -> ";
+	std::cout << Console::Bright << outputWav << Console::Reset << "\n";
+	std::cout << "\tsemitones: " << semitones << "\n\t     time: " << time << "x" << (exactLength ? " (exact)" : "") << "\n\t tonality: " << tonality << "Hz\n";
 
 	Wav inWav;
 	if (!inWav.read(inputWav).warn()) args.errorExit("failed to read WAV");
@@ -37,15 +41,20 @@ int main(int argc, char* argv[]) {
 	outWav.sampleRate = inWav.sampleRate;
 	int outputLength = std::round(inputLength*time);
 
-	signalsmith::MemoryTracker memory;
+	signalsmith::MemoryTracker initMemory;
+	signalsmith::Stopwatch stopwatch;
 
-	// Use cheap RNG for comparison
-	signalsmith::stretch::SignalsmithStretch<float, std::mt19937> stretch;
+	stopwatch.start();
+	signalsmith::stretch::SignalsmithStretch<float/*, std::mt19937*/> stretch; // optional cheaper RNG for performance comparison
 	stretch.presetDefault(inWav.channels, inWav.sampleRate);
 	stretch.setTransposeSemitones(semitones, tonality/inWav.sampleRate);
+	double initSeconds = stopwatch.seconds(stopwatch.lap());
 
-	memory = memory.diff();
-	std::cout << "Memory: allocated " << (memory.allocBytes/1000) << "kB, freed " << (memory.freeBytes/1000) << "kB\n";
+	initMemory = initMemory.diff();
+	std::cout << "Setup:\n\t" << initSeconds << "s\n";
+	if (initMemory.implemented) {
+		std::cout << "\tallocated " << (initMemory.allocBytes/1000) << "kB, freed " << (initMemory.freeBytes/1000) << "kB\n";
+	}
 
 	// pad the input at the end, since we'll be reading slightly ahead
 	size_t paddedInputLength = inputLength + stretch.inputLatency();
@@ -56,29 +65,31 @@ int main(int argc, char* argv[]) {
 	outWav.samples.resize(paddedOutputLength*outWav.channels);
 
 	signalsmith::MemoryTracker processMemory;
-	// The simplest way to deal with input latency is to always be slightly ahead in the input
+
+	stopwatch.start();
+	// The simplest way to deal with input latency (when have access to the audio buffer) is to always be slightly ahead in the input
 	stretch.seek(inWav, stretch.inputLatency(), 1/time);
-	
-	// Process it all in one call, although it works just the same if we split into smaller blocks
 	inWav.offset += stretch.inputLatency();
-
-	// These lengths in the right ratio to get the time-stretch
+	// Process it all in one call, although it works just the same if we split into smaller blocks
 	stretch.process(inWav, inputLength, outWav, outputLength);
-
-	processMemory = processMemory.diff();
-	if (processMemory) {
-		std::cout << "Processing (alloc/free/current):\t" << processMemory.allocBytes << "/" << processMemory.freeBytes << "/" << processMemory.currentBytes << "\n";
-		args.errorExit("allocated during process()");
-	}
-
 	// Read the last bit of output without giving it any more input
 	outWav.offset += outputLength;
 	stretch.flush(outWav, tailSamples);
 	outWav.offset -= outputLength;
+
+	double processSeconds = stopwatch.seconds(stopwatch.lap());
+	double processRate = (inWav.length()/inWav.sampleRate)/processSeconds;
+	double processPercent = 100/processRate;
+	processMemory = processMemory.diff();
+	std::cout << "Process:\n\t" << processSeconds << "s, " << processRate << "x realtime, " << processPercent << "% CPU\n";
+	if (processMemory.implemented) {
+		std::cout << "\tallocated " << (processMemory.allocBytes/1000) << "kB, freed " << (processMemory.freeBytes/1000) << "kB\n";
+		if (processMemory) args.errorExit("allocated during process()");
+	}
 	
 	if (exactLength) {
 		// The start has some extra output - we could just trim it, but we might as well fold it back into the output
-		for (int c = 0; c < outWav.channels; ++c) {
+		for (size_t c = 0; c < outWav.channels; ++c) {
 			for (int i = 0; i < stretch.outputLatency(); ++i) {
 				double trimmed = outWav[stretch.outputLatency() - 1 - i][c];
 				outWav[stretch.outputLatency() + i][c] -= trimmed; // reversed in time and negated

cmd/util/memory-tracker.h

@@ -7,6 +7,8 @@
 namespace signalsmith {
 
 struct MemoryTracker {
+	static const bool implemented; // Whether the implementation actually tracks memory or not
+
 	size_t allocBytes, freeBytes, currentBytes;
 	MemoryTracker();
 	

cmd/util/memory-tracker.hxx

@@ -3,7 +3,9 @@
 #if !defined(__has_include) || !__has_include(<dlfcn.h>)
 // Fallback if we don't have <dlfcn.h>, which we use to get the existing methods
 signalsmith::MemoryTracker::MemoryTracker() : signalsmith::MemoryTracker::MemoryTracker(0, 0) {}
+const bool signalsmith::MemoryTracker::implemented = false;
 #else
+const bool signalsmith::MemoryTracker::implemented = true;
 
 #include <cstdlib>
 #include <cstddef>

cmd/util/stopwatch.h

@@ -0,0 +1,104 @@
+#ifndef SIGNALSMITH_STOPWATCH_UTIL_H
+#define SIGNALSMITH_STOPWATCH_UTIL_H
+
+#include <limits>
+#include <cmath>
+#include <atomic>
+#include <algorithm>
+
+// We want CPU time, not wall-clock time, so we can't use `std::chrono::high_resolution_clock`
+#ifdef WINDOWS
+#	include <windows.h>
+namespace signalsmith {
+class Stopwatch {
+	using Time = __int64;
+	inline Time now() {
+		LARGE_INTEGER result;
+		QueryPerformanceCounter(&result);
+		return result.QuadPart;
+	}
+	static double timeToSeconds(double t) {
+		LARGE_INTEGER freq;
+		QueryPerformanceFrequency(&freq);
+		return t/double(freq);
+	}
+#else
+#	include <ctime>
+namespace signalsmith {
+class Stopwatch {
+	using Time = std::clock_t;
+	inline Time now() {
+		return std::clock();
+	}
+	static double timeToSeconds(double t) {
+		return t/double(CLOCKS_PER_SEC);
+	}
+#endif
+
+	std::atomic<Time> lapStart; // the atomic store/load should act as barriers for reordering operations
+	Time lapBest, lapTotal, lapTotal2;
+	double lapOverhead = 0;
+	int lapCount = 0;
+	
+public:
+	Stopwatch(bool compensate=true) {
+		if (compensate) {
+			start();
+			const int repeats = 1000;
+			for (int i = 0; i < repeats; ++i) {
+				startLap();
+				lap();
+			}
+			lapOverhead = (double)lapTotal/lapCount;
+		}
+		start();
+	}
+
+	static double seconds(double time) {
+		return timeToSeconds(time);
+	}
+
+	void start() {
+		lapCount = 0;
+		lapTotal = lapTotal2 = 0;
+		lapBest = std::numeric_limits<Time>::max();
+		startLap();
+	}
+	void startLap() {
+		lapStart.store(now());
+	}
+	double lap() {
+		auto start = lapStart.load();
+		auto diff = now() - start;
+
+		if (diff < lapBest) lapBest = diff;
+		lapCount++;
+		lapTotal += diff;
+		lapTotal2 += diff*diff;
+
+		startLap();
+		return diff;
+	}
+	double total() const {
+		return std::max(0.0, lapTotal - lapCount*lapOverhead);
+	}
+	double mean() const {
+		return total()/lapCount;
+	}
+	double var() const {
+		double m = (double)lapTotal/lapCount, m2 = (double)lapTotal2/lapCount;
+		return std::max(0.0, m2 - m*m);
+	}
+	double std() const {
+		return sqrt(var());
+	}
+	double best() const {
+		return std::max(0.0, lapBest - lapOverhead);
+	}
+	double optimistic(double deviations=1) const {
+		return std::max(best(), mean() - std()*deviations);
+	}
+};
+
+} // namespace
+#endif // include guard