Scheduler latency measurements on 2.6.11.6
From: Willy TARREAU
Date: Mon Mar 28 2005 - 09:18:11 EST
Hi Ingo,
I've done some experiences with the 2.6 scheduler on 2.6.11.6 to try
to reproduce the very high latencies I encountered on some network
related programs which run on FC2 with 2.6.5-something.
The program which seems to be the most affected is an HTTP load
generator which I use as a stress-tester to push firewalls an
load-balancers to their limits, with a Tux on the other side to
achieve very high loads (and I guess you understand what "very high
load" can mean with Tux :-))
The program basically schedules connections around a select() loop.
It's available on my site for reference, see below[1]. Under high
loads (between 20k and 50k hits per second), the program eats all the
CPU because select() is called with very short timeouts, and everytime
it wakes up, there is some work to do. That's expected and not a
problem. The program tries to display injection statistics every 1000
ms precisely, and also displays how much time was really elapsed since
the last stat occurrence.
Under 2.6, if there is any small activity on the machine, the time
between two stats increases considerably, which means that the program
regularly freezes. I have observed several freezes of more than 13
seconds while I was running a simple "while :;do :;done" on another
console. Delays between 3 and 9 seconds are very common if I start any
cpu-hungry program.
Under 2.4, I only observe a few tens of ms, and at most a few hundreds
ms if the CPU is busy.
So I wrote a simple program to try to detect freezes within in a loop,
and uses select() to sleep for 1 ms and measures the time really
elapsed.
The first version (attached below) mesures the time spent in a loop
like this :
while(1) {
x=now();
for (volatile x=0; x<iterations; x++);
y=now();
select(0,0,0,0, 1ms);
z=now();
print loop=y-x, select=z-y;
}
I start one instance of this program with 20 millions iterations per
loop, then another one with 10 millions iterations per loop. What is
observed is that the first one takes about 50 ms for the for() loop,
and about 800 us for the select(). The second one takes about 25 ms
for the for() loop and about 800 ms for the select(), which is
consistent with the first one given the fact that it does half the
number of iterations in the for() loop.
Now, if I start the second program just after the first one, the first
one takes about 2.1 seconds to complete the for() loop during which
the second one runs at full speed. Then, the first one progresses
slowly, by jumps of about 120-950 ms while the second one gets more
regular CPU with progress every 25-75 ms.
As I was not sure whether the freezes were cumulated or at one time,
I modified the program (lat2 then lat3) [3], to measure the time
elapsed between two consecutive calls to gettimeofday().
The result is rather interesting [5]. Basically, the program did the
following :
while(1) {
x = now(); max = 0;
do {
y = now;
max = MAX(max, now() - y);
} while (y-x < atol(argv[1]));
select(0,0,0,0, 1ms);
z=now();
print select=z-y , loop=y-x, max;
}
Now we observe that running just this with only a "while :;do :;done"
in parallel exhibits 'max' values of about 2.1 seconds, which means
that the 'do()...while' loop has totally stopped for 2.1 seconds when
the second process started. The second test was done with 2
simultaneous shell loops, and the program froze for 3.1 seconds.
Latest test with lat3 also showed the number of iterations which took
more than 10 ms. It clearly shows that the loop is very smooth, except
for one iteration which takes 2.5 second. If I increase the loop time
to 1 second, the two simultaneous processes mutually hinder with
latencies of 1 second each, as shown in [6], sorted by date.
Looking at kernel/sched.c, I understood that the timeslices are set to
100 ms by default, and can grow as high as 800 ms for nice -19 and
shrink as low as 5 ms for nice +20. Playing with nice on any of the
processes showed this exact overall latency during the test, except
at start, where the behaviour was different : at nice +10, the latency
slowly increased from 50ms to 800ms instead of starting at 2 seconds
then decaying [7].
Starting the two processes at nice +15 exhibit a rather stable latency
starting at 25 ms, and quickly stabilizing to 50 ms. At nice +16, the,
latency is perfectly stable at 20ms from the beginning to the end, and
at +18, it goes down to 10 ms. At nice +20, they both keep stable at
5 ms. So now I'm wondering :
- what causes the initial high latency peak when I start a process
at nice +0, and what can be done about it (a freeze of 2 seconds
is rather annoying)
- it seems that renicing all processes to +16 protects from high
latencies. Maybe this could be an acceptable workaround for
network-only applications, but I have no idea about the side
effects this could bring (interactivity, etc...).
Any hint would be much appreciated since on some testing machines
(including notebook), this is clearly what makes me stick to 2.4.
Best regards,
Willy
--------
Appendix
--------
[0] reports and programs available at http://w.ods.org/linux/sched/
[1] HTTP traffic generator http://w.ods.org/tools/inject/
==================================================
[2] lat.c : first version of the latency program.
==================================================
#include <stdio.h>
#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <unistd.h>
unsigned long long tv_diff(struct timeval *tv1, struct timeval *tv2) {
unsigned long long ret;
ret = ((unsigned long long)(tv2->tv_sec - tv1->tv_sec)) * 1000000ULL;
if (tv2->tv_usec > tv1->tv_usec)
ret += (tv2->tv_usec - tv1->tv_usec);
else
ret -= (tv1->tv_usec - tv2->tv_usec);
return ret;
}
main(int argc, char **argv) {
struct timeval tv1, tv2, tv3, wait;
int loops;
if (argc > 1)
loops = atol(argv[1]);
else
loops = 50000000;
memset(&tv1, 0, sizeof(tv1));
memset(&tv2, 0, sizeof(tv2));
memset(&tv3, 0, sizeof(tv3));
gettimeofday(&tv1, NULL);
while (1) {
volatile i;
gettimeofday(&tv2, NULL);
for (i=0; i<loops; i++);
gettimeofday(&tv3, NULL);
printf("date=%lu.%06lu, user=%10lld us, wait=%10lld us\n",
tv3.tv_sec, tv3.tv_usec,
tv_diff(&tv2, &tv3), tv_diff(&tv1, &tv2));
wait.tv_sec = 0;
wait.tv_usec = 1000;
gettimeofday(&tv1, NULL);
select(0, NULL, NULL, NULL, &wait);
}
}
==================================================
[3] lat3.c : third version of the latency program.
==================================================
#include <stdio.h>
#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <unistd.h>
unsigned long long tv_diff(struct timeval *tv1, struct timeval *tv2) {
unsigned long long ret;
ret = ((unsigned long long)(tv2->tv_sec - tv1->tv_sec)) * 1000000ULL;
if (tv2->tv_usec > tv1->tv_usec)
ret += (tv2->tv_usec - tv1->tv_usec);
else
ret -= (tv1->tv_usec - tv2->tv_usec);
return ret;
}
main(int argc, char **argv) {
struct timeval tv1, tv2, tv3, tv4, wait;
int loops;
if (argc > 1)
loops = atol(argv[1]);
else
loops = 100000;
memset(&tv1, 0, sizeof(tv1)); memset(&tv2, 0, sizeof(tv2));
memset(&tv3, 0, sizeof(tv3)); memset(&tv4, 0, sizeof(tv4));
printf("Date_sec.msec select loop maxlat nbmax\n");
gettimeofday(&tv1, NULL);
while (1) {
int i, max, times;
gettimeofday(&tv2, NULL);
tv4 = tv2;
max = 0; times = 0;
do {
gettimeofday(&tv3, NULL);
i = tv_diff(&tv4, &tv3);
if (i > max)
max = i;
if (i > 10000)
times++;
tv4 = tv3;
i = tv_diff(&tv2, &tv3);
} while (i < loops);
printf("%lu.%03lu %7lld %7lld %7d %7d\n",
tv3.tv_sec, tv3.tv_usec/1000,
tv_diff(&tv1, &tv2), tv_diff(&tv2, &tv3),
max, times);
wait.tv_sec = 0;
wait.tv_usec = 1000;
gettimeofday(&tv1, NULL);
select(0, NULL, NULL, NULL, &wait);
}
}
==================================================
[4] latencies report on first test with 2 'lat' instances run in
parallel
==================================================
P:-- = process 1 : ./lat 20000000, started at 1111993713.241839
P:** = process 2 : ./lat 10000000, started at 1111993714.549886
P system time time spent time spent
tv_sec.tv_usec in loop in select()
-- 1111993713.241839, user= 49421 us, wait= 456 us
-- 1111993713.291499, user= 49089 us, wait= 410 us
-- 1111993713.341838, user= 49435 us, wait= 744 us
-- 1111993713.391437, user= 49042 us, wait= 396 us
-- 1111993713.441843, user= 49455 us, wait= 791 us
-- 1111993713.490587, user= 48207 us, wait= 377 us
-- 1111993713.540792, user= 49419 us, wait= 625 us
-- 1111993713.592292, user= 50927 us, wait= 413 us
-- 1111993713.643759, user= 50402 us, wait= 890 us
-- 1111993713.693417, user= 49068 us, wait= 427 us
-- 1111993713.744553, user= 50211 us, wait= 764 us
-- 1111993713.794794, user= 49460 us, wait= 620 us
-- 1111993713.844748, user= 49422 us, wait= 372 us
-- 1111993713.894778, user= 49459 us, wait= 411 us
-- 1111993713.944731, user= 49420 us, wait= 373 us
-- 1111993713.994919, user= 49615 us, wait= 413 us
-- 1111993714.043893, user= 48597 us, wait= 215 us
-- 1111993714.093461, user= 49172 us, wait= 236 us
-- 1111993714.144210, user= 49929 us, wait= 659 us
-- 1111993714.194733, user= 49460 us, wait= 889 us
-- 1111993714.244725, user= 49459 us, wait= 373 us
-- 1111993714.294754, user= 49496 us, wait= 373 us
-- 1111993714.344672, user= 49422 us, wait= 337 us
-- 1111993714.394704, user= 49461 us, wait= 412 us
-- 1111993714.444655, user= 49420 us, wait= 371 us
-- 1111993714.494687, user= 49459 us, wait= 413 us
** 1111993714.549886, user= 24833 us, wait= 0 us
** 1111993714.575477, user= 25267 us, wait= 289 us
** 1111993714.600950, user= 24744 us, wait= 569 us
** 1111993714.626437, user= 25235 us, wait= 94 us
** 1111993714.651910, user= 24712 us, wait= 601 us
** 1111993714.676941, user= 24747 us, wait= 126 us
** 1111993714.701902, user= 24712 us, wait= 92 us
** 1111993714.726043, user= 23856 us, wait= 127 us
** 1111993714.751503, user= 24320 us, wait= 972 us
** 1111993714.776508, user= 24329 us, wait= 518 us
** 1111993714.801897, user= 24722 us, wait= 510 us
** 1111993714.827284, user= 25104 us, wait= 125 us
** 1111993714.852452, user= 24285 us, wait= 725 us
** 1111993714.877947, user= 24783 us, wait= 555 us
** 1111993714.902449, user= 24286 us, wait= 58 us
** 1111993714.927864, user= 24708 us, wait= 550 us
** 1111993714.952864, user= 24712 us, wait= 130 us
** 1111993714.977897, user= 24749 us, wait= 127 us
** 1111993715.002856, user= 24711 us, wait= 90 us
** 1111993715.027851, user= 24710 us, wait= 128 us
** 1111993715.052890, user= 24753 us, wait= 129 us
** 1111993715.078392, user= 25259 us, wait= 85 us
** 1111993715.103840, user= 24711 us, wait= 579 us
** 1111993715.129352, user= 25227 us, wait= 128 us
** 1111993715.154834, user= 24712 us, wait= 611 us
** 1111993715.179867, user= 24749 us, wait= 126 us
** 1111993715.204825, user= 24710 us, wait= 91 us
** 1111993715.229818, user= 24708 us, wait= 128 us
** 1111993715.254817, user= 24710 us, wait= 132 us
** 1111993715.279850, user= 24748 us, wait= 128 us
** 1111993715.304386, user= 24286 us, wait= 93 us
** 1111993715.329805, user= 24710 us, wait= 552 us
** 1111993715.354801, user= 24709 us, wait= 130 us
** 1111993715.379837, user= 24750 us, wait= 129 us
** 1111993715.404796, user= 24712 us, wait= 90 us
** 1111993715.429788, user= 24708 us, wait= 127 us
** 1111993715.453935, user= 23858 us, wait= 132 us
** 1111993715.479831, user= 24759 us, wait= 970 us
** 1111993715.504789, user= 24720 us, wait= 81 us
** 1111993715.529347, user= 24283 us, wait= 117 us
** 1111993715.553917, user= 23852 us, wait= 561 us
** 1111993715.579859, user= 24802 us, wait= 968 us
** 1111993715.605199, user= 25145 us, wait= 37 us
** 1111993715.630842, user= 24790 us, wait= 696 us
** 1111993715.655756, user= 24711 us, wait= 44 us
** 1111993715.680790, user= 24748 us, wait= 129 us
** 1111993715.705747, user= 24709 us, wait= 91 us
** 1111993715.730744, user= 24710 us, wait= 130 us
** 1111993715.755315, user= 24285 us, wait= 129 us
** 1111993715.780777, user= 24751 us, wait= 554 us
** 1111993715.805731, user= 24708 us, wait= 88 us
** 1111993715.830730, user= 24711 us, wait= 131 us
** 1111993715.855422, user= 24407 us, wait= 128 us
** 1111993715.880562, user= 24551 us, wait= 430 us
** 1111993715.905292, user= 24285 us, wait= 283 us
** 1111993715.931150, user= 25146 us, wait= 555 us
** 1111993715.956284, user= 24284 us, wait= 693 us
** 1111993715.982182, user= 25186 us, wait= 556 us
** 1111993716.007274, user= 24282 us, wait= 653 us
** 1111993716.032748, user= 24760 us, wait= 557 us
** 1111993716.057267, user= 24283 us, wait= 78 us
** 1111993716.084110, user= 26130 us, wait= 556 us
** 1111993716.109259, user= 24283 us, wait= 708 us
** 1111993716.135627, user= 25654 us, wait= 557 us
** 1111993716.160251, user= 24282 us, wait= 183 us
** 1111993716.186151, user= 25186 us, wait= 556 us
** 1111993716.211245, user= 24284 us, wait= 652 us
** 1111993716.237102, user= 25145 us, wait= 555 us
** 1111993716.262236, user= 24283 us, wait= 694 us
** 1111993716.288133, user= 25184 us, wait= 557 us
** 1111993716.313228, user= 24283 us, wait= 655 us
** 1111993716.338236, user= 24295 us, wait= 556 us
** 1111993716.363220, user= 24282 us, wait= 545 us
** 1111993716.389121, user= 25147 us, wait= 597 us
** 1111993716.414212, user= 24282 us, wait= 651 us
** 1111993716.440071, user= 25145 us, wait= 557 us
** 1111993716.465245, user= 24323 us, wait= 694 us
** 1111993716.491065, user= 25147 us, wait= 515 us
** 1111993716.516206, user= 24292 us, wait= 693 us
** 1111993716.541620, user= 24709 us, wait= 548 us
** 1111993716.566736, user= 24826 us, wait= 133 us
** 1111993716.592614, user= 24711 us, wait= 998 us
-- 1111993716.616717, user= 2121497 us, wait= 373 us
** 1111993716.621474, user= 28575 us, wait= 129 us
** 1111993716.647549, user= 25654 us, wait= 265 us
** 1111993716.672212, user= 24321 us, wait= 182 us
** 1111993716.697596, user= 24709 us, wait= 518 us
** 1111993716.724593, user= 26707 us, wait= 132 us
** 1111993716.749588, user= 24709 us, wait= 129 us
** 1111993716.774238, user= 24360 us, wait= 133 us
** 1111993716.799581, user= 24710 us, wait= 476 us
** 1111993716.824576, user= 24708 us, wait= 131 us
-- 1111993716.874215, user= 252583 us, wait= 4730 us
** 1111993716.895877, user= 71013 us, wait= 131 us
** 1111993716.922539, user= 25686 us, wait= 819 us
** 1111993716.947132, user= 24283 us, wait= 152 us
** 1111993716.973030, user= 25185 us, wait= 556 us
** 1111993717.043543, user= 69702 us, wait= 653 us
** 1111993717.069044, user= 25213 us, wait= 130 us
** 1111993717.094537, user= 24708 us, wait= 627 us
** 1111993717.119531, user= 24708 us, wait= 129 us
-- 1111993717.129505, user= 233469 us, wait= 21658 us
** 1111993717.147968, user= 28149 us, wait= 131 us
** 1111993717.173564, user= 24749 us, wait= 689 us
** 1111993717.198520, user= 24709 us, wait= 90 us
** 1111993717.223517, user= 24710 us, wait= 131 us
-- 1111993717.281687, user= 133559 us, wait= 18460 us
** 1111993717.297538, user= 73735 us, wait= 129 us
** 1111993717.322296, user= 24504 us, wait= 98 us
** 1111993717.347534, user= 24746 us, wait= 335 us
** 1111993717.371676, user= 23892 us, wait= 93 us
** 1111993717.436345, user= 63564 us, wait= 937 us
** 1111993717.461054, user= 24283 us, wait= 269 us
** 1111993717.486111, user= 24344 us, wait= 556 us
** 1111993717.511048, user= 24283 us, wait= 497 us
-- 1111993717.538346, user= 240650 us, wait= 15838 us
** 1111993717.545901, user= 34142 us, wait= 555 us
** 1111993717.571567, user= 24813 us, wait= 697 us
** 1111993717.596896, user= 25146 us, wait= 25 us
** 1111993717.622033, user= 24283 us, wait= 697 us
-- 1111993717.689683, user= 143624 us, wait= 7553 us
** 1111993717.696456, user= 73713 us, wait= 553 us
** 1111993717.721016, user= 24285 us, wait= 118 us
** 1111993717.746437, user= 24710 us, wait= 554 us
** 1111993717.770618, user= 23891 us, wait= 133 us
** 1111993717.828860, user= 57140 us, wait= 933 us
** 1111993717.854894, user= 25182 us, wait= 695 us
** 1111993717.880028, user= 24321 us, wait= 657 us
** 1111993717.905849, user= 25146 us, wait= 518 us
-- 1111993717.944866, user= 248251 us, wait= 6757 us
** 1111993717.945532, user= 38833 us, wait= 693 us
** 1111993717.971049, user= 24356 us, wait= 992 us
** 1111993717.995973, user= 24284 us, wait= 482 us
** 1111993718.021982, user= 25296 us, wait= 557 us
** 1111993718.046967, user= 24285 us, wait= 542 us
-- 1111993718.098033, user= 152330 us, wait= 678 us
** 1111993718.121020, user= 73342 us, wait= 555 us
** 1111993718.175406, user= 24744 us, wait= 29484 us
** 1111993718.199944, user= 24286 us, wait= 92 us
** 1111993718.225799, user= 25144 us, wait= 553 us
** 1111993718.250935, user= 24284 us, wait= 694 us
** 1111993718.275976, user= 24329 us, wait= 555 us
** 1111993718.300927, user= 24284 us, wait= 509 us
** 1111993718.326794, user= 25155 us, wait= 556 us
** 1111993718.351920, user= 24285 us, wait= 683 us
** 1111993718.377816, user= 25184 us, wait= 555 us
** 1111993718.402913, user= 24285 us, wait= 654 us
** 1111993718.428769, user= 25145 us, wait= 554 us
** 1111993718.453906, user= 24285 us, wait= 695 us
** 1111993718.479362, user= 24746 us, wait= 553 us
** 1111993718.503899, user= 24283 us, wait= 96 us
** 1111993718.529317, user= 24709 us, wait= 551 us
** 1111993718.554314, user= 24708 us, wait= 132 us
** 1111993718.579420, user= 24819 us, wait= 130 us
** 1111993718.604744, user= 25146 us, wait= 20 us
** 1111993718.629880, user= 24287 us, wait= 692 us
** 1111993718.655816, user= 25227 us, wait= 552 us
-- 1111993718.670711, user= 549531 us, wait= 22985 us
** 1111993718.696319, user= 25445 us, wait= 14900 us
-- 1111993718.751516, user= 55038 us, wait= 25606 us
** 1111993718.769957, user= 68379 us, wait= 5101 us
** 1111993718.810843, user= 24277 us, wait= 16452 us
** 1111993718.836273, user= 24711 us, wait= 562 us
** 1111993718.861266, user= 24708 us, wait= 128 us
** 1111993718.885505, user= 23951 us, wait= 131 us
** 1111993718.911259, user= 24709 us, wait= 876 us
-- 1111993718.965887, user= 195771 us, wait= 18428 us
** 1111993718.967980, user= 56433 us, wait= 131 us
** 1111993718.993247, user= 24709 us, wait= 402 us
** 1111993719.020242, user= 24709 us, wait= 2129 us
** 1111993719.045284, user= 24754 us, wait= 132 us
-- 1111993719.093043, user= 124905 us, wait= 2091 us
** 1111993719.117629, user= 24422 us, wait= 47766 us
** 1111993719.144171, user= 25656 us, wait= 874 us
** 1111993719.168406, user= 23895 us, wait= 328 us
** 1111993719.193837, user= 25261 us, wait= 158 us
** 1111993719.218789, user= 24285 us, wait= 655 us
** 1111993719.244210, user= 24710 us, wait= 699 us
** 1111993719.269243, user= 24747 us, wait= 274 us
** 1111993719.294203, user= 24711 us, wait= 237 us
** 1111993719.319198, user= 24710 us, wait= 273 us
** 1111993719.344196, user= 24709 us, wait= 277 us
** 1111993719.369231, user= 24750 us, wait= 273 us
** 1111993719.394188, user= 24711 us, wait= 234 us
** 1111993719.419183, user= 24710 us, wait= 273 us
** 1111993719.444180, user= 24711 us, wait= 274 us
** 1111993719.469215, user= 24749 us, wait= 274 us
** 1111993719.494231, user= 24769 us, wait= 235 us
** 1111993719.519167, user= 24709 us, wait= 215 us
** 1111993719.559732, user= 40278 us, wait= 275 us
** 1111993719.604591, user= 25145 us, wait= 19557 us
** 1111993719.630151, user= 24710 us, wait= 838 us
** 1111993719.655665, user= 25228 us, wait= 274 us
** 1111993719.681183, user= 24750 us, wait= 755 us
** 1111993719.706141, user= 24710 us, wait= 236 us
** 1111993719.731136, user= 24710 us, wait= 273 us
** 1111993719.756131, user= 24709 us, wait= 274 us
** 1111993719.781170, user= 24752 us, wait= 276 us
** 1111993719.806124, user= 24710 us, wait= 232 us
** 1111993719.831123, user= 24712 us, wait= 276 us
** 1111993719.856116, user= 24709 us, wait= 272 us
** 1111993719.881151, user= 24748 us, wait= 276 us
** 1111993719.906111, user= 24712 us, wait= 236 us
** 1111993719.931106, user= 24711 us, wait= 272 us
** 1111993719.955249, user= 23857 us, wait= 274 us
** 1111993719.981014, user= 25597 us, wait= 156 us
** 1111993720.011092, user= 24709 us, wait= 5357 us
** 1111993720.036135, user= 24756 us, wait= 275 us
** 1111993720.061085, user= 24709 us, wait= 229 us
** 1111993720.086192, user= 24820 us, wait= 275 us
-- 1111993720.092040, user= 974252 us, wait= 24583 us
** 1111993720.116381, user= 24327 us, wait= 5850 us
** 1111993720.142154, user= 24791 us, wait= 970 us
** 1111993720.166843, user= 24484 us, wait= 192 us
** 1111993720.192568, user= 25212 us, wait= 500 us
** 1111993720.217636, user= 24284 us, wait= 772 us
** 1111993720.249493, user= 25146 us, wait= 6699 us
** 1111993720.274664, user= 24321 us, wait= 838 us
** 1111993720.300485, user= 25146 us, wait= 663 us
** 1111993720.325621, user= 24286 us, wait= 838 us
** 1111993720.351478, user= 25146 us, wait= 700 us
** 1111993720.376688, user= 24360 us, wait= 838 us
** 1111993720.402472, user= 25148 us, wait= 624 us
** 1111993720.441027, user= 24709 us, wait= 13835 us
** 1111993720.465640, user= 24323 us, wait= 278 us
** 1111993720.490168, user= 23858 us, wait= 658 us
** 1111993720.515467, user= 25132 us, wait= 155 us
** 1111993720.541013, user= 24710 us, wait= 824 us
** 1111993720.566048, user= 24749 us, wait= 275 us
** 1111993720.590924, user= 24629 us, wait= 235 us
** 1111993720.616474, user= 25183 us, wait= 355 us
** 1111993720.641659, user= 24372 us, wait= 801 us
** 1111993720.667035, user= 24748 us, wait= 616 us
** 1111993720.691564, user= 24284 us, wait= 232 us
** 1111993720.717423, user= 25147 us, wait= 700 us
** 1111993720.751980, user= 24709 us, wait= 9836 us
** 1111993720.777017, user= 24750 us, wait= 275 us
** 1111993720.801973, user= 24710 us, wait= 234 us
** 1111993720.826971, user= 24712 us, wait= 274 us
** 1111993720.851966, user= 24711 us, wait= 272 us
** 1111993720.877575, user= 25323 us, wait= 275 us
** 1111993720.902756, user= 24508 us, wait= 661 us
** 1111993720.927530, user= 24286 us, wait= 476 us
** 1111993720.965424, user= 25186 us, wait= 12696 us
** 1111993720.990519, user= 24285 us, wait= 798 us
** 1111993721.015986, user= 24756 us, wait= 699 us
** 1111993721.040083, user= 23856 us, wait= 228 us
** 1111993721.066281, user= 26031 us, wait= 156 us
-- 1111993721.066583, user= 949623 us, wait= 24908 us
** 1111993721.092898, user= 25676 us, wait= 929 us
** 1111993721.144430, user= 45217 us, wait= 6303 us
** 1111993721.200868, user= 46517 us, wait= 9908 us
** 1111993721.270960, user= 60618 us, wait= 9462 us
** 1111993721.320463, user= 44276 us, wait= 5215 us
** 1111993721.376595, user= 46271 us, wait= 9848 us
** 1111993721.441384, user= 55070 us, wait= 9707 us
** 1111993721.497743, user= 48366 us, wait= 7981 us
** 1111993721.553152, user= 45856 us, wait= 9541 us
** 1111993721.618383, user= 55056 us, wait= 10163 us
** 1111993721.658720, user= 30441 us, wait= 9884 us
** 1111993721.719345, user= 55072 us, wait= 5541 us
** 1111993721.759890, user= 30626 us, wait= 9907 us
** 1111993721.819330, user= 55072 us, wait= 4356 us
** 1111993721.859934, user= 30685 us, wait= 9907 us
** 1111993721.920176, user= 55934 us, wait= 4297 us
** 1111993721.965367, user= 35135 us, wait= 10044 us
** 1111993722.000338, user= 25113 us, wait= 9846 us
==================================================
[5] other reports with lat2 and lat3
==================================================
#process1= lat2 50000
#process2= while : ;do :; done
date=1111995134.390, wait= 827 us, user= 50000 us, max= 51
date=1111995134.441, wait= 827 us, user= 50000 us, max= 22
date=1111995136.546, wait= 828 us, user= 2103676 us, max=2102961
date=1111995136.995, wait= 399760 us, user= 50000 us, max= 51
date=1111995137.046, wait= 985 us, user= 50000 us, max= 89
date=1111995137.097, wait= 1017 us, user= 50000 us, max= 22
date=1111995137.148, wait= 940 us, user= 50000 us, max= 51
#process1= lat2 100000
#process2= 2x while : &
date=1111995037.390, wait= 818 us, user= 100000 us, max= 153
date=1111995037.491, wait= 817 us, user= 100000 us, max= 65
date=1111995037.592, wait= 819 us, user= 100000 us, max= 51
date=1111995040.691, wait= 819 us, user= 3098525 us, max=3062425
date=1111995040.991, wait= 199769 us, user= 100000 us, max= 51
date=1111995041.092, wait= 971 us, user= 100000 us, max= 89
date=1111995041.193, wait= 970 us, user= 100000 us, max= 56
#process1=lat3 (nbmax shows the number of lags of more than 10 ms)
#process2=while :;do :;done
Date_sec.msec select loop maxlat nbmax
1112008903.267 929 100000 48 0
1112008903.368 930 100000 52 0
1112008903.469 931 100000 49 0
1112008903.570 930 100000 54 0
1112008903.673 930 101297 8288 0
1112008903.773 680 100000 51 0
1112008903.874 977 100000 54 0
1112008906.469 978 2593603 2507346 1
1112008906.669 99929 100000 49 0
1112008906.770 929 100000 51 0
1112008906.871 930 100000 50 0
==================================================
[6] large latency reports with 2x lat3 1000000
==================================================
P: Date_sec.msec select loop maxlat nbmax
1: 1112015222.379 1 1000000 24646 1
1: 1112015223.380 177 1000000 70 0
1: 1112015224.380 791 1000000 98 0
1: 1112015225.381 792 1000000 8299 0
1: 1112015227.335 841 1952641 1002003 1
2: 1112015227.335 1 1000000 94 0
1: 1112015228.939 603960 1000000 8297 0
2: 1112015228.939 65 1603966 1000071 1
1: 1112015229.940 795 1000000 53 0
2: 1112015231.675 1000842 1735522 835883 1
1: 1112015232.015 899654 1175819 299966 1
1: 1112015233.615 599855 1000000 53 0
2: 1112015233.615 39986 1899922 1000070 1
1: 1112015235.376 793 1759891 1000020 1
2: 1112015235.376 760666 1000000 53 0
2: 1112015237.076 844 1699738 899875 1
1: 1112015238.016 800663 1839721 899875 1
2: 1112015238.516 39986 1399788 459942 1
1: 1112015239.916 39937 1859880 1000022 1
2: 1112015239.916 399932 1000000 53 0
1: 1112015241.677 760667 1000000 53 0
2: 1112015241.677 842 1759937 1000068 1
1: 1112015243.385 796 1707751 899888 1
2: 1112015244.334 808663 1848719 908875 1
1: 1112015245.234 39972 1808725 859880 1
2: 1112015245.834 39985 1459779 559927 1
1: 1112015247.234 39939 1959863 1000020 1
2: 1112015247.234 399930 1000000 54 0
1: 1112015248.995 760670 1000000 53 0
2: 1112015248.995 844 1759940 1000069 1
1: 1112015250.704 793 1708738 907873 1
2: 1112015251.644 801660 1847719 899874 1
1: 1112015252.544 39986 1799726 859880 1
2: 1112015253.044 39939 1359793 459942 1
1: 1112015254.553 39986 1968863 1000022 1
2: 1112015254.553 508869 1000000 53 0
2: 1112015256.008 841 1453798 693927 1
2: 1112015257.009 973 1000000 8287 0
==================================================
[7] slowly increasing latency with 2x nice +10 lat3 1000000
==================================================
P Date_sec.msec select loop maxlat nbmax
1: 1112015805.344 0 1000000 24711 1
1: 1112015806.344 155 1000000 24471 1
1: 1112015807.345 837 1000000 8286 0
1: 1112015808.346 791 1000000 53 0
1: 1112015809.347 793 1000000 91 0
1: 1112015810.347 792 1000000 53 0
1: 1112015811.348 793 1000000 53 0
1: 1112015812.349 793 1000000 8285 0
1: 1112015813.350 840 1000000 50004 7
2: 1112015813.728 1 1049753 50004 11
1: 1112015814.400 49827 1000000 50004 10
2: 1112015814.778 938 1048839 50004 11
1: 1112015815.450 49832 1000000 50005 10
2: 1112015815.785 945 1006846 85998 10
1: 1112015816.535 49786 1035842 99996 9
2: 1112015816.835 49985 1000000 149988 8
1: 1112015817.635 49938 1049840 249974 7
2: 1112015818.185 49833 1299802 499935 6
1: 1112015818.835 49936 1149835 599929 1
2: 1112015819.735 49986 1499772 849882 1
1: 1112015820.585 49928 1699742 799890 1
2: 1112015821.485 49984 1699750 849890 1
1: 1112015822.384 49936 1749734 849883 1
2: 1112015823.284 49976 1749734 849882 1
1: 1112015824.184 49935 1749734 849881 1
2: 1112015825.084 49986 1749734 849883 1
1: 1112015825.984 49938 1749734 849882 1
2: 1112015826.834 49985 1699750 799898 1
1: 1112015827.734 49937 1699742 849882 1
2: 1112015828.633 49977 1749734 849883 1
1: 1112015829.533 49936 1749734 849882 1
2: 1112015830.433 49985 1749734 849881 1
1: 1112015831.291 49938 1707741 807889 1
1: 1112015832.341 49984 1000000 8285 0
--
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/