Tick Latency Tracing

5 files changed, 57 insertions, 17 deletions

diff --git a/include/util/status.h b/include/util/status.h
index f6966dd..3314055 100644
--- a/include/util/status.h
+++ b/include/util/status.h
@@ -1,6 +1,7 @@
 #ifndef UTIL_STATUS_H
 #define UTIL_STATUS_H
 
+void time_status(void);
 void status(void);
 
 #endif
diff --git a/src/cpu/irq.c b/src/cpu/irq.c
index 4708293..b5f3e03 100644
--- a/src/cpu/irq.c
+++ b/src/cpu/irq.c
@@ -83,8 +83,6 @@ unsigned long c_fiq_handler(void)
 		counter++;
 		if (counter % 0x6000 == 0)
 			counter = 0;
-		if (counter % 0x08 == 0)
-			status();
 		if (counter % 0x40 == 0)
 			return 1;
 		return 0;
diff --git a/src/sys/core.c b/src/sys/core.c
index 6421c71..e94c86b 100644
--- a/src/sys/core.c
+++ b/src/sys/core.c
@@ -11,6 +11,7 @@
 #include <sys/power.h>
 #include <sys/schedule.h>
 #include <util/mutex.h>
+#include <util/status.h>
 #include <util/time.h>
 
 // Initialize IRQs
diff --git a/src/tests/test.c b/src/tests/test.c
index 89979f9..d59be9f 100644
--- a/src/tests/test.c
+++ b/src/tests/test.c
@@ -4,8 +4,9 @@
 #include <lib/kmem.h>
 #include <sys/core.h>
 #include <sys/schedule.h>
-#include <util/mutex.h>
 #include <util/lock.h>
+#include <util/mutex.h>
+#include <util/status.h>
 
 extern void atest(void);
 void qualitative_tests(void);
@@ -154,6 +155,39 @@ void test_entry(void)
 	draw_u10(tidx+len+1, y+5, dt%TEST_COUNT);
 	tidx += TEST_RESULT_WIDTH;
 
+	// Test 7: Tick Latency
+#define DELAY_TIME 512000
+	unsigned long center = 0;
+	sys0_64(SYS_TIME, &ti);
+	delay(DELAY_TIME);
+	sys0_64(SYS_TIME, &tf);
+	center = (tf - ti - 10);
+	if (10 > (tf-ti))
+		center = 0;
+	dt = 0;
+	unsigned long j = 0;
+	for(int i = 0; i < TEST_COUNT; i++) {
+		sys0_64(SYS_TIME, &ti);
+		delay(DELAY_TIME);
+		sys0_64(SYS_TIME, &tf);
+		dt += tf - ti;
+		if ((tf-ti-center) < TEST_BIN_COUNT)
+			bins[(tf-ti)-center]++;
+		else
+			j++;
+	}
+	for (int i = 0; i < TEST_BIN_COUNT; i++) {
+		draw_hex32(tidx, y+6+i, i);
+		draw_string(tidx+9, y+6+i, TEST_STR_CLR);
+		draw_u10(tidx+9, y+6+i, bins[i]);
+		bins[i] = 0;
+	}
+	draw_hex32(tidx, y+4, j);
+	draw_string(tidx, y+5, "       ");
+	len = draw_u10(tidx, y+5, dt/TEST_COUNT);
+	draw_u10(tidx+len+1, y+5, dt%TEST_COUNT);
+	tidx += TEST_RESULT_WIDTH;
+
 	add_thread(qualitative_tests, 0, 4);
 }
 
@@ -312,4 +346,5 @@ void qualitative_tests(void)
 	add_thread(deadlock_test1, 0, 5);
 	add_thread(semaphore_test1, 0, 6);
 	add_thread(semaphore_test2, 0, 7);
+	add_thread(time_status, 0, 8);
 }
diff --git a/src/util/status.c b/src/util/status.c
index cfadd19..456e89d 100644
--- a/src/util/status.c
+++ b/src/util/status.c
@@ -58,6 +58,24 @@ void output_irq_status(void)
 	}
 }
 
+void time_status(void)
+{
+	// Report Sys Timer Stataus
+	unsigned long systime;
+	draw_string(0, 8, "Sys Timer Status");
+	systime = *(volatile unsigned long*)SYS_TIMER_CS;
+	draw_hex32(17, 8, systime);
+	draw_string(17+8, 8, ":");
+	unsigned long long tval = get_time();
+	draw_hex32(17+8, 8, (tval >> 32));
+	draw_hex32(17+8+8, 8, tval);
+	systime = *(volatile unsigned long*)SYS_TIMER_C0;
+	draw_hex32(19+14+8+1, 8, systime);
+	draw_string(19+14+9+8, 8, "|");
+	draw_string(19+14+18, 8, "           ");
+	draw_u10(19+14+18, 8, ((unsigned long)tval)/1000000);
+}
+
 void status(void)
 {
 	// OS Info
@@ -111,18 +129,5 @@ void status(void)
 	draw_string(0, 7, "Status Updated by Core #");
 	draw_hex32(24, 7, coren);
 
-	// Report Sys Timer Stataus
-	unsigned long systime;
-	draw_string(0, 8, "Sys Timer Status");
-	systime = *(volatile unsigned long*)SYS_TIMER_CS;
-	draw_hex32(17, 8, systime);
-	draw_string(17+8, 8, ":");
-	unsigned long long tval = get_time();
-	draw_hex32(17+8, 8, (tval >> 32));
-	draw_hex32(17+8+8, 8, tval);
-	systime = *(volatile unsigned long*)SYS_TIMER_C0;
-	draw_hex32(19+14+8+1, 8, systime);
-	draw_string(19+14+9+8, 8, "|");
-	draw_string(19+14+18, 8, "           ");
-	draw_u10(19+14+18, 8, ((unsigned long)tval)/1000000);
+	time_status();
 }