Make logging functions a bit more flexible.

Calls to dsp_log_printf() must now be wrapped in the new dsp_log_acquire()
and dsp_log_release() functions. Allows printing lines piecemeal with
proper locking.

Author: bmc0

dsp.c

@@ -145,20 +145,18 @@ struct dsp_globals dsp_globals = {
 	"dsp",                  /* prog_name */
 };
 
-int dsp_log_printf(const char *fmt, ...)
+void dsp_log_acquire(void)
 {
-	int r;
 	pthread_mutex_lock(&log_lock);
 	if (progress_line && !progress_cleared)
 		fputs(CLEAR_PROGRESS, stderr);
-	va_list v;
-	va_start(v, fmt);
-	r = vfprintf(stderr, fmt, v);
-	va_end(v);
+}
+
+void dsp_log_release(void)
+{
 	if (progress_line && !progress_cleared)
 		fputs(progress_line, stderr);
 	pthread_mutex_unlock(&log_lock);
-	return r;
 }
 
 void ev_queue_push(enum event_type type, int val)
@@ -457,27 +455,28 @@ static void print_progress(struct codec *in, ssize_t pos, int is_paused, int for
 	static struct timespec then;
 	if (has_elapsed(&then, 0.1) || force) {
 #endif
-		double chain_delay_s, out_delay_s;
+		double in_delay_s = 0.0, chain_delay_s, out_delay_s;
 		get_delay_sec(&chain_delay_s, &out_delay_s);
 		ssize_t delay = get_delay_frames(in->fs, chain_delay_s, out_delay_s);
 		ssize_t p = (pos > delay) ? pos - delay : 0;
 		ssize_t rem = (in->frames > p) ? in->frames - p : 0;
+		if (verbose_progress)
+			in_delay_s = (double) codec_read_buf_delay(in_codec_buf) / in->fs;
+		pthread_mutex_lock(&log_lock);
 		if (progress_line == NULL)
 			progress_line = calloc(PROGRESS_MAX_LEN, sizeof(char));
 		int pl = snprintf(progress_line, PROGRESS_MAX_LEN, "%c  %.1f%%  "TIME_FMT"  -"TIME_FMT"  ",
 			(is_paused) ? '|' : '>', (in->frames != -1) ? (double) p / in->frames * 100.0 : 0,
 			TIME_FMT_ARGS(p, in->fs), TIME_FMT_ARGS(rem, in->fs));
 		if (pl < PROGRESS_MAX_LEN - 1 && verbose_progress) {
-			double in_delay_s = (double) codec_read_buf_delay(in_codec_buf) / in->fs;
 			pl += snprintf(progress_line + pl, PROGRESS_MAX_LEN - pl, "lat:%.2fms+%.2fms+%.2fms=%.2fms  ",
 				in_delay_s*1000.0, chain_delay_s*1000.0, out_delay_s*1000.0, (in_delay_s+chain_delay_s+out_delay_s)*1000.0);
 		}
 		if (pl < PROGRESS_MAX_LEN - 1 && (verbose_progress || clip_count != 0)) {
 			pl += snprintf(progress_line + pl, PROGRESS_MAX_LEN - pl, "peak:%.2fdBFS  clip:%ld  ",
 				20.0*log10(peak), clip_count);
 		}
-		pthread_mutex_lock(&log_lock);
-		fprintf(stderr, "\r%s\033[K", progress_line);
+		dsp_log_printf("\r%s\033[K", progress_line);
 		progress_cleared = 0;
 		pthread_mutex_unlock(&log_lock);
 #ifdef HAVE_CLOCK_GETTIME
@@ -782,7 +781,9 @@ int main(int argc, char *argv[])
 					case EVENT_TYPE_KEY:
 						switch (ev.val) {
 						case 'h':
+							dsp_log_acquire();
 							dsp_log_printf("\n%s\n", interactive_help);
+							dsp_log_release();
 							break;
 						case ',':
 							pos = do_seek(in_codecs.head, pos, (ssize_t) in_codecs.head->fs * -5, SEEK_CUR, is_paused);

dsp.h

@@ -30,8 +30,23 @@ enum {
 	LL_VERBOSE,
 };
 #define LOGLEVEL(l) (dsp_globals.loglevel >= (l))
-#define LOG_FMT(l, fmt, ...) do { if (LOGLEVEL(l)) dsp_log_printf("%s: " fmt "\n", dsp_globals.prog_name, __VA_ARGS__); } while (0)
-#define LOG_S(l, s) do { if (LOGLEVEL(l)) dsp_log_printf("%s: %s\n", dsp_globals.prog_name, s); } while (0)
+#define dsp_log_printf(...) fprintf(stderr, __VA_ARGS__)
+#define LOG_FMT(l, fmt, ...) \
+	do { \
+		if (LOGLEVEL(l)) { \
+			dsp_log_acquire(); \
+			dsp_log_printf("%s: " fmt "\n", dsp_globals.prog_name, __VA_ARGS__); \
+			dsp_log_release(); \
+		} \
+	} while (0)
+#define LOG_S(l, s) \
+	do { \
+		if (LOGLEVEL(l)) { \
+			dsp_log_acquire(); \
+			dsp_log_printf("%s: %s\n", dsp_globals.prog_name, s); \
+			dsp_log_release(); \
+		} \
+	} while (0)
 
 #define DEFAULT_FS       44100
 #define DEFAULT_CHANNELS     1
@@ -53,6 +68,7 @@ struct stream_info {
 };
 
 extern struct dsp_globals dsp_globals;
-extern int dsp_log_printf(const char *, ...);
+extern void dsp_log_acquire(void);
+extern void dsp_log_release(void);
 
 #endif

effect.c

@@ -235,12 +235,14 @@ static int build_effects_chain_block(int argc, const char *const *argv, struct e
 		}
 		else {
 			if (LOGLEVEL(LL_VERBOSE)) {
-				fprintf(stderr, "%s: effect:", dsp_globals.prog_name);
+				dsp_log_acquire();
+				dsp_log_printf("%s: effect:", dsp_globals.prog_name);
 				for (int j = 0; j < i - k; ++j)
-					fprintf(stderr, " %s", argv[k + j]);
-				fprintf(stderr, "; channels=%d [", stream->channels);
+					dsp_log_printf(" %s", argv[k + j]);
+				dsp_log_printf("; channels=%d [", stream->channels);
 				print_selector(channel_selector, stream->channels);
-				fprintf(stderr, "] fs=%d\n", stream->fs);
+				dsp_log_printf("] fs=%d\n", stream->fs);
+				dsp_log_release();
 			}
 			e = ei->init(ei, stream, channel_selector, dir, i - k, &argv[k]);
 			if (e == NULL) {

ladspa_dsp.c

@@ -57,15 +57,8 @@ static int n_configs = 0;
 static struct ladspa_dsp_config *configs = NULL;
 static LADSPA_Descriptor *descriptors = NULL;
 
-int dsp_log_printf(const char *fmt, ...)
-{
-	int r;
-	va_list v;
-	va_start(v, fmt);
-	r = vfprintf(stderr, fmt, v);
-	va_end(v);
-	return r;
-}
+void dsp_log_acquire(void) { /* do nothing */ }
+void dsp_log_release(void) { /* do nothing */ }
 
 static void init_config(struct ladspa_dsp_config *config, const char *file_name, const char *dir_path)
 {

matrix4.c

@@ -123,10 +123,13 @@ sample_t * matrix4_effect_run(struct effect *e, ssize_t *frames, sample_t *ibuf,
 	}
 	#ifndef LADSPA_FRONTEND
 		/* TODO: Implement a proper way for effects to show status lines. */
-		if (state->show_status)
-			fprintf(stderr, "\n%s%s: lr: %+06.2f (%+06.2f); cs: %+06.2f (%+06.2f); dir_boost: l:%05.3f r:%05.3f; adj: %05.3f; ord: %zd; diff: %zd; early: %zd\033[K\r\033[A",
+		if (state->show_status) {
+			dsp_log_acquire();
+			dsp_log_printf("\n%s%s: lr: %+06.2f (%+06.2f); cs: %+06.2f (%+06.2f); dir_boost: l:%05.3f r:%05.3f; adj: %05.3f; ord: %zd; diff: %zd; early: %zd\033[K\r\033[A",
 				e->name, (state->disable) ? " [off]" : "", TO_DEGREES(state->ax.lr), TO_DEGREES(state->ax_ev.lr), TO_DEGREES(state->ax.cs), TO_DEGREES(state->ax_ev.cs),
 				fl_boost, fr_boost, state->ev.adj, state->ev.ord_count, state->ev.diff_count, state->ev.early_count);
+			dsp_log_release();
+		}
 	#endif
 
 	*frames = oframes;
@@ -187,7 +190,11 @@ void matrix4_effect_destroy(struct effect *e)
 	free(state->bufs);
 	event_state_cleanup(&state->ev);
 	#ifndef LADSPA_FRONTEND
-		if (state->show_status) fprintf(stderr, "\033[K\n\033[K\r\033[A");
+		if (state->show_status) {
+			dsp_log_acquire();
+			dsp_log_printf("\033[K\n\033[K\r\033[A");
+			dsp_log_release();
+		}
 	#endif
 	free(state);
 }

matrix4_mb.c

@@ -390,20 +390,22 @@ sample_t * matrix4_mb_effect_run(struct effect *e, ssize_t *frames, sample_t *ib
 	#ifndef LADSPA_FRONTEND
 		/* TODO: Implement a proper way for effects to show status lines. */
 		if (state->show_status) {
+			dsp_log_acquire();
 			for (i = 0; i < N_BANDS; ++i) {
-				fprintf(stderr, "\n%s%s: band %zd: lr: %+06.2f (%+06.2f); cs: %+06.2f (%+06.2f); dir_boost: l:%05.3f r:%05.3f; adj: %05.3f; ord: %zd; diff: %zd; early: %zd\033[K\r",
+				dsp_log_printf("\n%s%s: band %zd: lr: %+06.2f (%+06.2f); cs: %+06.2f (%+06.2f); dir_boost: l:%05.3f r:%05.3f; adj: %05.3f; ord: %zd; diff: %zd; early: %zd\033[K\r",
 					e->name, (state->disable) ? " [off]" : "", i,
 					TO_DEGREES(state->band[i].ax.lr), TO_DEGREES(state->band[i].ax_ev.lr), TO_DEGREES(state->band[i].ax.cs), TO_DEGREES(state->band[i].ax_ev.cs),
 					state->band[i].fl_boost, state->band[i].fr_boost, state->band[i].ev.adj, state->band[i].ev.ord_count, state->band[i].ev.diff_count, state->band[i].ev.early_count);
 			}
-			fprintf(stderr, "\n%s%s: weighted RMS dir_boost: l:%05.3f r:%05.3f\033[K\r",
+			dsp_log_printf("\n%s%s: weighted RMS dir_boost: l:%05.3f r:%05.3f\033[K\r",
 				e->name, (state->disable) ? " [off]" : "",
 				#if DOWNSAMPLE_FACTOR > 1
 					state->fl_boost[1], state->fr_boost[1]);
 				#else
 					state->fl_boost, state->fr_boost);
 				#endif
-			fprintf(stderr, "\033[%zdA", i+1);
+			dsp_log_printf("\033[%zdA", i+1);
+			dsp_log_release();
 		}
 	#endif
 
@@ -470,8 +472,10 @@ void matrix4_mb_effect_destroy(struct effect *e)
 		event_state_cleanup(&state->band[i].ev);
 	#ifndef LADSPA_FRONTEND
 		if (state->show_status) {
-			for (int i = 0; i < N_BANDS+1; ++i) fprintf(stderr, "\033[K\n");
-			fprintf(stderr, "\033[K\r\033[%dA", N_BANDS+1);
+			dsp_log_acquire();
+			for (int i = 0; i < N_BANDS+1; ++i) dsp_log_printf("\033[K\n");
+			dsp_log_printf("\033[K\r\033[%dA", N_BANDS+1);
+			dsp_log_release();
 		}
 	#endif
 	free(state);

stats.c

@@ -58,50 +58,52 @@ void stats_effect_destroy(struct effect *e)
 {
 	ssize_t i;
 	struct stats_state *state = (struct stats_state *) e->data;
-	fprintf(stderr, "\n%-18s", "Channel");
+	dsp_log_acquire();
+	dsp_log_printf("\n%-18s", "Channel");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12zd", i);
-	fprintf(stderr, "\n%-18s", "DC offset");
+		dsp_log_printf(" %12zd", i);
+	dsp_log_printf("\n%-18s", "DC offset");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.8f", state[i].sum / state[i].samples);
-	fprintf(stderr, "\n%-18s", "Minimum");
+		dsp_log_printf(" %12.8f", state[i].sum / state[i].samples);
+	dsp_log_printf("\n%-18s", "Minimum");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.8f", state[i].min);
-	fprintf(stderr, "\n%-18s", "Maximum");
+		dsp_log_printf(" %12.8f", state[i].min);
+	dsp_log_printf("\n%-18s", "Maximum");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.8f", state[i].max);
-	fprintf(stderr, "\n%-18s", "Peak level (dBFS)");
+		dsp_log_printf(" %12.8f", state[i].max);
+	dsp_log_printf("\n%-18s", "Peak level (dBFS)");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.4f", 20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max))));
+		dsp_log_printf(" %12.4f", 20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max))));
 	if (state->ref != -HUGE_VAL) {
-		fprintf(stderr, "\n%-18s", "Peak level (dBr)");
+		dsp_log_printf("\n%-18s", "Peak level (dBr)");
 		for (i = 0; i < e->ostream.channels; ++i)
-			fprintf(stderr, " %12.4f", state->ref + (20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max)))));
+			dsp_log_printf(" %12.4f", state->ref + (20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max)))));
 	}
