[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>

diff --git a/src/arch/i386/interface/pxeparent/pxeparent.c b/src/arch/i386/interface/pxeparent/pxeparent.c
index 744c7b6dd493aa7794d7f477e762969112d7572b..0b6be9a0309001b1141a97a2d6a4a3a8c22eee45 100644 (file)
--- a/src/arch/i386/interface/pxeparent/pxeparent.c
+++ b/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

diff --git a/src/arch/i386/transitions/librm_mgmt.c b/src/arch/i386/transitions/librm_mgmt.c
index f90d49b02af41fddba5f30e34840756fb44369cd..89668978b5900dd204047245eb6321e9762566c2 100644 (file)
--- a/src/arch/i386/transitions/librm_mgmt.c
+++ b/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 );

diff --git a/src/core/profile.c b/src/core/profile.c
index ceaadd6ce2aa28ac671d3a18025464982efaa44e..150e6b27381417aca0ceb012e02256c1e8f69fb0 100644 (file)
--- a/src/core/profile.c
+++ b/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)
  *

diff --git a/src/include/ipxe/profile.h b/src/include/ipxe/profile.h
index d4fc4f90f3bec3e0e11d413c41d98d73c5bf68c8..3a745fcfa850de87faaabc75c582875d01f74fd6 100644 (file)
--- a/src/include/ipxe/profile.h
+++ b/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 */