* Fernando Lopez-Lezcano <[email protected]> wrote:
> On Tue, 2005-11-15 at 10:08 +0100, Ingo Molnar wrote:
> > i have released the 2.6.14-rt13 tree, which can be downloaded from the
> > usual place:
> >
> > http://redhat.com/~mingo/realtime-preempt/
> >
> > lots of fixes in this release affecting all supported architectures, all
> > across the board. Big MIPS update from John Cooper.
>
> Can someone tell me if 2.6.14-rt13 is supposed to be fixed re: the
> problems I was having with random screensaver triggering and keyboard
> repeats?
>
> It is apparently not fixed.
>
> I just had a short burst of key repeats and saw one random screen
> blank. Right now everything seems normal but I was not allucinating
> :-)
is this on the dual-core X2 box, running 32-bit code? Did it happen with
idle=poll? Without idle=poll the TSCs run apart and a number of
artifacts may happen. With idle=poll specified the TSC _should_ be fully
synchronized.
To make sure could you run the attached time-warp-test utility i wrote
today? Compile it with:
gcc -Wall -O2 -o time-warp-test time-warp-test.c
it detects and reports time-warps (and does a maximum search for them
over time, that way you can see systematic drifts too). (It auto-detects
the # of CPUs and runs the appropriate number of tasks.)
running this tool on a X2 with idle=poll and an -rt kernel should give a
silent test-output.
running a vanilla kernel should give TSC level time warps:
#CPUs: 2
running 2 tasks to check for time-warps.
warp .. -1 cycles, ... 00000277ed9520c6 -> 00000277ed9520c5 ?
warp .. -18 cycles, ... 00000277ed97ac77 -> 00000277ed97ac65 ?
warp .. -19 cycles, ... 00000277edaedd54 -> 00000277edaedd41 ?
warp .. -84 cycles, ... 00000277ede0558a -> 00000277ede05536 ?
warp .. -97 cycles, ... 00000278035328a5 -> 0000027803532844 ?
warp .. -224 cycles, ... 000002781ed2db04 -> 000002781ed2da24 ?
(because the vanilla kernel doesnt do TSC synchronization accurately)
running it without idle=poll should give some really big time warps:
neptune:~> ./time-warp-test
#CPUs: 2
running 2 tasks to check for time-warps.
warp .. -435934 cycles, ... 00000101a2db4a8f -> 00000101a2d4a3b1 ?
WARP .. -123 usecs, .... 0003e96c2f3bb579 -> 0003e96c2f3bb4fe ?
WARP .. -198 usecs, .... 0003e96c2f3bb625 -> 0003e96c2f3bb55f ?
WARP .. -199 usecs, .... 0003e96c2f3bb659 -> 0003e96c2f3bb592 ?
warp .. -436117 cycles, ... 00000101a2e5aaf0 -> 00000101a2df035b ?
warp .. -437143 cycles, ... 00000101a2e84590 -> 00000101a2e199f9 ?
warp .. -437314 cycles, ... 00000101a2ead1b1 -> 00000101a2e4256f ?
warp .. -437363 cycles, ... 00000101a2ed9b19 -> 00000101a2e6eea6 ?
WARP .. -1951680 usecs, .... 0003e96c2f597f70 -> 0003e96c2f3bb7b0 ?
WARP .. -1951879 usecs, .... 0003e96c2f598016 -> 0003e96c2f3bb78f ?
WARP .. -1951681 usecs, .... 0003e96c2f598014 -> 0003e96c2f3bb853 ?
warp .. -437365 cycles, ... 00000101a4c5be7b -> 00000101a4bf1206 ?
warp .. -437366 cycles, ... 00000101a8f4af76 -> 00000101a8ee0300 ?
warp .. -437367 cycles, ... 00000101a968a34a -> 00000101a961f6d3 ?
these time warps will get worse over time - as the two cores drift
apart. (note that they wont drift during the test itself, because the
test makes all cores artificially busy and the X2 TSC drifting depends
on the core being idle)
but in any case, -rt13 should be silent and there should be no time
warps. If there are any then those could cause the keyboard repeat
problems.
Ingo
-------{ CUT HERE time-warp-test.c }-------------->
/*
* Copyright (C) 2005, Ingo Molnar
*
* time-warp-test.c: check TSC synchronity on x86 CPUs. Also detects
* gettimeofday()-level time warps.
*/
#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <signal.h>
#include <sys/wait.h>
#include <linux/unistd.h>
#include <unistd.h>
#include <string.h>
#include <pwd.h>
#include <grp.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/time.h>
#include <regex.h>
#include <fcntl.h>
#include <time.h>
#include <sys/mman.h>
#include <dlfcn.h>
#include <popt.h>
#include <sys/socket.h>
#include <ctype.h>
#include <assert.h>
#include <sched.h>
#define TEST_TSC
#define TEST_TOD
#define MAX_TASKS 128
#if DEBUG
# define Printf(x...) printf(x)
#else
# define Printf(x...) do { } while (0)
#endif
enum {
SHARED_TSC = 0,
SHARED_LOCK = 2,
SHARED_TOD = 3,
SHARED_WORST_TSC = 5,
SHARED_WORST_TOD = 7,
SHARED_LOCK2 = 200,
};
#define BUG_ON(c) assert(!(c))
typedef unsigned long long cycles_t;
typedef unsigned long long usecs_t;
#define rdtscll(val) \
__asm__ __volatile__("rdtsc" : "=A" (val))
#define rdtod(val) \
do { \
struct timeval tv; \
\
gettimeofday(&tv, NULL); \
(val) = tv.tv_sec * 1000000LL + tv.tv_usec; \
} while (0)
#define mb() \
__asm__ __volatile__("lock; addl $0, (%esp)")
static unsigned long *setup_shared_var(void)
{
char zerobuff [4096] = { 0, };
int ret, fd;
unsigned long *buf;
fd = creat(".tmp_mmap", 0700);
BUG_ON(fd == -1);
close(fd);
fd = open(".tmp_mmap", O_RDWR|O_CREAT|O_TRUNC);
BUG_ON(fd == -1);
ret = write(fd, zerobuff, 4096);
BUG_ON(ret != 4096);
buf = (void *)mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
BUG_ON(buf == (void *)-1);
close(fd);
return buf;
}
#define LOOPS 1000000
static inline unsigned long
cmpxchg(volatile unsigned long *ptr, unsigned long old, unsigned long new)
{
unsigned long prev;
__asm__ __volatile__("lock; cmpxchg %b1,%2"
: "=a"(prev)
: "q"(new), "m"(*(ptr)), "0"(old)
: "memory");
return prev;
}
static inline void lock(unsigned long *flag)
{
while (cmpxchg(flag, 0, 1) != 0)
/* nothing */;
}
static inline void unlock(unsigned long *flag)
{
*flag = 0;
mb();
}
static void print_status(void)
{
const char progress[] = "\\|/-";
static usecs_t prev_tod;
static int count;
usecs_t tod;
rdtod(tod);
if (tod - prev_tod < 100000ULL)
return;
prev_tod = tod;
count++;
printf("%c\r", progress[count & 3]);
fflush(stdout);
}
int main(int argc, char **argv)
{
int i, parent, me;
unsigned long *shared;
unsigned long cpus, tasks;
cpus = system("exit `grep processor /proc/cpuinfo | wc -l`");
cpus = WEXITSTATUS(cpus);
if (argc > 2) {
usage:
fprintf(stderr,
"usage: tsc-sync-test <threads>\n");
exit(-1);
}
if (argc == 2) {
tasks = atol(argv[1]);
if (!tasks)
goto usage;
} else
tasks = cpus;
printf("#CPUs: %ld\n", cpus);
printf("running %ld tasks to check for time-warps.\n", tasks);
shared = setup_shared_var();
parent = getpid();
for (i = 1; i < tasks; i++)
if (!fork())
break;
me = getpid();
while (1) {
cycles_t t0, t1;
usecs_t T0, T1;
long long delta;
#ifdef TEST_TSC
lock(shared + SHARED_LOCK);
rdtscll(t1);
t0 = *(cycles_t *)(shared + SHARED_TSC);
*(cycles_t *)(shared + SHARED_TSC) = t1;
unlock(shared + SHARED_LOCK);
delta = t1-t0;
if (delta < *(long long *)(shared + SHARED_WORST_TSC)) {
*(long long *)(shared + SHARED_WORST_TSC) = delta;
printf("\rwarp .. %9Ld cycles, ... %016Lx -> %016Lx ?\n",
delta, t0, t1);
}
// occasionally disturb things a bit
if (!(t0 & 7)) {
lock(shared + SHARED_LOCK2);
unlock(shared + SHARED_LOCK2);
}
#endif
#ifdef TEST_TOD
lock(shared + SHARED_LOCK);
rdtod(T1);
T0 = *(usecs_t *)(shared + SHARED_TOD);
*(usecs_t *)(shared + SHARED_TOD) = T1;
unlock(shared + SHARED_LOCK);
delta = T1-T0;
if (delta < *(long long *)(shared + SHARED_WORST_TOD)) {
*(long long *)(shared + SHARED_WORST_TOD) = delta;
printf("\rWARP .. %9Ld usecs, .... %016Lx -> %016Lx ?\n",
delta, T0, T1);
}
if (!(T0 & 7)) {
lock(shared + SHARED_LOCK2);
unlock(shared + SHARED_LOCK2);
}
#endif
if (me == parent)
print_status();
}
return 0;
}
On Mon, 2005-11-21 at 23:19 +0100, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <[email protected]> wrote:
>
> > On Tue, 2005-11-15 at 10:08 +0100, Ingo Molnar wrote:
> > > i have released the 2.6.14-rt13 tree, which can be downloaded from the
> > > usual place:
> > >
> > > http://redhat.com/~mingo/realtime-preempt/
> > >
> > > lots of fixes in this release affecting all supported architectures, all
> > > across the board. Big MIPS update from John Cooper.
> >
> > Can someone tell me if 2.6.14-rt13 is supposed to be fixed re: the
> > problems I was having with random screensaver triggering and keyboard
> > repeats?
> >
> > It is apparently not fixed.
> >
> > I just had a short burst of key repeats and saw one random screen
> > blank. Right now everything seems normal but I was not allucinating
> > :-)
>
> is this on the dual-core X2 box, running 32-bit code?
That's correct.
> Did it happen with idle=poll?
No, I'm not running with idle=poll right now.
> Without idle=poll the TSCs run apart and a number of
> artifacts may happen. With idle=poll specified the TSC _should_ be fully
> synchronized.
Well, I could try but it is not a solution I could use. It would turn
all my machines into space heaters 24x7, no sense in doing that :-)
I got an answer off the list from John (Stultz) in response to the dmesg
output I sent him and he suggested I try idle=poll (which I briefly did
last week) and also changing:
/sys/devices/system/clocksource/clocksource0/clocksource
to acpi_pm, which I just did. It is too early to tell re: keyboard
repeats and screensaver false triggers, but it did fix the problems I
was seeing with a hacked Jack that is using gettimeofday instead of tsc
reads. Meaning, Jack with gettimeofday + tsc timing source has problems,
Jack with gettimeofday + acpi_pm does not. It would seem gettimeofday is
not working correctly with tsc.
> To make sure could you run the attached time-warp-test utility i wrote
> today?
I will and report back.
Thanks.
-- Fernando
> Compile it with:
>
> gcc -Wall -O2 -o time-warp-test time-warp-test.c
>
> it detects and reports time-warps (and does a maximum search for them
> over time, that way you can see systematic drifts too). (It auto-detects
> the # of CPUs and runs the appropriate number of tasks.)
>
> running this tool on a X2 with idle=poll and an -rt kernel should give a
> silent test-output.
>
> running a vanilla kernel should give TSC level time warps:
>
> #CPUs: 2
> running 2 tasks to check for time-warps.
> warp .. -1 cycles, ... 00000277ed9520c6 -> 00000277ed9520c5 ?
> warp .. -18 cycles, ... 00000277ed97ac77 -> 00000277ed97ac65 ?
> warp .. -19 cycles, ... 00000277edaedd54 -> 00000277edaedd41 ?
> warp .. -84 cycles, ... 00000277ede0558a -> 00000277ede05536 ?
> warp .. -97 cycles, ... 00000278035328a5 -> 0000027803532844 ?
> warp .. -224 cycles, ... 000002781ed2db04 -> 000002781ed2da24 ?
>
> (because the vanilla kernel doesnt do TSC synchronization accurately)
>
> running it without idle=poll should give some really big time warps:
>
> neptune:~> ./time-warp-test
> #CPUs: 2
> running 2 tasks to check for time-warps.
> warp .. -435934 cycles, ... 00000101a2db4a8f -> 00000101a2d4a3b1 ?
> WARP .. -123 usecs, .... 0003e96c2f3bb579 -> 0003e96c2f3bb4fe ?
> WARP .. -198 usecs, .... 0003e96c2f3bb625 -> 0003e96c2f3bb55f ?
> WARP .. -199 usecs, .... 0003e96c2f3bb659 -> 0003e96c2f3bb592 ?
> warp .. -436117 cycles, ... 00000101a2e5aaf0 -> 00000101a2df035b ?
> warp .. -437143 cycles, ... 00000101a2e84590 -> 00000101a2e199f9 ?
> warp .. -437314 cycles, ... 00000101a2ead1b1 -> 00000101a2e4256f ?
> warp .. -437363 cycles, ... 00000101a2ed9b19 -> 00000101a2e6eea6 ?
> WARP .. -1951680 usecs, .... 0003e96c2f597f70 -> 0003e96c2f3bb7b0 ?
> WARP .. -1951879 usecs, .... 0003e96c2f598016 -> 0003e96c2f3bb78f ?
> WARP .. -1951681 usecs, .... 0003e96c2f598014 -> 0003e96c2f3bb853 ?
> warp .. -437365 cycles, ... 00000101a4c5be7b -> 00000101a4bf1206 ?
> warp .. -437366 cycles, ... 00000101a8f4af76 -> 00000101a8ee0300 ?
> warp .. -437367 cycles, ... 00000101a968a34a -> 00000101a961f6d3 ?
>
> these time warps will get worse over time - as the two cores drift
> apart. (note that they wont drift during the test itself, because the
> test makes all cores artificially busy and the X2 TSC drifting depends
> on the core being idle)
>
> but in any case, -rt13 should be silent and there should be no time
> warps. If there are any then those could cause the keyboard repeat
> problems.
>
> Ingo
>
> -------{ CUT HERE time-warp-test.c }-------------->
[MUNCH]
On Mon, 2005-11-21 at 23:19 +0100, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <[email protected]> wrote:
> > I just had a short burst of key repeats and saw one random screen
> > blank. Right now everything seems normal but I was not allucinating
> > :-)
>
> is this on the dual-core X2 box, running 32-bit code? Did it happen with
> idle=poll? Without idle=poll the TSCs run apart and a number of
> artifacts may happen. With idle=poll specified the TSC _should_ be fully
> synchronized.
>
> To make sure could you run the attached time-warp-test utility i wrote
> today? Compile it with:
>
> gcc -Wall -O2 -o time-warp-test time-warp-test.c
>
> it detects and reports time-warps (and does a maximum search for them
> over time, that way you can see systematic drifts too). (It auto-detects
> the # of CPUs and runs the appropriate number of tasks.)
Ok, here are some test runs:
Athlon X2, 2.6.14-rt13, __not__ booting idle=poll
cat /sys/devices/system/clocksource/clocksource0/clocksource
acpi_pm jiffies *tsc pit
[hacked Jack with gettimeofday fails with "delay exceeded..." messages]
# ./time-warp-test #CPUs: 2
running 2 tasks to check for time-warps.
warp .. -2735313 cycles, ... 000014b9f770036f -> 000014b9f746469e ?
WARP .. -1224 usecs, .... 0004061b6acd7dc6 -> 0004061b6acd78fe ?
WARP .. -1237 usecs, .... 0004061b6acd7e07 -> 0004061b6acd7932 ?
warp .. -2735317 cycles, ... 000014b9f7773a97 -> 000014b9f74d7dc2 ?
WARP .. -1238 usecs, .... 0004061b6acd7e65 -> 0004061b6acd798f ?
warp .. -2736775 cycles, ... 000014b9f77a9bd0 -> 000014b9f750d949 ?
warp .. -2736848 cycles, ... 000014b9f77c83aa -> 000014b9f752c0da ?
warp .. -2736953 cycles, ... 000014b9f77e82a6 -> 000014b9f754bf6d ?
warp .. -2737060 cycles, ... 000014b9f7831875 -> 000014b9f75954d1 ?
warp .. -2737090 cycles, ... 000014b9f792d70b -> 000014b9f7691349 ?
warp .. -2737265 cycles, ... 000014b9f79c9509 -> 000014b9f772d098 ?
warp .. -2737387 cycles, ... 000014ba0129c8e7 -> 000014ba010003fc ?
warp .. -2737405 cycles, ... 000014ba0b696ad1 -> 000014ba0b3fa5d4 ?
WARP .. -4398045268 usecs, .... 0004061c70fdbd6e -> 0004061b6ad8e51a ?
WARP .. -4398045269 usecs, .... 0004061c70fdbe56 -> 0004061b6ad8e601 ?
warp .. -2737407 cycles, ... 000014c0f4960dfd -> 000014c0f46c48fe ?
warp .. -2737435 cycles, ... 000014c100f929b5 -> 000014c100cf649a ?
warp .. -2737450 cycles, ... 000014ef1eff0250 -> 000014ef1ed53d26 ?
warp .. -2737470 cycles, ... 000014ef2a976748 -> 000014ef2a6da20a ?
warp .. -2737472 cycles, ... 000014ef98ee8f62 -> 000014ef98c4ca22 ?
warp .. -2737494 cycles, ... 000014efac5b0d44 -> 000014efac3147ee ?
warp .. -2737506 cycles, ... 000014f42d48833f -> 000014f42d1ebddd ?
WARP .. -4398046507 usecs, .... 0004061c788544c5 -> 0004061b7260679a ?
warp .. -2737535 cycles, ... 000014ffb2b84ca9 -> 000014ffb28e872a ?
warp .. -2737678 cycles, ... 0000150b8cae9ad3 -> 0000150b8c84d4c5 ?
warp .. -2737847 cycles, ... 0000153e388bc05d -> 0000153e3861f9a6 ?
warp .. -2737851 cycles, ... 0000153e3b472185 -> 0000153e3b1d5aca ?
warp .. -2737871 cycles, ... 0000153e3b94270d -> 0000153e3b6a603e ?
warp .. -2737872 cycles, ... 0000153e3c3d4034 -> 0000153e3c137964 ?
warp .. -2737891 cycles, ... 0000153e51313527 -> 0000153e51076e44 ?
warp .. -2737935 cycles, ... 0000153e55df386a -> 0000153e55b5715b ?
warp .. -2737987 cycles, ... 0000153ec3280132 -> 0000153ec2fe39ef ?
warp .. -2738044 cycles, ... 00001542b6d5c7bd -> 00001542b6ac0041 ?
warp .. -2738056 cycles, ... 0000154332e5f8dd -> 0000154332bc3155 ?
warp .. -2738059 cycles, ... 000015433aa0e85b -> 000015433a7720d0 ?
warp .. -2738087 cycles, ... 0000154363eb9eb5 -> 0000154363c1d70e ?
warp .. -2738100 cycles, ... 00001547a3407554 -> 00001547a316ada0 ?
warp .. -2738101 cycles, ... 00001547a342315e -> 00001547a31869a9 ?
warp .. -2738131 cycles, ... 00001547a36dca74 -> 00001547a34402a1 ?
warp .. -2738251 cycles, ... 00001547a67672fd -> 00001547a64caab2 ?
warp .. -2738253 cycles, ... 0000154811d20a22 -> 0000154811a841d5 ?
warp .. -2738261 cycles, ... 00001548bd4fe888 -> 00001548bd262033 ?
warp .. -2738270 cycles, ... 00001549e8ba9459 -> 00001549e890cbfb ?
warp .. -2738284 cycles, ... 0000154bca42c59f -> 0000154bca18fd33 ?
warp .. -2738287 cycles, ... 0000154c15d10b04 -> 0000154c15a74295 ?
warp .. -2738393 cycles, ... 00001559054f8a3b -> 000015590525c162 ?
warp .. -2738445 cycles, ... 00001559055cd294 -> 0000155905330987 ?
warp .. -2738462 cycles, ... 00001559057d79e3 -> 000015590553b0c5 ?
warp .. -2738482 cycles, ... 00001559221f9b08 -> 0000155921f5d1d6 ?
warp .. -2738486 cycles, ... 000015593f6a2298 -> 000015593f405962 ?
warp .. -2738602 cycles, ... 000015594da97b42 -> 000015594d7fb198 ?
warp .. -2738607 cycles, ... 0000155a41e90e62 -> 0000155a41bf44b3 ?
warp .. -2738621 cycles, ... 0000155e0f15910d -> 0000155e0eebc750 ?
warp .. -2738650 cycles, ... 0000155f746123f6 -> 0000155f74375a1c ?
warp .. -2738653 cycles, ... 000015610cbc0276 -> 000015610c923899 ?
warp .. -2738655 cycles, ... 0000156241a4f73a -> 00001562417b2d5b ?
Now with
cat /sys/devices/system/clocksource/clocksource0/clocksource
*acpi_pm jiffies tsc pit
[hacked Jack with gettimeofday works fine]
# ./time-warp-test
#CPUs: 2
running 2 tasks to check for time-warps.
warp .. -2709892 cycles, ... 000015870e3c5333 -> 000015870e12f9af ?
warp .. -2709931 cycles, ... 000015870e611d33 -> 000015870e37c388 ?
warp .. -2714592 cycles, ... 000015871b20ef38 -> 000015871af78358 ?
warp .. -2714599 cycles, ... 0000158727b08141 -> 000015872787155a ?
warp .. -2714610 cycles, ... 00001587341f8c9c -> 0000158733f620aa ?
warp .. -2714611 cycles, ... 0000158740a746a4 -> 00001587407ddab1 ?
warp .. -2714632 cycles, ... 000015874d202559 -> 000015874cf6b951 ?
warp .. -2714672 cycles, ... 000015875aa36481 -> 000015875a79f851 ?
warp .. -2714674 cycles, ... 000015876eabae9b -> 000015876e824269 ?
warp .. -2714676 cycles, ... 0000158c00b9eec1 -> 0000158c0090828d ?
warp .. -2714851 cycles, ... 000015a87d87fdf7 -> 000015a87d5e9114 ?
warp .. -2714868 cycles, ... 000015a91f8611c6 -> 000015a91f5ca4d2 ?
warp .. -2714900 cycles, ... 000015d4abcac875 -> 000015d4aba15b61 ?
warp .. -2714932 cycles, ... 000016722ed1bafe -> 000016722ea84dca ?
warp .. -2714933 cycles, ... 000016722edb5d24 -> 000016722eb1efef ?
warp .. -2714960 cycles, ... 000016722edf16d0 -> 000016722eb5a980 ?
warp .. -2715093 cycles, ... 0000167241711403 -> 000016724147a62e ?
warp .. -2715369 cycles, ... 0000167254f44d20 -> 0000167254cade37 ?
warp .. -2715372 cycles, ... 000016727c056ff2 -> 000016727bdc0106 ?
warp .. -2715382 cycles, ... 0000167294580d33 -> 00001672942e9e3d ?
warp .. -2715386 cycles, ... 00001672acf231c5 -> 00001672acc8c2cb ?
warp .. -2715394 cycles, ... 00001672c5a30efc -> 00001672c5799ffa ?
warp .. -2715397 cycles, ... 00001672f3946ebc -> 00001672f36affb7 ?
warp .. -2715417 cycles, ... 000016733b4806b8 -> 000016733b1e979f ?
warp .. -2715464 cycles, ... 00001675810adae0 -> 0000167580e16b98 ?
warp .. -2715471 cycles, ... 0000174825657d7a -> 00001748253c0e2b ?
I both cases messages seem to come in bunches. I get 5 to 15 on startup
of the test no matter what. After that it is more sporadic.
-- Fernando
On Mon, 2005-11-21 at 23:19 +0100, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <[email protected]> wrote:
>
> > On Tue, 2005-11-15 at 10:08 +0100, Ingo Molnar wrote:
> > > i have released the 2.6.14-rt13 tree, which can be downloaded from the
> > > usual place:
> > >
> > > http://redhat.com/~mingo/realtime-preempt/
> > >
> > > lots of fixes in this release affecting all supported architectures, all
> > > across the board. Big MIPS update from John Cooper.
> >
> > Can someone tell me if 2.6.14-rt13 is supposed to be fixed re: the
> > problems I was having with random screensaver triggering and keyboard
> > repeats?
> >
> > It is apparently not fixed.
> >
> > I just had a short burst of key repeats and saw one random screen
> > blank. Right now everything seems normal but I was not allucinating
> > :-)
>
> is this on the dual-core X2 box, running 32-bit code? Did it happen with
> idle=poll? Without idle=poll the TSCs run apart and a number of
> artifacts may happen. With idle=poll specified the TSC _should_ be fully
> synchronized.
>
> To make sure could you run the attached time-warp-test utility i wrote
> today? Compile it with:
>
> gcc -Wall -O2 -o time-warp-test time-warp-test.c
>
> it detects and reports time-warps (and does a maximum search for them
> over time, that way you can see systematic drifts too). (It auto-detects
> the # of CPUs and runs the appropriate number of tasks.)
>
> running this tool on a X2 with idle=poll and an -rt kernel should give a
> silent test-output.
>
> running a vanilla kernel should give TSC level time warps:
>
> #CPUs: 2
> running 2 tasks to check for time-warps.
> warp .. -1 cycles, ... 00000277ed9520c6 -> 00000277ed9520c5 ?
> warp .. -18 cycles, ... 00000277ed97ac77 -> 00000277ed97ac65 ?
> warp .. -19 cycles, ... 00000277edaedd54 -> 00000277edaedd41 ?
> warp .. -84 cycles, ... 00000277ede0558a -> 00000277ede05536 ?
> warp .. -97 cycles, ... 00000278035328a5 -> 0000027803532844 ?
> warp .. -224 cycles, ... 000002781ed2db04 -> 000002781ed2da24 ?
>
> (because the vanilla kernel doesnt do TSC synchronization accurately)
>
> running it without idle=poll should give some really big time warps:
>
> neptune:~> ./time-warp-test
> #CPUs: 2
> running 2 tasks to check for time-warps.
> warp .. -435934 cycles, ... 00000101a2db4a8f -> 00000101a2d4a3b1 ?
> WARP .. -123 usecs, .... 0003e96c2f3bb579 -> 0003e96c2f3bb4fe ?
> WARP .. -198 usecs, .... 0003e96c2f3bb625 -> 0003e96c2f3bb55f ?
> WARP .. -199 usecs, .... 0003e96c2f3bb659 -> 0003e96c2f3bb592 ?
> warp .. -436117 cycles, ... 00000101a2e5aaf0 -> 00000101a2df035b ?
> warp .. -437143 cycles, ... 00000101a2e84590 -> 00000101a2e199f9 ?
> warp .. -437314 cycles, ... 00000101a2ead1b1 -> 00000101a2e4256f ?
> warp .. -437363 cycles, ... 00000101a2ed9b19 -> 00000101a2e6eea6 ?
> WARP .. -1951680 usecs, .... 0003e96c2f597f70 -> 0003e96c2f3bb7b0 ?
> WARP .. -1951879 usecs, .... 0003e96c2f598016 -> 0003e96c2f3bb78f ?
> WARP .. -1951681 usecs, .... 0003e96c2f598014 -> 0003e96c2f3bb853 ?
> warp .. -437365 cycles, ... 00000101a4c5be7b -> 00000101a4bf1206 ?
> warp .. -437366 cycles, ... 00000101a8f4af76 -> 00000101a8ee0300 ?
> warp .. -437367 cycles, ... 00000101a968a34a -> 00000101a961f6d3 ?
>
> these time warps will get worse over time - as the two cores drift
> apart. (note that they wont drift during the test itself, because the
> test makes all cores artificially busy and the X2 TSC drifting depends
> on the core being idle)
I believe this is the same dual-core TSC drift that has been seen w/
x86-64. I have just added some similar logic to the TSC clocksource that
mimics what x86-64 does so an alternative clocksource will be selected
automatically.
I should be sending out another release later tonight with these
updates.
thanks
-john
On Mon, 21 Nov 2005, Ingo Molnar wrote:
>
> but in any case, -rt13 should be silent and there should be no time
> warps. If there are any then those could cause the keyboard repeat
> problems.
>
Hi Ingo,
I'm running -rt13 with the following command line:
root=/dev/md0 ro console=ttyS0,115200 console=tty0 nmi_watchdog=2 lapic
earlyprintk=ttyS0,115200 idle=poll
I just got the following output:
$ ./time-warp-test
#CPUs: 2
running 2 tasks to check for time-warps.
warp .. -5 cycles, ... 0000004fc2ab2b7f -> 0000004fc2ab2b7a ?
warp .. -12 cycles, ... 000000506d1d558c -> 000000506d1d5580 ?
warp .. -97 cycles, ... 000000536c8868d3 -> 000000536c886872 ?
warp .. -99 cycles, ... 00000059ae9d49a1 -> 00000059ae9d493e ?
warp .. -110 cycles, ... 00000059ed0f05d6 -> 00000059ed0f0568 ?
warp .. -118 cycles, ... 0000007392963142 -> 00000073929630cc ?
warp .. -122 cycles, ... 0000007d6a94bc76 -> 0000007d6a94bbfc ?
warp .. -346 cycles, ... 0000008acf28a18e -> 0000008acf28a034 ?
warp .. -390 cycles, ... 0000008b2fc61fef -> 0000008b2fc61e69 ?
-- Steve
On Mon, 2005-11-21 at 15:41 -0800, john stultz wrote:
> I believe this is the same dual-core TSC drift that has been seen w/
> x86-64. I have just added some similar logic to the TSC clocksource
> that mimics what x86-64 does so an alternative clocksource will be
> selected automatically.
>
> I should be sending out another release later tonight with these
> updates.
>
It is really unfortunate that the TSC cannot be used for timekeeping on
these machines. I wrote a simple benchmark that shows rdtsc on
Fernando's box to be insanely fast - 10000 iterations in 68
microseconds. This was an order of magnitude faster than any other
machine we tested. Why would they bother making it so fast if it's
useless for timekeeping?
Lee
* Steven Rostedt <[email protected]> wrote:
> Hi Ingo,
>
> I'm running -rt13 with the following command line:
>
> root=/dev/md0 ro console=ttyS0,115200 console=tty0 nmi_watchdog=2 lapic
> earlyprintk=ttyS0,115200 idle=poll
>
> I just got the following output:
>
> $ ./time-warp-test
> #CPUs: 2
> running 2 tasks to check for time-warps.
> warp .. -5 cycles, ... 0000004fc2ab2b7f -> 0000004fc2ab2b7a ?
> warp .. -12 cycles, ... 000000506d1d558c -> 000000506d1d5580 ?
> warp .. -97 cycles, ... 000000536c8868d3 -> 000000536c886872 ?
> warp .. -99 cycles, ... 00000059ae9d49a1 -> 00000059ae9d493e ?
> warp .. -110 cycles, ... 00000059ed0f05d6 -> 00000059ed0f0568 ?
> warp .. -118 cycles, ... 0000007392963142 -> 00000073929630cc ?
> warp .. -122 cycles, ... 0000007d6a94bc76 -> 0000007d6a94bbfc ?
> warp .. -346 cycles, ... 0000008acf28a18e -> 0000008acf28a034 ?
> warp .. -390 cycles, ... 0000008b2fc61fef -> 0000008b2fc61e69 ?
i've attached an updated utility below. But i too can see similar output
on an X2. A TSC-warp of 390 cycles _might_ be OK, but there are no
guarantees. It wont show up as a usecs-level (i.e. gettimeofday()) warp,
because 390 cycles is still much lower than the ~2000 cycles one
microsecond takes, but it could cause problems for other TSC users.
Basically if there is an observable and provable warp in the TSC output
then it must not be used for any purpose that is not strictly
per-CPU-ified (such as userspace threads bound to a single CPU, and the
TSC never used between threads).
Ingo
---------{ time-warp-test.c }--------->
/*
* Copyright (C) 2005, Ingo Molnar
*
* time-warp-test.c: check TSC synchronity on x86 CPUs. Also detects
* gettimeofday()-level time warps.
*/
#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <signal.h>
#include <sys/wait.h>
#include <linux/unistd.h>
#include <unistd.h>
#include <string.h>
#include <pwd.h>
#include <grp.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/time.h>
#include <regex.h>
#include <fcntl.h>
#include <time.h>
#include <sys/mman.h>
#include <dlfcn.h>
#include <popt.h>
#include <sys/socket.h>
#include <ctype.h>
#include <assert.h>
#include <sched.h>
#define TEST_TSC 1
#define TEST_TOD 1
#if !TEST_TSC && !TEST_TOD
# error this makes no sense ...
#endif
#if DEBUG
# define Printf(x...) printf(x)
#else
# define Printf(x...) do { } while (0)
#endif
/*
* Shared locks and variables between the test tasks:
*/
enum {
SHARED_TSC = 0,
SHARED_LOCK = 2,
SHARED_TOD = 3,
SHARED_WORST_TSC = 5,
SHARED_WORST_TOD = 7,
SHARED_NR_TSC_WARPS = 9,
SHARED_NR_TOD_WARPS = 10,
};
#define SHARED(x) (*(shared + SHARED_##x))
#define SHARED_LL(x) (*(long long *)(shared + SHARED_##x))
#define BUG_ON(c) assert(!(c))
typedef unsigned long long cycles_t;
typedef unsigned long long usecs_t;
#define rdtscll(val) \
do { \
__asm__ __volatile__("rdtsc" : "=A" (val)); \
} while (0)
#define rdtod(val) \
do { \
struct timeval tv; \
\
gettimeofday(&tv, NULL); \
(val) = tv.tv_sec * 1000000LL + tv.tv_usec; \
} while (0)
static unsigned long *setup_shared_var(void)
{
char zerobuff [4096] = { 0, };
int ret, fd;
unsigned long *buf;
fd = creat(".tmp_mmap", 0700);
BUG_ON(fd == -1);
close(fd);
fd = open(".tmp_mmap", O_RDWR|O_CREAT|O_TRUNC);
BUG_ON(fd == -1);
ret = write(fd, zerobuff, 4096);
BUG_ON(ret != 4096);
buf = (void *)mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
BUG_ON(buf == (void *)-1);
close(fd);
return buf;
}
#define LOOPS 1000000
static inline unsigned long
cmpxchg(volatile unsigned long *ptr, unsigned long old, unsigned long new)
{
unsigned long prev;
__asm__ __volatile__("lock; cmpxchg %b1,%2"
: "=a"(prev)
: "q"(new), "m"(*(ptr)), "0"(old)
: "memory");
return prev;
}
static inline void lock(unsigned long *flag)
{
while (cmpxchg(flag, 0, 1) != 0)
/* nothing */;
}
static inline void unlock(unsigned long *flag)
{
*flag = 0;
}
static void print_status(unsigned long *shared)
{
const char progress[] = "\\|/-";
static usecs_t prev_tod;
static int count1, count2;
usecs_t tod;
count1++;
if (count1 < 1000)
return;
count1 = 0;
rdtod(tod);
if (tod - prev_tod < 100000ULL)
return;
prev_tod = tod;
count2++;
if (TEST_TSC)
printf("| # of TSC-warps:%ld", SHARED(NR_TSC_WARPS));
if (TEST_TOD)
printf(" | # of TOD-warps:%ld", SHARED(NR_TOD_WARPS));
printf(" %c\r", progress[count2 & 3]);
fflush(stdout);
}
static inline void test_TSC(unsigned long *shared)
{
#if TEST_TSC
cycles_t t0, t1;
long long delta;
lock(&SHARED(LOCK));
rdtscll(t1);
t0 = SHARED_LL(TSC);
SHARED_LL(TSC) = t1;
delta = t1-t0;
if (delta < 0) {
SHARED(NR_TSC_WARPS)++;
if (delta < SHARED_LL(WORST_TSC)) {
SHARED_LL(WORST_TSC) = delta;
fprintf(stderr, "\rnew TSC-warp maximum: %9Ld cycles, %016Lx -> %016Lx\n",
delta, t0, t1);
}
}
unlock(&SHARED(LOCK));
#endif
}
static inline void test_TOD(unsigned long *shared)
{
#if TEST_TOD
usecs_t T0, T1;
long long delta;
lock(&SHARED(LOCK));
rdtod(T1);
T0 = SHARED_LL(TOD);
SHARED_LL(TOD) = T1;
delta = T1-T0;
if (delta < 0) {
SHARED(NR_TOD_WARPS)++;
if (delta < SHARED_LL(WORST_TOD)) {
SHARED_LL(WORST_TOD) = delta;
fprintf(stderr, "\rnew TOD-warp maximum: %9Ld usecs, %016Lx -> %016Lx\n",
delta, T0, T1);
}
}
unlock(&SHARED(LOCK));
#endif
}
int main(int argc, char **argv)
{
int i, parent, me;
unsigned long *shared;
unsigned long cpus, tasks;
cpus = system("exit `grep processor /proc/cpuinfo | wc -l`");
cpus = WEXITSTATUS(cpus);
if (argc > 2) {
usage:
fprintf(stderr,
"usage: tsc-sync-test <threads>\n");
exit(-1);
}
if (argc == 2) {
tasks = atol(argv[1]);
if (!tasks)
goto usage;
} else
tasks = cpus;
printf("%ld CPUs, running %ld parallel test-tasks.\n", cpus, tasks);
printf("checking for time-warps via:\n"
#if TEST_TSC
"- read time stamp counter (RDTSC) instruction (cycle resolution)\n"
#endif
#if TEST_TOD
"- gettimeofday (TOD) syscall (usec resolution)\n"
#endif
"\n"
);
shared = setup_shared_var();
parent = getpid();
for (i = 1; i < tasks; i++)
if (!fork())
break;
me = getpid();
while (1) {
test_TSC(shared);
test_TOD(shared);
if (me == parent)
print_status(shared);
}
return 0;
}
On Tue, 2005-11-22 at 12:16 +0100, Ingo Molnar wrote:
> * Steven Rostedt <[email protected]> wrote:
>
> > Hi Ingo,
> >
> > I'm running -rt13 with the following command line:
> >
> > root=/dev/md0 ro console=ttyS0,115200 console=tty0 nmi_watchdog=2 lapic
> > earlyprintk=ttyS0,115200 idle=poll
> >
> > I just got the following output:
> >
> > $ ./time-warp-test
> > #CPUs: 2
> > running 2 tasks to check for time-warps.
> > warp .. -5 cycles, ... 0000004fc2ab2b7f -> 0000004fc2ab2b7a ?
> > warp .. -12 cycles, ... 000000506d1d558c -> 000000506d1d5580 ?
> > warp .. -97 cycles, ... 000000536c8868d3 -> 000000536c886872 ?
> > warp .. -99 cycles, ... 00000059ae9d49a1 -> 00000059ae9d493e ?
> > warp .. -110 cycles, ... 00000059ed0f05d6 -> 00000059ed0f0568 ?
> > warp .. -118 cycles, ... 0000007392963142 -> 00000073929630cc ?
> > warp .. -122 cycles, ... 0000007d6a94bc76 -> 0000007d6a94bbfc ?
> > warp .. -346 cycles, ... 0000008acf28a18e -> 0000008acf28a034 ?
> > warp .. -390 cycles, ... 0000008b2fc61fef -> 0000008b2fc61e69 ?
>
> i've attached an updated utility below.
I'm adding a run with:
echo "tsc"> /sys/devices/system/clocksource/clocksource0/clocksource
_not_ booted with idle=poll
at the end of this email.
> But i too can see similar output
> on an X2. A TSC-warp of 390 cycles _might_ be OK, but there are no
> guarantees.
In my experience the amount seems to be related to how long the system
has been up. Which is to be expected if the two TSCs drift, right?
> It wont show up as a usecs-level (i.e. gettimeofday()) warp,
> because 390 cycles is still much lower than the ~2000 cycles one
> microsecond takes, but it could cause problems for other TSC users.
>
> Basically if there is an observable and provable warp in the TSC output
> then it must not be used for any purpose that is not strictly
> per-CPU-ified (such as userspace threads bound to a single CPU, and the
> TSC never used between threads).
Apparently that's the case.
John Stultz just released a new version of his patch that takes care of
not using the TSC as a time source on X2's. Hopefully that will make its
way to the -rt patches soon :-) This would take care of the key repeat /
screensaver problems (I just saw a post yesterday on linux-audio-user
about someone else on an X2 processor having the same problems), Jack
will need a patch to use gettimeofday in those cases.
Is /sys/devices/system/clocksource/clocksource0/clocksource part of the
standard kernel tree? I was thinking on using that for the Jack patch to
decide whether to use tsc or not (ie: if it is good enough for the
kernel it should be good enough for Jack).
To all involved, a big _THANKS_ for helping track this very annoying
problem!
-- Fernando
# time ./time-warp
2 CPUs, running 2 parallel test-tasks.
checking for time-warps via:
- read time stamp counter (RDTSC) instruction (cycle resolution)
- gettimeofday (TOD) syscall (usec resolution)
new TOD-warp maximum: -4398046507 usecs, 0004062bea76af5b ->
0004062ae451d230
new TSC-warp maximum: -3122849 cycles, 00009a5f725821a3 ->
00009a5f72287b02
new TSC-warp maximum: -3123428 cycles, 00009a5f725b26a8 ->
00009a5f722b7dc4
new TSC-warp maximum: -3123690 cycles, 00009a60ccc01765 ->
00009a60cc906d7b
new TSC-warp maximum: -3123793 cycles, 00009a61a5897c78 ->
00009a61a559d227
new TSC-warp maximum: -3123965 cycles, 00009a68b7481924 ->
00009a68b7186e27
new TSC-warp maximum: -3123966 cycles, 00009a68b754b37b ->
00009a68b725087d
new TSC-warp maximum: -3124141 cycles, 00009a68c003e8ee ->
00009a68bfd43d41
new TSC-warp maximum: -3124253 cycles, 00009a68c8b511d9 ->
00009a68c88565bc
new TSC-warp maximum: -3124268 cycles, 00009a68d2bcaaad ->
00009a68d28cfe81
new TSC-warp maximum: -3124269 cycles, 00009a68eedd440e ->
00009a68eead97e1
new TSC-warp maximum: -3124280 cycles, 00009a68eefefe95 ->
00009a68eecf525d
new TSC-warp maximum: -3124342 cycles, 00009a6907369ac7 ->
00009a690706ee51
new TSC-warp maximum: -3124592 cycles, 00009a69147b7019 ->
00009a69144bc2a9
new TSC-warp maximum: -3124609 cycles, 00009a69aa0dd745 ->
00009a69a9de29c4
new TSC-warp maximum: -3124637 cycles, 00009a69df64a2ff ->
00009a69df34f562
new TSC-warp maximum: -3124652 cycles, 00009a6a649d4a10 ->
00009a6a646d9c64
new TSC-warp maximum: -3124663 cycles, 00009a6ad73c29e2 ->
00009a6ad70c7c2b
new TSC-warp maximum: -3124699 cycles, 00009af351a28fbb ->
00009af35172e1e0
| # of TSC-warps:185478076 | # of TOD-warps:185477650 \
real 6m58.633s
user 5m17.436s
sys 1m27.135s
Fernando Lopez-Lezcano wrote:
>>Basically if there is an observable and provable warp in the TSC output
>>then it must not be used for any purpose that is not strictly
>>per-CPU-ified (such as userspace threads bound to a single CPU, and the
>>TSC never used between threads).
> Apparently that's the case.
What about periodically re-syncing the TSCs on the cpus? Are they
writeable?
Chris
On Tue, 22 Nov 2005, Christopher Friesen wrote:
> Fernando Lopez-Lezcano wrote:
>
> >>Basically if there is an observable and provable warp in the TSC output
> >>then it must not be used for any purpose that is not strictly
> >>per-CPU-ified (such as userspace threads bound to a single CPU, and the
> >>TSC never used between threads).
>
> > Apparently that's the case.
>
> What about periodically re-syncing the TSCs on the cpus? Are they
> writeable?
>
I believe you can reset them to zero, but I don't think you can set them
to anything else. I had to do something similar a few years ago, and I
don't have the specs in front of me, so this is coming straight from
memory.
Even if you could reset them, it would be very difficult to make all CPUs
have the same counter. Not to mention that this would also screw up all
timings elsewhere when the sync happens. Remember, this would have to work
not just on 2 cpus, but 4, 8 and beyond.
-- Steve
* Steven Rostedt <[email protected]> wrote:
> > > Apparently that's the case.
> >
> > What about periodically re-syncing the TSCs on the cpus? Are they
> > writeable?
>
> I believe you can reset them to zero, but I don't think you can set
> them to anything else. I had to do something similar a few years ago,
> and I don't have the specs in front of me, so this is coming straight
> from memory.
on a reasonably new CPU you ought to be able to set the 64-bit value -
but that doesnt change the fundamental fact: we have no idea how much
time has passed while we were in HLT. Especially with things like
dyntick/noidle we could spend _alot_ of time in HLT, and the TSC could
drift significantly. How do we know how much that is?
Ingo