-	fprintf(stderr, "\n%-18s", "RMS level (dBFS)");
+	dsp_log_printf("\n%-18s", "RMS level (dBFS)");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.4f", 20 * log10(sqrt(state[i].sum_sq / state[i].samples)));
+		dsp_log_printf(" %12.4f", 20 * log10(sqrt(state[i].sum_sq / state[i].samples)));
 	if (state->ref != -HUGE_VAL) {
-		fprintf(stderr, "\n%-18s", "RMS level (dBr)");
+		dsp_log_printf("\n%-18s", "RMS level (dBr)");
 		for (i = 0; i < e->ostream.channels; ++i)
-			fprintf(stderr, " %12.4f", state->ref + (20 * log10(sqrt(state[i].sum_sq / state[i].samples))));
+			dsp_log_printf(" %12.4f", state->ref + (20 * log10(sqrt(state[i].sum_sq / state[i].samples))));
 	}
-	fprintf(stderr, "\n%-18s", "Crest factor (dB)");
+	dsp_log_printf("\n%-18s", "Crest factor (dB)");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.4f", 20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max)) / sqrt(state[i].sum_sq / state[i].samples)));
-	fprintf(stderr, "\n%-18s", "Peak count");
+		dsp_log_printf(" %12.4f", 20 * log10(MAXIMUM(fabs(state[i].min), fabs(state[i].max)) / sqrt(state[i].sum_sq / state[i].samples)));
+	dsp_log_printf("\n%-18s", "Peak count");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12zd", state[i].peak_count);
-	fprintf(stderr, "\n%-18s", "Peak sample");
+		dsp_log_printf(" %12zd", state[i].peak_count);
+	dsp_log_printf("\n%-18s", "Peak sample");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12zd", state[i].peak_frame);
-	fprintf(stderr, "\n%-18s", "Samples");
+		dsp_log_printf(" %12zd", state[i].peak_frame);
+	dsp_log_printf("\n%-18s", "Samples");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12zd", state[i].samples);
-	fprintf(stderr, "\n%-18s", "Length (s)");
+		dsp_log_printf(" %12zd", state[i].samples);
+	dsp_log_printf("\n%-18s", "Length (s)");
 	for (i = 0; i < e->ostream.channels; ++i)
