Module Profiling Problem

[Chris K Cockrum]

I have been developing a driver for an audio card and encountered a problem 
which I have duplicated in the test code below.  My problem is that when 
trying to profile a section of code in a kernel module I get erratic 
results.  My cycle counts are sometimes 73xxx cycles more that I expect 
them to be.  Does anyone know what could be causing this?

Thanks in Advance,
Chris K Cockrum
iBiquity Digital Corp.
http://www.ibiquity.com

Running Linux 2.4.0 on a Tyan Tiger Dual 800MHz Motherboard w/133MHz Bus

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/sched.h>
#include <asm/smplock.h>

/* Declare Spinlock */
spinlock_t testlock;

int init_module(void)
{
    unsigned long long starttime,stoptime;

    unsigned int lockflags,n,tempval=20000;

    spin_lock_init(&testlock);

    for (n=0;n<40;n++)
    {
       spin_lock_irqsave(&testlock,lockflags);

       /* Clear Interrupt Flag */
       __asm__ __volatile__ ("cli");

       /* Get CPU Clock */
       __asm__ __volatile__ ("rdtsc\n\t" \
                             "movl %%eax, (%%ecx)\n\t" \
                             "movl %%edx, 4(%%ecx)"\
                             ::"c" (&starttime));

       /* Waste Time-Register Moves Looped tempval Times */
       __asm__ __volatile__ ("loop: movl %%ecx,%%eax\t\n" \
                             "      decl %%ecx\t\n" \
                             "      jnz loop" \
                             :: "c" (tempval) : "%eax");

       /* Get CPU Clock */
       __asm__ __volatile__ ("rdtsc\n\t" \
                             "movl %%eax, (%%ecx)\n\t" \
                             "movl %%edx, 4(%%ecx)"\
                             ::"c" (&stoptime));

       spin_unlock_irqrestore(&testlock,lockflags);

       printk(KERN_DEBUG "Test: 0x%08X:%08X - %d Cycles\n", \
             (unsigned int) (((stoptime-starttime)>>32)&0xFFFFFFFF), \
             (unsigned int)  ((stoptime-starttime)     &0xFFFFFFFF), \
             (unsigned int)  ((stoptime-starttime)     &0xFFFFFFFF)  );

    }
    return 0;
}

void cleanup_module(void)
{
printk(KERN_DEBUG "Unloaded\n");
}

Results:

Test: 0x00000000:0000EA94 - 60052 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:00020977 - 133495 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:00020997 - 133527 Cycles
Test: 0x00000000:0002098F - 133519 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:00020976 - 133494 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0002098A - 133514 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0002098E - 133518 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles
Test: 0x00000000:0002098A - 133514 Cycles
Test: 0x00000000:0000EA87 - 60039 Cycles