ish: fix task profiling

Previously when performing 'taskinfo' command on ISH5, the time spend in
exception was very high. The time spent in each task was also negative.
The task profiling was broken in many ways. This CL fixes the following:

- Added correct exception start and end times through out
- Updated exception (isr) start and end time to 32-bit so we don't
have issues with 32-bit time rollover
- Fixed time spending in task, exception, and IRQ distribution
- Fixed code that determines which vector is being serviced. Calculation
  before was backwards previously.
- The IRQ_COUNT for ish was too small so we couldn't correctly
  profile the IRQ distribution

BRANCH=none
BUG=b:121343650,b:112750896
TEST='taskinfo' behaves correctly on aracada (ISH5)

Change-Id: I643d3133a608865a1862a70585cfeced4d24649d
Signed-off-by: Jett Rink <jettrink@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1389058
Reviewed-by: Hyungwoo Yang <hyungwoo.yang@intel.com>

7 files changed, 81 insertions, 52 deletions

diff --git a/chip/ish/config_chip.h b/chip/ish/config_chip.h
index 273bcd0788..e83e9fc065 100644
--- a/chip/ish/config_chip.h
+++ b/chip/ish/config_chip.h
@@ -10,7 +10,7 @@
 #include "core/minute-ia/config_core.h"
 
 /* Number of IRQ vectors on the ISH */
-#define CONFIG_IRQ_COUNT	15
+#define CONFIG_IRQ_COUNT	(VEC_TO_IRQ(255) + 1)
 
 /* Use a bigger console output buffer */
 #undef CONFIG_UART_TX_BUF_SIZE
diff --git a/chip/ish/registers.h b/chip/ish/registers.h
index b23890f75a..6137dc6e08 100644
--- a/chip/ish/registers.h
+++ b/chip/ish/registers.h
@@ -59,7 +59,8 @@ enum ish_i2c_port {
  */
 #define USER_VEC_START   32
 /* Map IRQs to vectors after offset 10 for certain APIC interrupts */
-#define IRQ_TO_VEC(irq)  (irq + USER_VEC_START + 10)
+#define IRQ_TO_VEC(irq)  ((irq) + USER_VEC_START + 10)
+#define VEC_TO_IRQ(vec)  ((vec) - USER_VEC_START - 10)
 
 /* ISH GPIO Registers */
 #define ISH_GPIO_GCCR REG32(ISH_GPIO_BASE + 0x000) /* Direction lock */
diff --git a/core/minute-ia/interrupts.c b/core/minute-ia/interrupts.c
index 85f0f21c4d..ee9a9c981c 100644
--- a/core/minute-ia/interrupts.c
+++ b/core/minute-ia/interrupts.c
@@ -94,22 +94,31 @@ void set_interrupt_gate(uint8_t num, isr_handler_t func, uint8_t flags)
 	__idt[num].flags = flags;
 }
 
