[profile] Allow interrupts to be excluded from profiling results

Interrupt processing adds noise to profiling results.  Allow
interrupts (from within protected mode) to be profiled separately,
with time spent within the interrupt handler being excluded from any
other profiling currently in progress.

Signed-off-by: Michael Brown <mcb30@ipxe.org>

src/arch/i386/interface/pxeparent/pxeparent.c

@@ -240,12 +240,12 @@ int pxeparent_call ( SEGOFF16_t entry, unsigned int function,
 			         "D" ( __from_data16 ( &pxeparent_params ) )
 			       : "ecx", "esi" );
 	profile_stop ( &profiler->total );
-	profile_start_at ( &profiler->p2r, profiler->total.started );
+	profile_start_at ( &profiler->p2r, profile_started ( &profiler->total));
 	profile_stop_at ( &profiler->p2r, started );
 	profile_start_at ( &profiler->ext, started );
 	profile_stop_at ( &profiler->ext, stopped );
 	profile_start_at ( &profiler->r2p, stopped );
-	profile_stop_at ( &profiler->r2p, profiler->total.stopped );
+	profile_stop_at ( &profiler->r2p, profile_stopped ( &profiler->total ));
 
 	/* Determine return status code based on PXENV_EXIT and
 	 * PXENV_STATUS

src/arch/i386/transitions/librm_mgmt.c

@@ -8,6 +8,7 @@
 FILE_LICENCE ( GPL2_OR_LATER );
 
 #include <stdint.h>
+#include <ipxe/profile.h>
 #include <realmode.h>
 #include <pic8259.h>
 
@@ -30,6 +31,12 @@ struct idtr idtr = {
 	.limit = ( sizeof ( idt ) - 1 ),
 };
 
+/** Timer interrupt profiler */
+static struct profiler timer_irq_profiler __profiler = { .name = "irq.timer" };
+
+/** Other interrupt profiler */
+static struct profiler other_irq_profiler __profiler = { .name = "irq.other" };
+
 /**
  * Allocate space on the real-mode stack and copy data there from a
  * user buffer
@@ -103,19 +110,39 @@ void init_idt ( void ) {
 	idtr.base = virt_to_phys ( idt );
 }
 
+/**
+ * Determine interrupt profiler (for debugging)
+ *
+ * @v intr		Interrupt number
+ * @ret profiler	Profiler
+ */
+static struct profiler * interrupt_profiler ( int intr ) {
+
+	switch ( intr ) {
+	case IRQ_INT ( 0 ) :
+		return &timer_irq_profiler;
+	default:
+		return &other_irq_profiler;
+	}
+}
+
 /**
  * Interrupt handler
  *
- * @v irq		Interrupt number
+ * @v intr		Interrupt number
  */
-void __attribute__ (( cdecl, regparm ( 1 ) )) interrupt ( int irq ) {
+void __attribute__ (( cdecl, regparm ( 1 ) )) interrupt ( int intr ) {
+	struct profiler *profiler = interrupt_profiler ( intr );
 	uint32_t discard_eax;
 
 	/* Reissue interrupt in real mode */
+	profile_start ( profiler );
 	__asm__ __volatile__ ( REAL_CODE ( "movb %%al, %%cs:(1f + 1)\n\t"
 					   "\n1:\n\t"
 					   "int $0x00\n\t" )
-			       : "=a" ( discard_eax ) : "0" ( irq ) );
+			       : "=a" ( discard_eax ) : "0" ( intr ) );
+	profile_stop ( profiler );
+	profile_exclude ( profiler );
 }
 
 PROVIDE_UACCESS_INLINE ( librm, phys_to_user );

src/core/profile.c

@@ -40,6 +40,9 @@ FILE_LICENCE ( GPL2_OR_LATER );
  * to avoid the use of floating-point instructions.
  */
 
