From 6f410a16d946d7015eaa11c1b255c28debb0d8b5 Mon Sep 17 00:00:00 2001 From: Michael Brown Date: Sun, 4 May 2014 11:45:11 +0100 Subject: [PATCH] [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 --- src/arch/i386/interface/pxeparent/pxeparent.c | 4 +- src/arch/i386/transitions/librm_mgmt.c | 33 +++++- src/core/profile.c | 3 + src/include/ipxe/profile.h | 103 +++++++++++++++--- 4 files changed, 120 insertions(+), 23 deletions(-) diff --git a/src/arch/i386/interface/pxeparent/pxeparent.c b/src/arch/i386/interface/pxeparent/pxeparent.c index 744c7b6d..0b6be9a0 100644 --- 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 f90d49b0..89668978 100644 --- 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 +#include #include #include @@ -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 ceaadd6c..150e6b27 100644 --- 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 d4fc4f90..3a745fcf 100644 --- 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,23 +161,7 @@ profile_start ( struct profiler *profiler ) { } /** - * Record profiling result - * - * @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_update ( profiler, ( stopped - profiler->started ) ); - } -} - -/** - * Record profiling result + * Stop profiling * * @v profiler Profiler */ @@ -119,4 +173,17 @@ profile_stop ( struct profiler *profiler ) { profile_stop_at ( profiler, profile_timestamp() ); } +/** + * Exclude time from other ongoing profiling results + * + * @v profiler Profiler + */ +static inline __attribute__ (( always_inline )) void +profile_exclude ( struct profiler *profiler ) { + + /* If profiling is active then update accumulated excluded time */ + if ( PROFILING ) + profile_excluded += profile_elapsed ( profiler ); +} + #endif /* _IPXE_PROFILE_H */