lkml.org 
[lkml]   [1996]   [Nov]   [6]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Date
Subjecttime warps: good bad news
Hello,

according to an idea of Ingo Molnar I changed the Pentium timer
interrupt service routine to look for delayed timer interrupt
processing. As on of my kernel trees is rather "hacked", I do not
supply a patch, but the complete routine I used (hack.c).

Now the good news:

As I could not detect a severly delayed interrupt (with my load), I
also wrote a test program (not too good) that compares the Pentium
cycle counter and the current kernel lcok that is maintained in
software. I tried to calculate the difference of both values in
microseconds and abort the program if the error exeeds about 2500us.

Now the bad news:

The program stopped! Using a stock 2.0.22 kernel I got the following
results (copied by hand and rounded):

D E L A Y E R R O R
min max min max
5 173424 -1887 8569
5 231164 -1875 60341
5 341642 -85 210257

Now I think these numbers are quite impressive (especially the
delays). Of course I know that the test program may be rescheduled
between any statement, but 340ms seems to be a long time.

My machine, a P100 with 32MB of RAM and an Adaptec 2940 SCSI
hostadapter, was rather idle. I was just funning "find /" on another
terminal, and I had a serial receive interrupt once per second.

The process ran as root with normal priority. I hope all data are not
just an artefact of software time measuring. Possibly I should use
the real-time features of Linux, but I did not know how to do that.
Ideas welcome.

I'll attach both programs (excuse the size)...

Ulrich
static void pentium_timer_interrupt(int irq, void *dev_id, struct pt_regs *regs)
{
typedef union {
unsigned long long ull;
struct {
unsigned long lo;
unsigned long hi;
} s;
} ugly_hack;
static ugly_hack saved_cc; /* = 0; */
#define MHZ 100
#define CYCLES_PER_JIFFY (MHZ * 1000000 / HZ)
/* read Pentium cycle counter */
__asm__(".byte 0x0f,0x31"
:"=a" (last_timer_cc.low),
"=d" (last_timer_cc.high));
if ( ((ugly_hack *) &last_timer_cc)->ull - saved_cc.ull >
6ULL * CYCLES_PER_JIFFY / 5 ) {
printk(KERN_DEBUG "P timer: delayed ISR %Lu from %p\n",
((ugly_hack *) &last_timer_cc)->ull - saved_cc.ull,
__builtin_return_address(0));
}
saved_cc = *(ugly_hack *) &last_timer_cc;
timer_interrupt(irq, NULL, regs);
}
/* $Id: pentium_time.c,v 1.2 1996/11/04 22:36:16 root Exp $ */
/* ATTENTION: Program only works without "-O"; I don't know why */
#include <stdio.h>
#include <unistd.h>
#include <sys/time.h>

#ifndef HZ
#define HZ 100
#endif

#define MHZ 100
#define CYCLES_PER_SECOND (MHZ * 1000000UL)
#define CYCLES_PER_JIFFY (CYCLES_PER_SECOND / HZ)
#define USEC_PER_JIFFY (1000000L / HZ)

#define barrier() __asm__("": : :"memory") /* from kernel.h */

typedef struct {
unsigned long lo;
unsigned long hi;
} LLS;

typedef union {
unsigned long long ull;
LLS lls;
} CC;

CC cc1;
CC cc2;
CC cc;
unsigned long us1;
unsigned long us2;
unsigned long us;

/* return Pentium cycle counter */
inline CC read_CC(void)
{
CC result;

__asm__(".byte 0x0f, 0x31" :"=a" (result.lls.lo), "=d" (result.lls.hi));
return(result);
}

void calibrate(void)
{
CC c1, c2;
struct timeval tv1, tv2;

fprintf(stderr, "Calibrating counters, be patient...\n");
c1 = read_CC();
gettimeofday(&tv1, NULL);
sleep(1);
c2 = read_CC();
gettimeofday(&tv2, NULL);
us1 = 1000000 * (tv2.tv_sec - tv1.tv_sec) + tv2.tv_usec - tv1.tv_usec;
cc1.ull = c2.ull - c1.ull;
printf("Elapsed time = %fs, elapsed cycles = %Lu\n",
(double) us1 / 1000000, cc1.ull);

c1 = read_CC();
gettimeofday(&tv1, NULL);
do {
c2 = read_CC();
} while ( c2.ull - c1.ull < CYCLES_PER_SECOND );
gettimeofday(&tv2, NULL);
us2 = 1000000 * (tv2.tv_sec - tv1.tv_sec) + tv2.tv_usec - tv1.tv_usec;
cc2.ull = c2.ull - c1.ull;
printf("Elapsed time = %fs, elapsed cycles = %Lu\n",
(double) us2 / 1000000, cc2.ull);
cc.ull = (cc1.ull + cc2.ull) / 2;
us = (us1 + us2) / 2;
printf("Average: elapsed time = %fs, elapsed cycles = %Lu\n",
(double) us / 1000000, cc.ull);
}

/* update peak values */
int update_peaks(unsigned long elapsed_us, double error_us)
{
static unsigned long min_ela = 1000000UL;
static unsigned long max_ela = 0UL;
static double min_err = 1000000.0;
static double max_err = -1000000.0;
int change;

change = 0;
if ( elapsed_us < min_ela )
change = 1, min_ela = elapsed_us;
if ( elapsed_us > max_ela )
change = 1, max_ela = elapsed_us;
if ( error_us < min_err )
change = 1, min_err = error_us;
if ( error_us > max_err )
change = 1, max_err = error_us;
if ( change )
printf("new peaks: elapsed = (%lu, %lu), error = (%f, %f)\n",
min_ela, max_ela, min_err, max_err);
return(change);
}

/* perform measurements */
void measure()
{
CC c0, c1;
struct timeval tv0, tv1;
unsigned long dus;
CC dc;
double delta;

c0 = read_CC();
gettimeofday(&tv0, NULL);
while (1)
{
c1 = read_CC();
gettimeofday(&tv1, NULL);
dc = c1.ull - c0.ull;
dus = 1000000 * (tv1.tv_sec - tv0.tv_sec) +
tv1.tv_usec - tv0.tv_usec;
delta = dus - (1000000.0 * dc.ull + dc.ull / 2) / cc.ull;
if ( update_peaks(dus, delta) )
{
printf("elapsed time = %luus, est = %luus, error = %fus\n",
dus,
(unsigned long) ((dc.ull * us2 + CYCLES_PER_SECOND / 2) /
CYCLES_PER_SECOND),
delta);
}
if ( delta >= USEC_PER_JIFFY / 4 ||
delta <= -USEC_PER_JIFFY / 4 )
{
break;
}
c0 = c1;
tv0 = tv1;
}
}

int main()
{
calibrate();
measure();
return(0);
}
\
 
 \ /
  Last update: 2005-03-22 13:38    [W:0.028 / U:0.812 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site