-void unhandled_vector(void)
+/* This should only be called from an interrupt context */
+uint32_t get_current_interrupt_vector(void)
 {
-	uint32_t vec = 0xff, i;
-	uint32_t ioapic_icr_last = LAPIC_ISR_REG; /* In service register */
-
-	/* Scan ISRs */
-	for (i = 7; i >= 0; i--, ioapic_icr_last -= 0x10) {
+	uint32_t vec, i;
+	/* In service register */
+	uint32_t *ioapic_icr_last = (uint32_t *)LAPIC_ISR_REG;
 
-		asm("movl (%1), %0\n" : "=&r" (vec) : "r" (ioapic_icr_last));
+	/* Scan ISRs from highest priority */
+	for (i = 7; i >= 0; i--, ioapic_icr_last -= 4) {
+		vec = *ioapic_icr_last;
 		if (vec) {
-			vec = (32 * __fls(vec)) + i;
-			break;
+			return (32 * i) + __fls(vec);
 		}
 	}
 
+	CPRINTS("Cannot get vector, not in ISR!");
+	return 0;
+}
+
+/* Should only be called in interrupt context */
+void unhandled_vector(void)
+{
+	uint32_t vec = get_current_interrupt_vector();
 	CPRINTF("Ignoring vector 0x%0x!\n", vec);
+	/* Put the vector number in eax so default_int_handler can use it */
 	asm("" : : "a" (vec));
 }
 
diff --git a/core/minute-ia/interrupts.h b/core/minute-ia/interrupts.h
index ae3903b6fc..d962afccf0 100644
--- a/core/minute-ia/interrupts.h
+++ b/core/minute-ia/interrupts.h
@@ -67,6 +67,9 @@ typedef void (*isr_handler_t) (void);
 void init_interrupts(void);
 void mask_interrupt(unsigned int irq);
 void unmask_interrupt(unsigned int irq);
+
+/* Only call in interrupt context */
+uint32_t get_current_interrupt_vector(void);
 #endif
 
 #endif	/* __CROS_EC_IA32_INTERRUPTS_H */
diff --git a/core/minute-ia/irq_handler.h b/core/minute-ia/irq_handler.h
index b9cbc33ae0..b121413d8d 100644
--- a/core/minute-ia/irq_handler.h
+++ b/core/minute-ia/irq_handler.h
@@ -18,6 +18,13 @@
 #define rstr_fpu_ctx
 #endif
 
+#ifdef CONFIG_TASK_PROFILING
+#define task_start_irq_handler_call "call task_start_irq_handler\n"
+#else
+#define task_start_irq_handler_call
+#endif
+
+
 struct irq_data {
 	void (*routine)(void);
 	int irq;
@@ -47,6 +54,7 @@ struct irq_data {
 		"_irq_"#irq"_handler:\n"				\
 			"pusha\n"					\
 			ASM_LOCK_PREFIX "addl  $1, __in_isr\n"		\
+			task_start_irq_handler_call			\
 			"call "#routine"\n"				\
 			"push $0\n"					\
 			"push $0\n"					\
diff --git a/core/minute-ia/switch.S b/core/minute-ia/switch.S
index de76421a57..9391c186e4 100644
--- a/core/minute-ia/switch.S
+++ b/core/minute-ia/switch.S
@@ -9,6 +9,12 @@
 #include "registers.h"
 #include "task_defs.h"
 
+#ifdef CONFIG_TASK_PROFILING
+#define task_start_irq_handler_call call task_start_irq_handler
+#else
+#define task_start_irq_handler_call
+#endif
+
 .text
 
 .extern current_task
@@ -57,7 +63,7 @@ default_int_handler:
 .endfunc
 
 # Switches from one task to another if ready.
-# __schedule triggeres software interrupt ISH_TS_VECTOR, which is handled by
+# __schedule triggers software interrupt ISH_TS_VECTOR, which is handled by
 # __switchto
 .align 4
 .func __switchto
@@ -71,10 +77,17 @@ __switchto:
 	# triggering ISH_TS_VECTOR
 	#
 	# Push %ecx and %edx into stack to pass them as function parameters
-	# to switch_handler(desched, resched)
-
+	# to switch_handler(desched, resched). After call, we clean up stack
+	# pointer. Note, we do this now before task_start_irq has a chance
+	# to clobber these caller-saved registers.
 	push %ecx
 	push %edx
+
+	# We don't push anything on the stack for start irq since the
+	# parameter is unused.
+	task_start_irq_handler_call
+
+	# Stack is already set up from previous pushes
 	call switch_handler
 	addl $0x8, %esp		# Clean up stack
 
diff --git a/core/minute-ia/task.c b/core/minute-ia/task.c
index adc498830b..5d06672328 100644
--- a/core/minute-ia/task.c
+++ b/core/minute-ia/task.c
@@ -46,8 +46,12 @@ static const char * const task_names[] = {
 
 #ifdef CONFIG_TASK_PROFILING
 static uint64_t task_start_time; /* Time task scheduling started */
-static uint64_t exc_start_time;  /* Time of task->exception transition */
-static uint64_t exc_end_time;    /* Time of exception->task transition */
+/*
+ * We only keep 32-bit values for exception start/end time, to avoid
+ * accounting errors when we service interrupt when the timer wraps around.
+ */
+static uint32_t exc_start_time;  /* Time of task->exception transition */
+static uint32_t exc_end_time;    /* Time of exception->task transition */
 static uint64_t exc_total_time;  /* Total time in exceptions */
 static uint32_t svc_calls;	 /* Number of service calls */
 static uint32_t task_switches;	/* Number of times active task changed */
@@ -160,11 +164,6 @@ inline int in_interrupt_context(void)
 	return !!__in_isr;
 }
 
-static inline int get_interrupt_context(void)
-{
-	return 0;
-}
-
 task_id_t task_get_current(void)
 {
 #ifdef CONFIG_DEBUG_BRINGUP
@@ -192,22 +191,6 @@ int task_start_called(void)
 uint32_t switch_handler(int desched, task_id_t resched)
 {
 	task_ *current, *next;
-#ifdef CONFIG_TASK_PROFILING
-	int exc = get_interrupt_context();
-	uint64_t t;
-#endif
-
-
-#ifdef CONFIG_TASK_PROFILING
-	/*
-	 * SVCall isn't triggered via DECLARE_IRQ(), so it needs to track its
-	 * start time explicitly.
-	 */
-	if (exc == 0xb) {
-		exc_start_time = get_time().val;
-		svc_calls++;
-	}
-#endif
 
 	current = current_task;
 
@@ -234,16 +217,14 @@ uint32_t switch_handler(int desched, task_id_t resched)
 	next = __task_id_to_ptr(__fls(tasks_ready & tasks_enabled));
 
 #ifdef CONFIG_TASK_PROFILING
-	/* Track time in interrupts */
-	t = get_time().val;
-	exc_total_time += (t - exc_start_time);
+	/* Only the first ISR on the (nested IRQ) stack calculates time */
+	if (__in_isr == 1) {
+		/* Track time in interrupts */
+		uint32_t t = get_time().le.lo;
 
-	/*
-	 * Bill the current task for time between the end of the last interrupt
-	 * and the start of this one.
-	 */
-	current->runtime += (exc_start_time - exc_end_time);
-	exc_end_time = t;
+		exc_end_time = t;
+		exc_total_time += (t - exc_start_time);
+	}
 #endif
 
 	/* Nothing to do */
@@ -274,23 +255,37 @@ void __schedule(int desched, int resched)
 }
 
 #ifdef CONFIG_TASK_PROFILING
-void __keep task_start_irq_handler(void *excep_return)
+void __keep task_start_irq_handler(void *unused)
 {
 	/*
 	 * Get time before checking depth, in case this handler is
 	 * pre-empted.
 	 */
-	uint64_t t = get_time().val;
-	int irq = get_interrupt_context() - 16;
+	uint32_t t = get_time().le.lo;
+	uint32_t vector = get_current_interrupt_vector();
+	int irq = VEC_TO_IRQ(vector);
 
 	/*
 	 * Track IRQ distribution.  No need for atomic add, because an IRQ
-	 * can't pre-empt itself.
+	 * can't pre-empt itself. If less than 0, then the vector did not map
+	 * to an IRQ but was for a synchronous exception instead (TS_VECTOR)
 	 */
-	if (irq < ARRAY_SIZE(irq_dist))
+	if (irq > 0 && irq < ARRAY_SIZE(irq_dist))
 		irq_dist[irq]++;
+	else
+		/* Track total number of service calls */
+		atomic_add(&svc_calls, 1);
+
+	/* Only the outer ISR should keep track of the ISR start time */
+	if (__in_isr == 1) {
+		exc_start_time = t;
 
-	exc_start_time = t;
+		/*
+		 * Bill the current task for time between the end of the last
+		 * interrupt and the start of this interrupt (now).
+		 */
+		current_task->runtime += (t - exc_end_time);
+	}
 }
 #endif