alsa-utils/0028-alsaloop-added-xrun-profiling-support-U-xrun-added-S.patch

From 1a35bdf7c6c3a4727662d093963141dddc376072 Mon Sep 17 00:00:00 2001
From: Jaroslav Kysela <perex@perex.cz>
Date: Wed, 13 Oct 2010 23:39:36 +0200
Subject: [PATCH 28/38] alsaloop: added xrun profiling support (-U,--xrun), added SIGUSR1 state dump

Signed-off-by: Jaroslav Kysela <perex@perex.cz>
---
 alsaloop/alsaloop.c |   89 ++++++++++++++++++++++---
 alsaloop/alsaloop.h |   20 +++++-
 alsaloop/pcmjob.c   |  180 ++++++++++++++++++++++++++++++++++++++++++++-------
 alsaloop/test.sh    |   26 +++++---
 4 files changed, 270 insertions(+), 45 deletions(-)

diff --git a/alsaloop/alsaloop.c b/alsaloop/alsaloop.c
index 1b3505e..561fdd7 100644
--- a/alsaloop/alsaloop.c
+++ b/alsaloop/alsaloop.c
@@ -31,6 +31,7 @@
 #include <math.h>
 #include <pthread.h>
 #include <syslog.h>
+#include <sys/signal.h>
 #include "alsaloop.h"
 
 struct loopback_thread {
@@ -42,6 +43,7 @@ struct loopback_thread {
 	snd_output_t *output;
 };
 
+int quit = 0;
 int verbose = 0;
 int workarounds = 0;
 int daemonize = 0;
@@ -50,6 +52,10 @@ struct loopback **loopbacks = NULL;
 int loopbacks_count = 0;
 char **my_argv = NULL;
 int my_argc = 0;
+struct loopback_thread *threads;
+int threads_count = 0;
+pthread_t main_job;
+int arg_default_xrun = 0;
 
 static void my_exit(struct loopback_thread *thread, int exitcode)
 {
@@ -118,6 +124,7 @@ static int create_loopback(struct loopback **_handle,
 	handle->loop_time = ~0UL;
 	handle->loop_limit = ~0ULL;
 	handle->output = output;
+	handle->state = output;
 #ifdef USE_SAMPLERATE
 	handle->src_enable = 1;
 	handle->src_converter_type = SRC_SINC_BEST_QUALITY;
@@ -185,6 +192,7 @@ void help(void)
 "-e,--effect    apply an effect (bandpass filter sweep)\n"
 "-v,--verbose   verbose mode (more -v means more verbose)\n"
 "-w,--workaround use workaround (serialopen)\n"
+"-U,--xrun      xrun profiling\n"
 );
 	printf("\nRecognized sample formats are:");
 	for (k = 0; k < SND_PCM_FORMAT_LAST; ++k) {
@@ -326,7 +334,8 @@ static int add_oss_mixers(struct loopback *loop,
 
 static int parse_config_file(const char *file, snd_output_t *output);
 
-static int parse_config(int argc, char *argv[], snd_output_t *output)
+static int parse_config(int argc, char *argv[], snd_output_t *output,
+			int cmdline)
 {
 	struct option long_option[] =
 	{
@@ -356,6 +365,7 @@ static int parse_config(int argc, char *argv[], snd_output_t *output)
 		{"mixer", 1, NULL, 'm'},
 		{"ossmixer", 1, NULL, 'O'},
 		{"workaround", 1, NULL, 'w'},
+		{"xrun", 0, NULL, 'U'},
 		{NULL, 0, NULL, 0},
 	};
 	int err, morehelp;
@@ -384,12 +394,13 @@ static int parse_config(int argc, char *argv[], snd_output_t *output)
 	int arg_mixers_count = 0;
 	char *arg_ossmixers[MAX_MIXERS];
 	int arg_ossmixers_count = 0;
+	int arg_xrun = arg_default_xrun;
 
 	morehelp = 0;
 	while (1) {
 		int c;
 		if ((c = getopt_long(argc, argv,
-				"hdg:P:C:X:Y:l:t:F:f:c:r:s:benvA:S:a:m:T:O:w:",
+				"hdg:P:C:X:Y:l:t:F:f:c:r:s:benvA:S:a:m:T:O:w:U",
 				long_option, NULL)) < 0)
 			break;
 		switch (c) {
@@ -533,6 +544,11 @@ static int parse_config(int argc, char *argv[], snd_output_t *output)
 			if (strcasecmp(optarg, "serialopen") == 0)
 				workarounds |= WORKAROUND_SERIALOPEN;
 			break;
+		case 'U':
+			arg_xrun = 1;
+			if (cmdline)
+				arg_default_xrun = 1;
+			break;
 		}
 	}
 
@@ -570,6 +586,7 @@ static int parse_config(int argc, char *argv[], snd_output_t *output)
 		loop->sync = arg_sync;
 		loop->slave = arg_slave;
 		loop->thread = arg_thread;
+		loop->xrun = arg_xrun;
 		err = add_mixers(loop, arg_mixers, arg_mixers_count);
 		if (err < 0) {
 			logit(LOG_CRIT, "Unable to add mixer controls.\n");
@@ -656,7 +673,7 @@ static int parse_config_file(const char *file, snd_output_t *output)
 		optind = opterr = 1;
 		optopt = '?';
 
-		err = parse_config(argc, argv, output);
+		err = parse_config(argc, argv, output, 0);
 	      __next:
 		if (err < 0)
 			break;
@@ -698,7 +715,7 @@ static void thread_job1(void *_data)
 		logit(LOG_CRIT, "Poll FDs allocation failed.\n");
 		my_exit(thread, EXIT_FAILURE);
 	}
-	while (1) {
+	while (!quit) {
 		struct timeval tv1, tv2;
 		for (i = j = 0; i < thread->loopbacks_count; i++) {
 			err = pcmjob_pollfds_init(thread->loopbacks[i], &pfds[j]);
@@ -711,12 +728,16 @@ static void thread_job1(void *_data)
 		if (verbose > 10)
 			gettimeofday(&tv1, NULL);
 		err = poll(pfds, j, -1);
+		if (err < 0)
+			err = -errno;
 		if (verbose > 10) {
 			gettimeofday(&tv2, NULL);
 			snd_output_printf(output, "pool took %lius\n", timediff(tv2, tv1));
 		}
 		if (err < 0) {
-			logit(LOG_CRIT, "Poll failed.\n");
+			if (err == -EINTR || err == -ERESTART)
+				continue;
+			logit(LOG_CRIT, "Poll failed: %s\n", strerror(-err));
 			my_exit(thread, EXIT_FAILURE);
 		}
 		for (i = j = 0; i < thread->loopbacks_count; i++) {
@@ -745,18 +766,58 @@ static void thread_job(struct loopback_thread *thread)
 					      (void *) thread);
 }
 
+static void send_to_all(int sig)
+{
+	struct loopback_thread *thread;
+	int i;
+
+	for (i = 0; i < threads_count; i++) {
+		thread = &threads[i];
+		if (thread->threaded)
+			pthread_kill(thread->thread, sig);
+	}
+}
+
+static void signal_handler(int sig)
+{
+	quit = 1;
+	send_to_all(SIGUSR2);
+}
+
+static void signal_handler_state(int sig)
+{
+	pthread_t self = pthread_self();
+	struct loopback_thread *thread;
+	int i, j;
+
+	if (pthread_equal(main_job, self))
+		send_to_all(SIGUSR1);
+	for (i = 0; i < threads_count; i++) {
+		thread = &threads[i];
+		if (thread->thread == self) {
+			for (j = 0; j < thread->loopbacks_count; j++)
+				pcmjob_state(thread->loopbacks[j]);
+		}
+	}
+	signal(sig, signal_handler_state);
+}
+
+static void signal_handler_ignore(int sig)
+{
+	signal(sig, signal_handler_ignore);
+}
+
 int main(int argc, char *argv[])
 {
 	snd_output_t *output;
 	int i, j, k, l, err;
-	struct loopback_thread *threads;
 
 	err = snd_output_stdio_attach(&output, stdout, 0);
 	if (err < 0) {
 		logit(LOG_CRIT, "Output failed: %s\n", snd_strerror(err));
 		exit(EXIT_FAILURE);
 	}
-	err = parse_config(argc, argv, output);
+	err = parse_config(argc, argv, output, 1);
 	if (err < 0) {
 		logit(LOG_CRIT, "Unable to parse arguments or configuration...\n");
 		exit(EXIT_FAILURE);
@@ -825,12 +886,20 @@ int main(int argc, char *argv[])
 			if (loopbacks[i]->thread == k)
 				threads[k].loopbacks[l++] = loopbacks[i];
 	}
-
-	for (k = 0; k < j; k++)
+	threads_count = j;
+	main_job = pthread_self();
+ 
+	signal(SIGINT, signal_handler);
+	signal(SIGTERM, signal_handler);
+	signal(SIGABRT, signal_handler);
+	signal(SIGUSR1, signal_handler_state);
+	signal(SIGUSR2, signal_handler_ignore);
+
+	for (k = 0; k < threads_count; k++)
 		thread_job(&threads[k]);
 
 	if (j > 1) {
-		for (k = 0; k < j; k++)
+		for (k = 0; k < threads_count; k++)
 			pthread_join(threads[k].thread, NULL);
 	}
 
diff --git a/alsaloop/alsaloop.h b/alsaloop/alsaloop.h
index 7516807..839fc6d 100644
--- a/alsaloop/alsaloop.h
+++ b/alsaloop/alsaloop.h
@@ -95,6 +95,7 @@ struct loopback_handle {
 	unsigned int channels;
 	unsigned int buffer_size;
 	unsigned int period_size;
+	snd_pcm_uframes_t avail_min;
 	unsigned int buffer_size_req;
 	unsigned int period_size_req;
 	unsigned int frame_size;
@@ -130,12 +131,13 @@ struct loopback {
 	char *id;
 	struct loopback_handle *capt;
 	struct loopback_handle *play;
-	snd_pcm_uframes_t latency;	/* final latency */
-	unsigned int latency_req;	/* in frames / 2 */
-	unsigned int latency_reqtime;	/* in us / 2 */
+	snd_pcm_uframes_t latency;	/* final latency in frames */
+	unsigned int latency_req;	/* in frames */
+	unsigned int latency_reqtime;	/* in us */
 	unsigned long loop_time;	/* ~0 = unlimited (in seconds) */
 	unsigned long long loop_limit;	/* ~0 = unlimited (in frames) */
 	snd_output_t *output;
+	snd_output_t *state;
 	int pollfd_count;
 	int active_pollfd_count;
 	unsigned int linked:1;		/* linked streams */
@@ -153,6 +155,17 @@ struct loopback {
 	unsigned int total_queued_count;
 	snd_timestamp_t tstamp_start;
 	snd_timestamp_t tstamp_end;
+	/* xrun profiling */
+	unsigned int xrun:1;		/* xrun profiling */
+	snd_timestamp_t xrun_last_update;
+	snd_timestamp_t xrun_last_wake0;
+	snd_timestamp_t xrun_last_wake;
+	snd_timestamp_t xrun_last_check0;
+	snd_timestamp_t xrun_last_check;
+	snd_pcm_sframes_t xrun_last_pdelay;
+	snd_pcm_sframes_t xrun_last_cdelay;
+	long xrun_max_proctime;
+	double xrun_max_missing;
 	/* control mixer */
 	struct loopback_mixer *controls;
 	struct loopback_ossmixer *oss_controls;
@@ -190,6 +203,7 @@ int pcmjob_start(struct loopback *loop);
 int pcmjob_stop(struct loopback *loop);
 int pcmjob_pollfds_init(struct loopback *loop, struct pollfd *fds);
 int pcmjob_pollfds_handle(struct loopback *loop, struct pollfd *fds);
+void pcmjob_state(struct loopback *loop);
 
 int control_parse_id(const char *str, snd_ctl_elem_id_t *id);
 int control_id_match(snd_ctl_elem_id_t *id1, snd_ctl_elem_id_t *id2);
diff --git a/alsaloop/pcmjob.c b/alsaloop/pcmjob.c
index 9d1bb01..0f1a853 100644
--- a/alsaloop/pcmjob.c
+++ b/alsaloop/pcmjob.c
@@ -34,6 +34,8 @@
 #include <pthread.h>
 #include "alsaloop.h"
 
+#define XRUN_PROFILE_UNKNOWN (-10000000)
+
 static int set_rate_shift(struct loopback_handle *lhandle, double pitch);
 static int get_rate(struct loopback_handle *lhandle);
 
@@ -50,6 +52,7 @@ static const char *sync_types[] = {
 
 #define SRCTYPE(v) [SRC_##v] = "SRC_" #v
 
+#ifdef USE_SAMPLERATE
 static const char *src_types[] = {
 	SRCTYPE(SINC_BEST_QUALITY),
 	SRCTYPE(SINC_MEDIUM_QUALITY),
@@ -57,6 +60,7 @@ static const char *src_types[] = {
 	SRCTYPE(ZERO_ORDER_HOLD),
 	SRCTYPE(LINEAR)
 };
+#endif
 
 static pthread_mutex_t pcm_open_mutex =
                                 PTHREAD_RECURSIVE_MUTEX_INITIALIZER_NP;
@@ -78,6 +82,13 @@ static inline snd_pcm_uframes_t get_whole_latency(struct loopback *loop)
 	return loop->latency;
 }
 
+static inline unsigned long long
+			frames_to_time(struct loopback_handle *lhandle,
+				       snd_pcm_uframes_t frames)
+{
+	return (frames * 1000000ULL) / lhandle->rate;
+}
+
 static inline snd_pcm_uframes_t time_to_frames(struct loopback_handle *lhandle,
 					       unsigned long long time)
 {
@@ -125,7 +136,11 @@ static int setparams_stream(struct loopback_handle *lhandle,
 	rrate = 0;
 	snd_pcm_hw_params_get_rate(params, &rrate, 0);
 	lhandle->rate = rrate;
-	if (!lhandle->loopback->src_enable && (int)rrate != lhandle->rate) {
+	if (
+#ifdef USE_SAMPLERATE
+	    !lhandle->loopback->src_enable &&
+#endif
+	    (int)rrate != lhandle->rate) {
 		logit(LOG_CRIT, "Rate does not match (requested %iHz, got %iHz, resample %i)\n", lhandle->rate, rrate, lhandle->resample);
 		return -EINVAL;
 	}
@@ -247,6 +262,7 @@ static int setparams_set(struct loopback_handle *lhandle,
 		logit(LOG_CRIT, "Unable to set avail min for %s: %s\n", lhandle->id, snd_strerror(err));
 		return err;
 	}
+	snd_pcm_sw_params_get_avail_min(swparams, &lhandle->avail_min);
 	err = snd_pcm_sw_params(handle, swparams);
 	if (err < 0) {
 		logit(LOG_CRIT, "Unable to set sw params for %s: %s\n", lhandle->id, snd_strerror(err));
@@ -316,11 +332,12 @@ static int setparams(struct loopback *loop, snd_pcm_uframes_t bufsize)
 	return 0;
 }
 
-static void showlatency(struct loopback *loop, size_t latency, unsigned int rate)
+static void showlatency(snd_output_t *out, size_t latency, unsigned int rate,
+			char *prefix)
 {
 	double d;
 	d = (double)latency / (double)rate;
-	snd_output_printf(loop->output, "Latency %li frames, %.3fus, %.6fms (%.4fHz)\n", (long)latency, d * 1000000, d * 1000, (double)1 / d);
+	snd_output_printf(out, "%s %li frames, %.3fus, %.6fms (%.4fHz)\n", prefix, (long)latency, d * 1000000, d * 1000, (double)1 / d);
 }
 
 static long timediff(snd_timestamp_t t1, snd_timestamp_t t2)
@@ -328,11 +345,11 @@ static long timediff(snd_timestamp_t t1, snd_timestamp_t t2)
 	signed long l;
 
 	t1.tv_sec -= t2.tv_sec;
-	l = (signed long) t1.tv_usec - (signed long) t2.tv_usec;
-	if (l < 0) {
+	if (t1.tv_usec < t2.tv_usec) {
+		l = ((t1.tv_usec + 1000000) - t2.tv_usec) % 1000000;
 		t1.tv_sec--;
-		l = -l;
-		l %= 1000000;
+	} else {
+		l = t1.tv_usec - t2.tv_usec;
 	}
 	return (t1.tv_sec * 1000000) + l;
 }
@@ -346,6 +363,56 @@ static int getcurtimestamp(snd_timestamp_t *ts)
 	return 0;
 }
 
+static void xrun_profile0(struct loopback *loop)
+{
+	snd_pcm_sframes_t pdelay, cdelay;
+
+	if (snd_pcm_delay(loop->play->handle, &pdelay) >= 0 &&
+	    snd_pcm_delay(loop->capt->handle, &cdelay) >= 0) {
+		getcurtimestamp(&loop->xrun_last_update);
+		loop->xrun_last_pdelay = pdelay;
+		loop->xrun_last_cdelay = cdelay;
+	}
+}
+
+static inline void xrun_profile(struct loopback *loop)
+{
+	if (loop->xrun)
+		xrun_profile0(loop);
+}
+
+static void xrun_stats0(struct loopback *loop)
+{
+	snd_timestamp_t t;
+	double expected, last, wake, check, queued = -1, proc, missing;
+
+	expected = ((double)loop->latency /
+				(double)loop->play->rate) * 1000;
+	getcurtimestamp(&t);
+	last = (double)timediff(t, loop->xrun_last_update) / 1000;
+	wake = (double)timediff(t, loop->xrun_last_wake) / 1000;
+	check = (double)timediff(t, loop->xrun_last_check) / 1000;
+	if (loop->xrun_last_pdelay != XRUN_PROFILE_UNKNOWN)
+		queued = (((double)loop->xrun_last_pdelay *
+						loop->play->pitch) /
+				(double)loop->play->rate) * 1000;
+	proc = (double)loop->xrun_max_proctime / 1000;
+	missing = last - queued;
+	if (loop->xrun_max_missing < missing)
+		loop->xrun_max_missing = missing;
+	loop->xrun_max_proctime = 0;
+	getcurtimestamp(&t);
+	logit(LOG_INFO, "  last write before %.4fms, queued %.4fms -> missing %.4fms\n", last, queued, missing);
+	logit(LOG_INFO, "  expected %.4fms, processing %.4fms, max missing %.4fms\n", expected, proc, loop->xrun_max_missing);
+	logit(LOG_INFO, "  last wake before %.4fms, last check before %.4fms\n", wake, check);
+}
+
+static inline void xrun_stats(struct loopback *loop)
+{
+	if (loop->xrun)
+		xrun_stats0(loop);
+}
+
 static inline snd_pcm_uframes_t buf_avail(struct loopback_handle *lhandle)
 {
 	return lhandle->buf_size - lhandle->buf_count;
@@ -495,11 +562,13 @@ static int xrun(struct loopback_handle *lhandle)
 
 	if (lhandle == lhandle->loopback->play) {
 		logit(LOG_DEBUG, "underrun for %s\n", lhandle->id);
+		xrun_stats(lhandle->loopback);
 		if ((err = snd_pcm_prepare(lhandle->handle)) < 0)
 			return err;
 		lhandle->xrun_pending = 1;
 	} else {
 		logit(LOG_DEBUG, "overrun for %s\n", lhandle->id);
+		xrun_stats(lhandle->loopback);
 		if ((err = snd_pcm_prepare(lhandle->handle)) < 0)
 			return err;
 		lhandle->xrun_pending = 1;
@@ -622,6 +691,7 @@ static int writeit(struct loopback_handle *lhandle)
 			fwrite(lhandle->buf + lhandle->buf_pos * lhandle->frame_size,
 			       r, lhandle->frame_size, lhandle->loopback->pfile);
 #endif
+		xrun_profile(lhandle->loopback);
 		res += r;
 		lhandle->counter += r;
 		lhandle->buf_count -= r;
@@ -735,9 +805,17 @@ static int xrun_sync(struct loopback *loop)
 	loop->pitch_diff = loop->pitch_diff_min = loop->pitch_diff_max = 0;
 	if (verbose > 6) {
 		snd_output_printf(loop->output,
-			"sync: cdelay=%li(%li), pdelay=%li(%li), fill=%li (delay=%li), src_out=%li\n",
+			"sync: cdelay=%li(%li), pdelay=%li(%li), fill=%li (delay=%li)"
+#ifdef USE_SAMPLERATE
+			", src_out=%li"
+#endif
+			"\n",
 			(long)cdelay, (long)cdelay1, (long)pdelay, (long)pdelay1,
-			(long)fill, (long)delay1, (long)loop->src_out_frames);
+			(long)fill, (long)delay1
+#ifdef USE_SAMPLERATE
+			, (long)loop->src_out_frames
+#endif
+			);
 		snd_output_printf(loop->output,
 			"sync: cbufcount=%li, pbufcount=%li\n",
 			(long)capt->buf_count, (long)play->buf_count);
@@ -1112,10 +1190,7 @@ static int init_handle(struct loopback_handle *lhandle, int alloc)
 	lhandle->frame_size = (snd_pcm_format_width(lhandle->format) / 8) *
 							   lhandle->channels;
 	lhandle->sync_point = lhandle->rate * 15;	/* every 15 seconds */
-	lat = lhandle->loopback->latency_req;
-	if (lat == 0)
-		lat = time_to_frames(lhandle,
-				     lhandle->loopback->latency_reqtime);
+	lat = lhandle->loopback->latency;
 	if (lhandle->buffer_size > lat)
 		lat = lhandle->buffer_size;
 	lhandle->buf_size = lat * 2;
@@ -1152,8 +1227,6 @@ int pcmjob_init(struct loopback *loop)
 #ifdef USE_SAMPLERATE
 	if (loop->sync == SYNC_TYPE_AUTO && loop->src_enable)
 		loop->sync = SYNC_TYPE_SAMPLERATE;
-#else
-	loop->src_enable = 0;
 #endif
 	if (loop->sync == SYNC_TYPE_AUTO)
 		loop->sync = SYNC_TYPE_SIMPLE;
@@ -1270,14 +1343,16 @@ int pcmjob_start(struct loopback *loop)
 	}
 	loop->reinit = 0;
 	loop->use_samplerate = 0;
-	loop->latency = loop->latency_req;
-	if (loop->latency == 0)
-		loop->latency = time_to_frames(loop->play,
-					       loop->latency_reqtime);
+	if (loop->latency_req) {
+		loop->latency_reqtime = frames_to_time(loop->play,
+						       loop->latency_req);
+		loop->latency_req = 0;
+	}
+	loop->latency = time_to_frames(loop->play, loop->latency_reqtime);
 	if ((err = setparams(loop, loop->latency/2)) < 0)
 		goto __error;
 	if (verbose)
-		showlatency(loop, loop->latency, loop->play->rate_req);
+		showlatency(loop->output, loop->latency, loop->play->rate, "Latency");
 	if (loop->play->access == loop->capt->access &&
 	    loop->play->format == loop->capt->format &&
 	    loop->play->rate == loop->capt->rate &&
@@ -1402,6 +1477,12 @@ int pcmjob_start(struct loopback *loop)
 		goto __error;
 	}
 	loop->running = 1;
+	if (loop->xrun) {
+		getcurtimestamp(&loop->xrun_last_update);
+		loop->xrun_last_pdelay = XRUN_PROFILE_UNKNOWN;
+		loop->xrun_last_cdelay = XRUN_PROFILE_UNKNOWN;
+		loop->xrun_max_proctime = 0;
+	}
 	if ((err = snd_pcm_start(loop->capt->handle)) < 0) {
 		logit(LOG_CRIT, "pcm start %s error: %s\n", loop->capt->id, snd_strerror(err));
 		goto __error;
@@ -1568,7 +1649,7 @@ int pcmjob_pollfds_handle(struct loopback *loop, struct pollfd *fds)
 
 	if (verbose > 11)
 		snd_output_printf(loop->output, "%s: pollfds handle\n", loop->id);
-	if (verbose > 13)
+	if (verbose > 13 || loop->xrun)
 		getcurtimestamp(&loop->tstamp_start);
 	if (verbose > 12) {
 		snd_pcm_sframes_t pdelay, cdelay;
@@ -1595,6 +1676,14 @@ int pcmjob_pollfds_handle(struct loopback *loop, struct pollfd *fds)
 		if (err < 0)
 			return err;
 		idx += capt->pollfd_count;
+		if (loop->xrun) {
+			if (prevents || crevents) {
+				loop->xrun_last_wake = loop->xrun_last_wake0;
+				loop->xrun_last_wake0 = loop->tstamp_start;
+			}
+			loop->xrun_last_check = loop->xrun_last_check0;
+			loop->xrun_last_check0 = loop->tstamp_start;
+		}
 	} else {
 		prevents = crevents = 0;
 	}
@@ -1717,9 +1806,54 @@ int pcmjob_pollfds_handle(struct loopback *loop, struct pollfd *fds)
 			snd_output_printf(loop->output, "%s: end delay %li / %li / %li\n", capt->id, cdelay, capt->buf_size, capt->buf_count);
 	}
       __pcm_end:
-	if (verbose > 13) {
+	if (verbose > 13 || loop->xrun) {
+		long diff;
 		getcurtimestamp(&loop->tstamp_end);
-		snd_output_printf(loop->output, "%s: processing time %lius\n", capt->id, timediff(loop->tstamp_end, loop->tstamp_start));
+		diff = timediff(loop->tstamp_end, loop->tstamp_start);
+		if (verbose > 13)
+			snd_output_printf(loop->output, "%s: processing time %lius\n", loop->id, diff);
+		if (loop->xrun && loop->xrun_max_proctime < diff)
+			loop->xrun_max_proctime = diff;
 	}
 	return 0;
 }
+
+#define OUT(args...) \
+	snd_output_printf(loop->state, ##args)
+
+static pthread_mutex_t state_mutex = PTHREAD_MUTEX_INITIALIZER;
+
+static void show_handle(struct loopback_handle *lhandle, const char *id)
+{
+	struct loopback *loop = lhandle->loopback;
+
+	OUT("  %s: %s:\n", id, lhandle->id);
+	OUT("    device = '%s', ctldev '%s'\n", lhandle->device, lhandle->ctldev);
+	OUT("    card_number = %i\n", lhandle->card_number);
+	if (!loop->running)
+		return;
+	OUT("    access = %s, format = %s, rate = %u, channels = %u\n", snd_pcm_access_name(lhandle->access), snd_pcm_format_name(lhandle->format), lhandle->rate, lhandle->channels);
+	OUT("    buffer_size = %u, period_size = %u, avail_min = %li\n", lhandle->buffer_size, lhandle->period_size, lhandle->avail_min);
+	OUT("    xrun_pending = %i\n", lhandle->xrun_pending);
+	OUT("    buf_size = %li, buf_pos = %li, buf_count = %li, buf_over = %li\n", lhandle->buf_size, lhandle->buf_pos, lhandle->buf_count, lhandle->buf_over);
+	OUT("    pitch = %.8f\n", lhandle->pitch);
+}
+
+void pcmjob_state(struct loopback *loop)
+{
+	pthread_t self = pthread_self();
+	pthread_mutex_lock(&state_mutex);
+	OUT("State dump for thread %p job %i: %s:\n", (void *)self, loop->thread, loop->id);
+	OUT("  running = %i\n", loop->running);
+	OUT("  sync = %i\n", loop->sync);
+	OUT("  slave = %i\n", loop->slave);
+	if (!loop->running)
+		goto __skip;
+	OUT("  pollfd_count = %i\n", loop->pollfd_count);
+	OUT("  pitch = %.8f, delta = %.8f, diff = %li, min = %li, max = %li\n", loop->pitch, loop->pitch_delta, loop->pitch_diff, loop->pitch_diff_min, loop->pitch_diff_max);
+	OUT("  use_samplerate = %i\n", loop->use_samplerate);
+      __skip:
+	show_handle(loop->play, "playback");
+	show_handle(loop->capt, "capture");
+	pthread_mutex_unlock(&state_mutex);
+}
diff --git a/alsaloop/test.sh b/alsaloop/test.sh
index e3d81b1..ff9aa4e 100755
--- a/alsaloop/test.sh
+++ b/alsaloop/test.sh
@@ -35,20 +35,19 @@ EOF
 test3() {
   echo "TEST3"
 cat > $CFGFILE <<EOF
--C hw:1,0,0 -P plug:dmix:0 --tlatency 50000 --thread 0 \
+-C hw:1,0,0 -P plug:dmix:0 --tlatency 30000 --thread 0 \
     --mixer "name='Master Playback Volume'@name='Master Playback Volume'" \
     --mixer "name='Master Playback Switch'@name='Master Playback Switch'" \
     --mixer "name='PCM Playback Volume'" \
     --ossmixer "name=Master@VOLUME"
--C hw:1,0,1 -P plug:dmix:0 --tlatency 50000 --thread 1
--C hw:1,0,2 -P plug:dmix:0 --tlatency 50000 --thread 2
--C hw:1,0,3 -P plug:dmix:0 --tlatency 50000 --thread 3
--C hw:1,0,4 -P plug:dmix:0 --tlatency 50000 --thread 4
--C hw:1,0,5 -P plug:dmix:0 --tlatency 50000 --thread 5
--C hw:1,0,6 -P plug:dmix:0 --tlatency 50000 --thread 6
--C hw:1,0,7 -P plug:dmix:0 --tlatency 50000 --thread 7
+-C hw:1,0,1 -P plug:dmix:0 --tlatency 30000 --thread 1
+-C hw:1,0,2 -P plug:dmix:0 --tlatency 30000 --thread 2
+-C hw:1,0,3 -P plug:dmix:0 --tlatency 30000 --thread 3
+-C hw:1,0,4 -P plug:dmix:0 --tlatency 30000 --thread 4
+-C hw:1,0,5 -P plug:dmix:0 --tlatency 30000 --thread 5
+-C hw:1,0,6 -P plug:dmix:0 --tlatency 30000 --thread 6
+-C hw:1,0,7 -P plug:dmix:0 --tlatency 30000 --thread 7
 EOF
-  LD_PRELOAD="/home/perex/alsa/alsa-lib/src/.libs/libasound.so" \
   $DBG ./alsaloop --config $CFGFILE $ARGS
 }
 
@@ -75,11 +74,20 @@ EOF
   $DBG ./alsaloop --config $CFGFILE $ARGS
 }
 
+sigusr1() {
+	pid=$(ps ax | grep alsaloop | grep -v grep | colrm 7 255)
+	if test -n "$pid"; then
+		echo "Killing alsaloop $pid..."
+		kill -SIGUSR1 $pid
+	fi
+}
+
 case "$1" in
 test1) shift; ARGS="$@"; test1 ;;
 test2) shift; ARGS="$@"; test2 ;;
 test3) shift; ARGS="$@"; test3 ;;
 test4) shift; ARGS="$@"; test4 ;;
 test5) shift; ARGS="$@"; test5 ;;
+usr|sig*) sigusr1 ;;
 *) ARGS="$@"; test1 ;;
 esac
-- 
1.7.3.1