Messages in this thread | | | From | "Ulrich Windl" <> | Date | Tue, 5 Nov 1996 08:39:30 +0100 | Subject | time 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); }
| |