Display the CPU usage when -ddddd is used, ie the time spent on

calculations compared to the time spend on sleeping in poll().

3 files changed, 44 insertions, 10 deletions

diff --git a/usr.bin/aucat/file.c b/usr.bin/aucat/file.c
index fd76508628f..48136122884 100644
--- a/usr.bin/aucat/file.c
+++ b/usr.bin/aucat/file.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: file.c,v 1.26 2011/06/02 19:03:58 ratchov Exp $	*/
+/*	$OpenBSD: file.c,v 1.27 2011/06/27 07:22:00 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -73,6 +73,9 @@ struct timespec file_ts;
 struct filelist file_list;
 struct timo *timo_queue;
 unsigned timo_abstime;
+#ifdef DEBUG
+long long file_wtime, file_utime;
+#endif
 
 /*
  * initialise a timeout structure, arguments are callback and argument
@@ -297,6 +300,9 @@ file_poll(void)
 	struct file *f, *fnext;
 	struct aproc *p;
 	struct timespec ts;
+#ifdef DEBUG
+	struct timespec sleepts;
+#endif
 	long long delta_nsec;
 	int res;
 
@@ -347,21 +353,34 @@ file_poll(void)
 		dbg_puts("\n");
 	}
 #endif
+#ifdef DEBUG
+	clock_gettime(CLOCK_MONOTONIC, &sleepts);
+	file_utime += 1000000000LL * (sleepts.tv_sec - file_ts.tv_sec);
+	file_utime += sleepts.tv_nsec - file_ts.tv_nsec;
+#endif
 	res = poll(pfds, nfds, -1);
 	if (res < 0 && errno != EINTR)
 		err(1, "poll");
 	clock_gettime(CLOCK_MONOTONIC, &ts);
+#ifdef DEBUG
+	file_wtime += 1000000000LL * (ts.tv_sec - sleepts.tv_sec);
+	file_wtime += ts.tv_nsec - sleepts.tv_nsec;
+#endif
 	delta_nsec = 1000000000LL * (ts.tv_sec - file_ts.tv_sec);
 	delta_nsec += ts.tv_nsec - file_ts.tv_nsec;
-	if (delta_nsec > 0) {
-		file_ts = ts;
-		if (delta_nsec < 1000000000LL)
-			timo_update(delta_nsec / 1000);
-		else {
 #ifdef DEBUG
-			dbg_puts("ignored huge clock delta\n");
+	if (delta_nsec < 0) {
+		dbg_puts("file_poll: negative time interval\n");
+		dbg_panic();
+	}
+#endif
+	file_ts = ts;
+	if (delta_nsec < 1000000000LL)
+		timo_update(delta_nsec / 1000);
+	else {
+#ifdef DEBUG
+		dbg_puts("ignored huge clock delta\n");
 #endif
-		}
 	}
 	if (res <= 0)
 		return 1;
diff --git a/usr.bin/aucat/file.h b/usr.bin/aucat/file.h
index 5431025bd56..844900d5606 100644
--- a/usr.bin/aucat/file.h
+++ b/usr.bin/aucat/file.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: file.h,v 1.10 2010/07/06 20:06:35 ratchov Exp $	*/
+/*	$OpenBSD: file.h,v 1.11 2011/06/27 07:22:00 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -69,6 +69,10 @@ LIST_HEAD(filelist,file);
 
 extern struct filelist file_list;
 
+#ifdef DEBUG
+extern long long file_wtime, file_utime;
+#endif
+
 void timo_set(struct timo *, void (*)(void *), void *);
 void timo_add(struct timo *, unsigned);
 void timo_del(struct timo *);
diff --git a/usr.bin/aucat/siofile.c b/usr.bin/aucat/siofile.c
index a371521abc0..f01a9490293 100644
--- a/usr.bin/aucat/siofile.c
+++ b/usr.bin/aucat/siofile.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: siofile.c,v 1.6 2010/06/04 06:15:28 ratchov Exp $	*/
+/*	$OpenBSD: siofile.c,v 1.7 2011/06/27 07:22:00 ratchov Exp $	*/
 /*
  * Copyright (c) 2008 Alexandre Ratchov <alex@caoua.org>
  *
@@ -42,6 +42,9 @@ struct siofile {
 	unsigned rtickets, rbpf;
 	unsigned bufsz;
 	int started;
+#ifdef DEBUG
+	long long wtime, utime;
+#endif
 };
 
 void siofile_close(struct file *);
@@ -173,8 +176,14 @@ siofile_cb(void *addr, int delta)
 		file_dbg(&f->file);
 		dbg_puts(": tick, delta = ");
 		dbg_puti(delta);
+		dbg_puts(", load = ");
+		dbg_puti((file_utime - f->utime) / 1000);
+		dbg_puts(" + ");
+		dbg_puti((file_wtime - f->wtime) / 1000);
 		dbg_puts("\n");
 	}
+	f->wtime = file_wtime;
+	f->utime = file_utime;
 #endif
 	if (delta != 0) {
 		p = f->file.wproc;
@@ -308,6 +317,8 @@ siofile_start(struct file *file)
 	f->wtickets = f->bufsz * f->wbpf;
 	f->rtickets = 0;
 #ifdef DEBUG
+	f->wtime = file_wtime;
+	f->utime = file_utime;
 	if (debug_level >= 3) {
 		file_dbg(&f->file);
 		dbg_puts(": started\n");