help? baffled trying to figure out where time is being spent

[Chris Friesen]

Hi guys,

I'm looking at the following instrumented code.  This is part of an 
instrumented version of scheduler_tick(), running on what is essentially 
a "maple" board.  Dual 970fx, 4GB of memory.  Modified 2.6.10.

Shortly after initial boot, on cpu1, it seems like somehow there is a 
huge time gap between where "c" gets assigned and where "d" gets 
assigned in the code below.

The time gap between "c" and "d" is about 4.2 seconds.
The time gap between "aj" and "bj" is about 6.17 seconds.

The next time through the loop, the printk() triggers with a complaint 
that it took 6381 ticks between scheduler_tick() calls.

I'm baffled as to where the gap is coming from.  Any ideas?

Interrupts are for certain disabled while this code runs.  The printk 
statement is not being reached, so the "sched_delta" check is failing.

The gethrtime() function simply reads the tbr on ppc64, so it maps to a 
single instruction.



b=gethrtime();
	sched_delta = schedtime - __get_cpu_var(last_sched_tick);
c=gethrtime();
aj=jiffies;
	if (sched_delta > SCHED_INTERVAL_THRESH) {
		/* disable exception history if specified */
		if (disable_hist_on_event)
			disable_history_buffer = 1;
		printk(KERN_WARNING "cpu%d: jiffies: %lu, hrtime: %llu, %lu ticks 
between scheduler_tick() calls\n",
			smp_processor_id(), schedtime, (unsigned long long) gethrtime(), 
sched_delta);
	}
d=gethrtime();
bj=jiffies;



Chris