-		fprintf(stderr, " %12.2f", (double) state[i].samples / e->ostream.fs);
-	fputc('\n', stderr);
+		dsp_log_printf(" %12.2f", (double) state[i].samples / e->ostream.fs);
+	dsp_log_printf("\n");
+	dsp_log_release();
 	free(state);
 }
 

util.c

@@ -178,20 +178,20 @@ void print_selector(const char *b, int n)
 		if (c && l)
 			range_start = (range_start == -1) ? i - 1 : range_start;
 		else if (!c && range_start != -1) {
-			fprintf(stderr, "%s%d%s%d", (f) ? "" : ",", range_start, (i - range_start == 2) ? "," : "-", i - 1);
+			dsp_log_printf("%s%d%s%d", (f) ? "" : ",", range_start, (i - range_start == 2) ? "," : "-", i - 1);
 			range_start = -1;
 			f = 0;
 		}
 		else if (l) {
-			fprintf(stderr, "%s%d", (f) ? "" : ",", i - 1);
+			dsp_log_printf("%s%d", (f) ? "" : ",", i - 1);
 			f = 0;
 		}
 		l = c;
 	}
 	if (range_start != -1)
-		fprintf(stderr, "%s%d%s%d", (f) ? "" : ",", range_start, (i - range_start == 2) ? "," : "-", i - 1);
+		dsp_log_printf("%s%d%s%d", (f) ? "" : ",", range_start, (i - range_start == 2) ? "," : "-", i - 1);
 	else if (l)
-		fprintf(stderr, "%s%d", (f) ? "" : ",", n - 1);
+		dsp_log_printf("%s%d", (f) ? "" : ",", n - 1);
 }
 
 int num_bits_set(const char *b, int n)