+/** Accumulated time excluded from profiling */
+unsigned long profile_excluded;
+
 /**
  * Format a hex fraction (for debugging)
  *

src/include/ipxe/profile.h

@@ -58,11 +58,65 @@ struct profiler {
 #define __profiler
 #endif
 
+extern unsigned long profile_excluded;
+
 extern void profile_update ( struct profiler *profiler, unsigned long sample );
 extern unsigned long profile_mean ( struct profiler *profiler );
 extern unsigned long profile_variance ( struct profiler *profiler );
 extern unsigned long profile_stddev ( struct profiler *profiler );
 
+/**
+ * Get start time
+ *
+ * @v profiler		Profiler
+ * @ret started		Start time
+ */
+static inline __attribute__ (( always_inline )) unsigned long
+profile_started ( struct profiler *profiler ) {
+
+	/* If profiling is active then return start time */
+	if ( PROFILING ) {
+		return ( profiler->started + profile_excluded );
+	} else {
+		return 0;
+	}
+}
+
+/**
+ * Get stop time
+ *
+ * @v profiler		Profiler
+ * @ret stopped		Stop time
+ */
+static inline __attribute__ (( always_inline )) unsigned long
+profile_stopped ( struct profiler *profiler ) {
+
+	/* If profiling is active then return start time */
+	if ( PROFILING ) {
+		return ( profiler->stopped + profile_excluded );
+	} else {
+		return 0;
+	}
+}
+
+/**
+ * Get elapsed time
+ *
+ * @v profiler		Profiler
+ * @ret elapsed		Elapsed time
+ */
+static inline __attribute__ (( always_inline )) unsigned long
+profile_elapsed ( struct profiler *profiler ) {
+
+	/* If profiling is active then return elapsed time */
+	if ( PROFILING ) {
+		return ( profile_stopped ( profiler ) -
+			 profile_started ( profiler ) );
+	} else {
+		return 0;
+	}
+}
+
 /**
  * Start profiling
  *
@@ -74,7 +128,23 @@ profile_start_at ( struct profiler *profiler, unsigned long started ) {
 
 	/* If profiling is active then record start timestamp */
 	if ( PROFILING )
-		profiler->started = started;
+		profiler->started = ( started - profile_excluded );
+}
+
+/**
+ * Stop profiling
+ *
+ * @v profiler		Profiler
+ * @v stopped		Stop timestamp
+ */
+static inline __attribute__ (( always_inline )) void
+profile_stop_at ( struct profiler *profiler, unsigned long stopped ) {
+
+	/* If profiling is active then record end timestamp and update stats */
+	if ( PROFILING ) {
+		profiler->stopped = ( stopped - profile_excluded );
+		profile_update ( profiler, profile_elapsed ( profiler ) );
+	}
 }
 
 /**
@@ -91,32 +161,29 @@ profile_start ( struct profiler *profiler ) {
 }
 
 /**
- * Record profiling result
+ * Stop profiling
  *
  * @v profiler		Profiler
- * @v stopped		Stop timestamp
  */
 static inline __attribute__ (( always_inline )) void
-profile_stop_at ( struct profiler *profiler, unsigned long stopped ) {
+profile_stop ( struct profiler *profiler ) {
 
 	/* If profiling is active then record end timestamp and update stats */
-	if ( PROFILING ) {
-		profiler->stopped = stopped;
-		profile_update ( profiler, ( stopped - profiler->started ) );
-	}
+	if ( PROFILING )
+		profile_stop_at ( profiler, profile_timestamp() );
 }
 
 /**
- * Record profiling result
+ * Exclude time from other ongoing profiling results
  *
  * @v profiler		Profiler
  */
 static inline __attribute__ (( always_inline )) void
-profile_stop ( struct profiler *profiler ) {
+profile_exclude ( struct profiler *profiler ) {
 
-	/* If profiling is active then record end timestamp and update stats */
+	/* If profiling is active then update accumulated excluded time */
 	if ( PROFILING )
-		profile_stop_at ( profiler, profile_timestamp() );
+		profile_excluded += profile_elapsed ( profiler );
 }
 
 #endif /* _IPXE_PROFILE_H */