CFS scheduler, -v13

i'm pleased to announce release -v13 of the CFS scheduler patchset.

The CFS patch against v2.6.22-rc1, v2.6.21.1 or v2.6.20.10 can be downloaded from the usual place:

http://people.redhat.com/mingo/cfs-scheduler/

-v13 is a fixes-only release. It fixes a smaller accounting bug, so if you saw small lags during desktop use under certain workloads then please re-check that workload under -v13 too. It also tweaks SMP load-balancing a bit. (Note: the load-balancing artifact reported by Peter Williams is not a CFS-specific problem and he reproduced it in v2.6.21 too. Nevertheless -v13 should be less prone to such artifacts.)

I know about no open CFS regression at the moment, so please re-test -v13 and if you still see any problem please re-report it. Thanks!

Changes since -v12:

- small tweak: made the "fork flow" of reniced tasks zero-sum

- debugging update: /proc/<PID>/sched is now seqfile based and echoing 0 to it clears the maximum-tracking counters.

- more debugging counters

- small rounding fix to make the statistical average of rounding errors zero

- scale both the runtime limit and the granularity on SMP too, and make it dependent on HZ

- misc cleanups

As usual, any sort of feedback, bugreport, fix and suggestion is more than welcome,

Ingo

Hi
Been testing this version of CFS from last an hour or so and still facing same lag problems while browsing sites with heavy JS and or flash usage. Mouse movement is pathetic and audio starts to skip. I haven't face this behavior with CFS till v11.

Regards
Ananitya

i have just tried 5 different versions of the Flash plugin and i cannot reproduce this (flash games are still smooth and acceptable even with the system significantly overloaded with 5 infite loops or with a kernel build), so it would be nice if you could help me debug this problem.

The last version that worked for you was v11, correct? The biggest v11 -> v12 change was the yield workaround, and while testing your workload i also noticed that all Flash versions except the latest one (9.0 r31) use sys_sched_yield() quite frequently. So it would be nice to know which plugin version you are using (and which Firefox version): you can check that by typing about:plugins into firefox. Furthermore, could you also try the following tune:

echo 0 > /proc/sys/kernel/sched_yield_bug_workaround

and this:

echo 2 > /proc/sys/kernel/sched_yield_bug_workaround

if none of this changes behavior then please send me the output of the following:

strace -ttt -TTT -o strace.txt -f -p pidof firefox-bin < reproduce the lag in firefox >
< Ctrl-C the strace >

and send me the strace.txt file (off-line, it's going to be large). Thanks,

Ingo

Hi
I am using konqueror and about:plugins gives back this information regarding flashplayer.
Shockwave Flash Shockwave Flash 9.0 r31 libflashplayer.so
application/x-shockwave-flash - Shockwave Flash (swf)
application/futuresplash - FutureSplash Player (spl)

These values do visibly makes browsing smooth but it still lags though lag time is less compared to original values.

I am sending you all these information off list.

Regards
Ananitya

Hi Ingo,

Please ignore my last report about lag problem while using CFS-v13, it is working perfectly fine with 2.6.21.1 and the lag I used to see in v12 is not there with v13 anymore. After digging in a bit I found that problem is only occurring in 2.6.22-rc1 and it get fired by network usage while transmitting data upstream. I don't have any evidence that CFS is involved in lag problem since 2.6.22-rc1 with stock scheduler is also having same lag problem and it seems directly proportional with upstream speed while downstream doesn't shows any misbehavior { at lower upstream speed lag is less but with higher upstream speed system starts crawling and system load hitting to 70/75}. Lets see how 2.6.22-rc2 is doing.

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

ah, great - i was looking over your debug data and couldnt find the problem! This moves CFS into the "no open regressions" state again ;-)

if that lag still occurs with rc2 then please repeat the following debugging steps under CFS [which has more instrumentation than the stock scheduler]:

cat /proc/pidof firefox-bin/sched > sched1.txt echo 0 > /proc/pidof firefox-bin/sched

< reproduce the lag in firefox >

cat /proc/pidof firefox-bin/sched > sched2.txt

this way we'll be able to tell what nature this delay has. Also, could you send me your kernel's .config (off-list)?

Ingo

ok, i got your -rc2 debug numbers (off-list), and it doesnt look pretty:

before-lag:

 sleep_max                :           259502076
 block_max                :            27690921
 wait_max                 :            16381558

after-lag:

 sleep_max                :           584186160
 block_max                :           261780071
 wait_max                 :           881255577

ouch! a nearly 1 second delay got observed by the scheduler - something is really killing your system!

what does 'top' show during an upload? Is any system related task out of whack? Could you try to get a readprofile or an oprofile output from the kernel, so that we can see what is slowing it down so much? It could be something networking related in v2.6.22-rc2.

Ingo

ah, you got the latency tracer from Thomas, as part of the -hrt patchset
- that makes it quite a bit easier to debug. Could you run the attached trace-it-10sec utility:

trace-it-10sec > trace-to-ingo.txt

and send me the (compressed) trace output (off-list, or post an URL to the trace)? Try to reproduce the 'lag' event in the 10 seconds while the tracer is running.

Ingo

attached ...

Ingo

/*
* Copyright (C) 2005, Ingo Molnar <[email protected]>
*
* user-triggered tracing.
*
* The -rt kernel has a built-in kernel tracer, which will trace
* all kernel function calls (and a couple of special events as well),
* by using a build-time gcc feature that instruments all kernel
* functions.
*
* The tracer is highly automated for a number of latency tracing purposes,
* but it can also be switched into 'user-triggered' mode, which is a
* half-automatic tracing mode where userspace apps start and stop the
* tracer. This file shows a dumb example how to turn user-triggered
* tracing on, and how to start/stop tracing. Note that if you do
* multiple start/stop sequences, the kernel will do a maximum search
* over their latencies, and will keep the trace of the largest latency
* in /proc/latency_trace. The maximums are also reported to the kernel
* log. (but can also be read from /proc/sys/kernel/preempt_max_latency) *
* For the tracer to be activated, turn on CONFIG_WAKEUP_TIMING and
* CONFIG_LATENCY_TRACE in the .config, rebuild the kernel and boot
* into it. Note that the tracer can have significant runtime overhead,
* so you dont want to use it for performance testing :)
*/

#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <signal.h>
#include <sys/wait.h>
#include <linux/unistd.h>

int main (int argc, char **argv)

{
	int ret;

	if (getuid() != 0) {
		fprintf(stderr, "needs to run as root.\n");
		exit(1);
	}
	ret = system("cat /proc/sys/kernel/mcount_enabled >/dev/null 2>/dev/null");
	if (ret) {
		fprintf(stderr, "CONFIG_LATENCY_TRACING not enabled?\n");
		exit(1);
	}
//	system("echo 0 > /proc/sys/kernel/trace_all_cpus");
	system("echo 1 > /proc/sys/kernel/trace_enabled");
//	system("echo 0 > /proc/sys/kernel/trace_freerunning");
	system("echo 0 > /proc/sys/kernel/trace_print_at_crash");
	system("echo 1 > /proc/sys/kernel/trace_user_triggered");
	system("echo 0 > /proc/sys/kernel/trace_verbose");
	system("echo 0 > /proc/sys/kernel/preempt_max_latency");
	system("echo 0 > /proc/sys/kernel/preempt_thresh");

// system("[ -e /proc/sys/kernel/wakeup_timing ] && echo 1 > /proc/sys/kernel/wakeup_timing");
// system("echo 1 > /proc/sys/kernel/mcount_enabled");

	prctl(0, 1); // start tracing
	sleep(10);
	prctl(0, 0); // stop tracing

	system("cat /proc/latency_trace");

	return 0;
}

and ... you already did a trace for Thomas, for the softirq problem:

http://cybertek.info/taitai/trace.txt.bz2

this trace shows really bad networking related kernel activities!

gkrellm-5977 does this at timestamp 0:

gkrellm-5977 0..s. 0us : cond_resched_softirq (established_get_next)

2 milliseconds later it's still in established_get_next() (!):

gkrellm-5977 0..s. 2001us : cond_resched_softirq (established_get_next)

and the whole thing takes ... 455 msecs:

gkrellm-5977 0..s. 455443us+: cond_resched_softirq (established_get_next)

i think this suggests that you have tons of open sockets. What does "netstat -ts" say on your box?

Ingo

From: Ingo Molnar <[email protected]>
Date: Mon, 21 May 2007 10:12:01 +0200

So it's not the 3c59x bug :-)

If you have a lot of sockets, there is not way to make the performance of dumping /proc/net/tcp not suck, use the netlink socket dumping which is:

1) more efficient even for full dumps
2) allows filtering for the best possible performance

hm, there is a cond_resched_softirq() for every line output so the actual latency from this alone shouldnt be that bad. While /proc/net/tcp has a quadratic algorithm, the per-line latency is O(N), which shouldnt show up on the radar.

but note that Ananitya is running a fast system as a stock desktop system browsing the web, so there shouldnt be tons of sockets. So the latency isnt caused by /proc/net/tcp itself, but there does seem to be some networking related anomaly.

we'll hopefully be able to tell this more specifically from the re-done trace.

Ingo

On 2.6.21.1 doing normal work while seeding few torrents produces this with "netstat -ts". I will send you same information for 2.6.22-rc2 after a reboot.

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

Tcp:
1233 active connections openings
845 passive connection openings
9 failed connection attempts
164 connection resets received
5 connections established
44995 segments received
43171 segments send out
183 segments retransmited
0 bad segments received.
192 resets sent
UdpLite:
TcpExt:
696 TCP sockets finished time wait in fast timer 3273 delayed acks sent
12 delayed acks further delayed because of locked socket Quick ack mode was activated 38 times
4867 packets directly queued to recvmsg prequeue. 31660 packets directly received from backlog 6759887 packets directly received from prequeue 12038 packets header predicted
3228 packets header predicted and directly queued to user 4795 acknowledgments not containing data received 12680 predicted acknowledgments
15 times recovered from packet loss due to SACK data 4 congestion windows recovered after partial ack 12 TCP data loss events
5 timeouts after SACK recovery
8 timeouts in loss state
20 fast retransmits
25 retransmits in slow start
65 other TCP timeouts
5 sack retransmits failed
3 times receiver scheduled too late for direct processing 16 DSACKs sent for old packets
152 connections reset due to unexpected data
5 connections reset due to early user close

hm, this does not explain the /proc/net/tcp overhead i think - although it could be a red herring. Will have a closer look at your new trace.

if possible please try to generate the automatic softirq trace for Thomas, and then a separate trace for the firefox/net-lag thing, using trace-it-10sec.c. Btw., for the second trace, could you boot with maxcpus=1? That would make the second trace quite a bit more straightforward to analyze. You probably need both cpus to trigger the softirq problem.

Ingo

here is the link for new trace with maxcpus=1.
http://cybertek.info/taitai/trace-it-10sec-to-ingo-with-maxcpus=1.bz2

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

I am posting links to the information you asked for. One more thing, after digging a bit more I found its QoS shaping that is making the box crawl. Once I disabled the traffic shaping everything comes back to smooth and normal. Shaping being done on very low speed residential ADSL 256/64 Kbps connection. If you want me to post shaping rules, please free to ask. BTW its a simple HTB/SFQ rules.

http://cybertek.info/taitai/netstat-ts-before-crawl-normal-workload.txt
http://cybertek.info/taitai/netstat-ts-while-crawl-normal-workload.txt
http://cybertek.info/taitai/trace-to-ingo.txt.bz2

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

[...]

thanks! This trace indeed includes the smoking gun, htb_dequeue() and __qdisc_run():

privoxy-12926 1.Ns1 1597us : rb_first (htb_dequeue)

this goes on, non-preemptible, for 160 milliseconds (!):

privoxy-12926 1.Ns1 161568us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161568us : qdisc_watchdog_schedule (htb_dequeue)

and finally manages to escape the loop:

privoxy-12926 1.Ns1 161597us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161597us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161599us : htb_safe_rb_erase (htb_dequeue) privoxy-12926 1.Ns1 161599us : rb_erase (htb_safe_rb_erase) privoxy-12926 1.Ns1 161600us : htb_change_class_mode (htb_dequeue) privoxy-12926 1.Ns1 161601us : htb_activate_prios (htb_change_class_mode)

and the system recovers.

David, any ideas about what's wrong with htb_dequeue(), based on this trace?

Ingo

This looks like fallout from the switch to hrtimers. Anant, please send me your HTB script, I'll try to reproduce it.

I think I already found the bug, please try if this patch helps.

[NET_SCHED]: sch_htb: fix event cache time calculation

The event cache time must be an absolute value, when no event exists it is incorrectly set to 1s instead of 1s in the future.

Should fix excessive load reported by Anant Nitya <[email protected]>.

---
commit 49d1023ea0ea8377e740123d5954e88a00f78b7c
tree 031c210f1b5e37ade5a4fa519f5808cd49225b89
parent 637fc540b0ad22bf7971929e906e704236af06cd
author Patrick McHardy <[email protected]> Mon, 21 May 2007 23:24:16 +0200 committer Patrick McHardy <[email protected]> Mon, 21 May 2007 23:25:51 +0200

 net/sched/sch_htb.c |    5 +++--
 1 files changed, 3 insertions(+), 2 deletions(-)

index 99bcec8..035788c 100644
@@ -976,8 +976,9 @@ static struct sk_buff *htb_dequeue(struct Qdisc *sch)
 
 		if (q->now >= q->near_ev_cache[level]) {
 			event = htb_do_events(q, level);
-			q->near_ev_cache[level] = event ? event :
-							  PSCHED_TICKS_PER_SEC;
+			if (!event)
+				event = q->now + PSCHED_TICKS_PER_SEC;
+			q->near_ev_cache[level] = event;
 		} else
 			event = q->near_ev_cache[level];
 

Sorry, but this patch is not helping here. I recompiled the kernel with this patch but same load pattern still make system to crawl.

Here is the link for script I use to shape traffic.

http://cybertek.info/taitai/adslbwopt.sh

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

could you also apply the fix for the softirq problem below, to make sure it does not interact?

Ingo

Index: linux/kernel/sched.c
===================================================================
@@ -4212,9 +4212,7 @@ int __sched cond_resched_softirq(void)
 	BUG_ON(!in_softirq());
 
 	if (need_resched() && system_state == SYSTEM_RUNNING) {
-		raw_local_irq_disable();
-		_local_bh_enable();
-		raw_local_irq_enable();
+		local_bh_enable();
 		__cond_resched();
 		local_bh_disable();
 		return 1;

thanks.

if you feel inclined to try the git-bisection then by all means please do it (it will certainly be helpful and educative), but it's optional: i dont think you should 'need' to go through extra debugging chores, my analysis based on the excellent trace you provided still holds and whoever modified htb_dequeue()'s logic recently ought to be able to figure that out (or send you a debug patch to further narrow the problem down).

The trace shows a _clearly_ anomalous loop: for example there's 56396 (!) calls to rb_first() in htb_dequeue() [without the kernel ever exiting that function]:

earth4:~/s> grep rb_first trace-to-ingo.txt | wc -l 56396

and the set of rules you are using are alot simpler and the networking load you are using is not large by any means. Here's the trace analysis below again.

Ingo

----------------------->

This trace indeed includes the smoking gun, htb_dequeue() and __qdisc_run():

privoxy-12926 1.Ns1 1597us : rb_first (htb_dequeue)

this goes on, non-preemptible, for 160 milliseconds (!):

privoxy-12926 1.Ns1 161568us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161568us : qdisc_watchdog_schedule (htb_dequeue)

and finally manages to escape the loop:

privoxy-12926 1.Ns1 161597us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161597us : rb_first (htb_dequeue) privoxy-12926 1.Ns1 161599us : htb_safe_rb_erase (htb_dequeue) privoxy-12926 1.Ns1 161599us : rb_erase (htb_safe_rb_erase) privoxy-12926 1.Ns1 161600us : htb_change_class_mode (htb_dequeue) privoxy-12926 1.Ns1 161601us : htb_activate_prios (htb_change_class_mode)

and the system recovers.

How is this trace to be understood? Is it simply a call trace in execution-order? If thats the case than we are exiting htb_dequeue, each call to qdisc_watchdog_schedule happens at the very end of that function, which would imply a bug in __qdisc_run.

Looking at the recent changes to __qdisc_run, this indeed seems to be the case, when the qdisc is throttled and has packets queued we return a value != 0, causing __qdisc_run to loop until all packets have been sent, which may be a long time.

Anant, can you please verify by testing the attached patch? Thanks.

index f28bb2d..f536060 100644
@@ -174,7 +174,7 @@ requeue:
 
 out:
 	BUG_ON((int) q->q.qlen < 0);
-	return q->q.qlen;
+	return skb ? q->q.qlen : 0;
 }
 
 void __qdisc_run(struct net_device *dev)

yeah. There's a help section at the top of the trace which explains the other fields too:

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /

privoxy-12926 1.Ns1 0us : ktime_get_ts (ktime_get)

the function name in braces is the parent function. So in this case the trace entry means we called ktime_get_ts() from ktime_get().

Ingo

Good catch! I was obviously half awake at the time :)

We could also fix it this way:

[NET_SCHED]: Fix qdisc_restart return value when dequeue is empty

My previous patch that changed the return value of qdisc_restart incorrectly made the case where dequeue returns empty continue processing packets.

This patch is based on diagnosis and fix by Patrick McHardy.

Thanks,

Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <[email protected]>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt
--

index f28bb2d..cbefe22 100644
@@ -169,8 +169,8 @@ requeue:
 		else
 			q->ops->requeue(skb, q);
 		netif_schedule(dev);
-		return 0;
 	}
+	return 0;
 
 out:
 	BUG_ON((int) q->q.qlen < 0);

Yes, that looks better, thanks.

There appear to be other obvious problems in the recent "cleanups" in this area..

Look at

	psched_tdiff_bounded(psched_time_t tv1, psched_time_t tv2, psched_time_t bound)
	{
		return min(tv1 - tv2, bound);
	}

and compare it to the previous code:

	#define PSCHED_TDIFF_SAFE(tv1, tv2, bound) \
		min_t(long long, (tv1) - (tv2), bound)

and ponder how that "trivial cleanup" totally broke the thing.

Hint: "psched_time_t" is an "u64". What does that mean for

	min(tv1 - tv2, bound);

again, when "tv2" is larger than tv1. It _used_ to return a negative value. Now it returns a positive "bound" upper bound, because "tv1-tv2" will be used as a huge unsigned (and thus _positive_) integer. And was that accidental, or done on purpose?

Sounds accidental to me, since you then want to return a "psched_tdiff_t", which is typedeffed to be "long".

Doesn't sound very safe to me, especially since the commit message for this is "[NET_SCHED]: turn PSCHED_TDIFF_SAFE into inline function", and there's no indication that anybody realized that it changed semantics in the process.

Hmm? What _should_ that thing do?

Linus

I did realize it, but tv2 > tv1 can't happen and makes no sense for the users of this function. I probably should have provided a more detailed changelog entry.

It is used to calculate the amount of tokens a tocken bucket has accumulated since the last refill, thus we always have tv1 >= tv2 (modulo ktime wraps). In fact tv2 > tv1 was never properly supported. This macro would have returned the negative long long value, but all users assign it to a psched_tdiff_t (long), so depending on the exact values, it might still be interpreted as a large positive value. Additionally there was a second implementation for the gettimeofday clocksource that didn't return the negative difference but the bound value.

also:

...

i gave your patch a quick test-boot and networking still works fine.

Ingo

From: Ingo Molnar <[email protected]>
Date: Wed, 23 May 2007 13:40:21 +0200

Applied, thanks everyone.

Even though it didn't fix this problem, this patch I sent earlier is also needed.

[NET_SCHED]: sch_htb: fix event cache time calculation

The event cache time must be an absolute value, when no event exists it is incorrectly set to 1s instead of 1s in the future.

---
commit 49d1023ea0ea8377e740123d5954e88a00f78b7c
tree 031c210f1b5e37ade5a4fa519f5808cd49225b89
parent 637fc540b0ad22bf7971929e906e704236af06cd
author Patrick McHardy <[email protected]> Mon, 21 May 2007 23:24:16 +0200 committer Patrick McHardy <[email protected]> Mon, 21 May 2007 23:25:51 +0200

 net/sched/sch_htb.c |    5 +++--
 1 files changed, 3 insertions(+), 2 deletions(-)

index 99bcec8..035788c 100644
@@ -976,8 +976,9 @@ static struct sk_buff *htb_dequeue(struct Qdisc *sch)
 
 		if (q->now >= q->near_ev_cache[level]) {
 			event = htb_do_events(q, level);
-			q->near_ev_cache[level] = event ? event :
-							  PSCHED_TICKS_PER_SEC;
+			if (!event)
+				event = q->now + PSCHED_TICKS_PER_SEC;
+			q->near_ev_cache[level] = event;
 		} else
 			event = q->near_ev_cache[level];
 

From: Patrick McHardy <[email protected]>
Date: Thu, 24 May 2007 07:41:00 +0200

Thanks a lot for reminding me about this patch Patrick, applied.

Networking lag I been seeing since 2.6.22-rc1, disappeared after applying this patch. Thanks to everyone who helped me run my system sane again. :)

Reagards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

btw., could you please send this patch on-list too please?

Ingo

disregard this - just found Patrick's patch.

Ingo

Thanks. Please also send the output of "tc -s -d qdisc show dev ppp0" and "tc -d -s class show dev ppp0" at the time the problem occurs.

Here it goes...

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

qdisc htb 1: r2q 1 default 50 direct_packets_stat 0 ver 3.17
Sent 837184 bytes 3603 pkt (dropped 0, overlimits 60528154 requeues 0) rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 4210: parent 1:10 limit 50p quantum 1492b flows 50/1024 perturb 10sec
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 4220: parent 1:20 limit 50p quantum 1492b flows 50/1024 perturb 10sec
Sent 102922 bytes 2364 pkt (dropped 0, overlimits 0 requeues 0) rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 4230: parent 1:30 limit 64p quantum 1492b flows 64/1024 perturb 10sec
Sent 12690 bytes 167 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 4240: parent 1:40 limit 128p quantum 1492b flows 128/1024 perturb 10sec
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 4250: parent 1:50 limit 64p quantum 1492b flows 64/1024 perturb 10sec
Sent 714095 bytes 944 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
qdisc sfq 666: parent 1:666 limit 128p quantum 1492b flows 128/1024 perturb 10sec
Sent 7477 bytes 128 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0

class htb 1:10 parent 1:1 leaf 4210: prio 0 quantum 1000 rate 7000bit ceil 57000bit burst 1599b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
lended: 0 borrowed: 0 giants: 0
tokens: 1785713 ctokens: 219297

class htb 1:1 root rate 64000bit ceil 64000bit burst 1599b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 7
Sent 1533899 bytes 5926 pkt (dropped 0, overlimits 0 requeues 0)
rate 74640bit 31pps backlog 0b 0p requeues 0
lended: 1113 borrowed: 0 giants: 0
tokens: -255221 ctokens: -255221

class htb 1:20 parent 1:1 leaf 4220: prio 1 quantum 3125 rate 25000bit ceil 57000bit burst 1599b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 171357 bytes 3931 pkt (dropped 0, overlimits 0 requeues 0)
rate 7376bit 21pps backlog 0b 0p requeues 0
lended: 3931 borrowed: 0 giants: 0
tokens: 341211 ctokens: 150341

class htb 1:30 parent 1:1 leaf 4230: prio 4 quantum 1250 rate 10000bit ceil 51000bit burst 1600b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 15578 bytes 205 pkt (dropped 0, overlimits 0 requeues 0)
rate 336bit 0pps backlog 0b 0p requeues 0
lended: 205 borrowed: 0 giants: 0
tokens: 1137614 ctokens: 223153

class htb 1:40 parent 1:1 leaf 4240: prio 4 quantum 1000 rate 8000bit ceil 51000bit burst 1600b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
rate 0bit 0pps backlog 0b 0p requeues 0
lended: 0 borrowed: 0 giants: 0
tokens: 1562500 ctokens: 245097

class htb 1:50 parent 1:1 leaf 4250: prio 4 quantum 1000 rate 7000bit ceil 60000bit burst 1599b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 1329025 bytes 1455 pkt (dropped 0, overlimits 0 requeues 0)
rate 65384bit 6pps backlog 0b 0p requeues 0
lended: 342 borrowed: 1113 giants: 0
tokens: -2865704 ctokens: 1887

class htb 1:666 parent 1:1 leaf 666: prio 7 quantum 1492 rate 3000bit ceil 48000bit burst 1599b/8 mpu 0b overhead 0b cburst 1599b/8 mpu 0b overhead 0b level 0
Sent 17939 bytes 335 pkt (dropped 0, overlimits 0 requeues 0)
rate 1104bit 2pps backlog 0b 0p requeues 0
lended: 335 borrowed: 0 giants: 0
tokens: 3937910 ctokens: 246505

From: Ingo Molnar <[email protected]>
Date: Mon, 21 May 2007 09:58:24 +0200

There is a driver specific problem that's been around for a while, but it only effects 3c59x chips, is that what you have?

the problem first showed up in v2.6.22-rc1 and he didnt have it in v2.6.21 - does that still qualify his box for the 3c59x problem?

Ingo

From: Ingo Molnar <[email protected]>
Date: Mon, 21 May 2007 10:28:05 +0200

If the latency is showing up in /proc/net/tcp dumping, it's not the 3c59x problem.

Please just discard any latency trace that shows symbols from that code, really.

Can you bisect it? Just do

	git bisect start
	git bisect good v2.6.21
	git bisect bad v2.6.22-rc1

and start testing the end result. The bisection thing is pretty efficient, so while there's almost 5000 commits in there, you realy shouldn't need to test more than ten kernels to get it narrowed down to just five commits or so, and since it seems to be very repeatable and noticeable for you, bisecting should be the trivial thing to figure out what broke.

David: all the blather about network drivers and/or /proc/net/tcp being slow anyway misses the *big* point: it didn't use to do this. So there's a new bug there. Maybe something keeps sockets around in a dead state on the hash lists or whatever. Mayube something else breaks his bittorrent client. Whatever. We don't know. But it's a regression.

Linus

'm not seeing this, do have a site or two as examples?

Bill Davidsen <[email protected]>
  "We have more to fear from the bungling of the incompetent than from
the machinations of the wicked."  - from Slashdot

Please disregard the above post, lag problem I am experiencing got introduced in 2.6.22-rcX and is network QoS specific and its not related to CFS.

Regards
Ananitya

Out of many thousands, one may endeavor for perfection, and of
those who have achieved perfection, hardly one knows Me in truth.
				-- Gita Sutra Of Mysticism

Just thought I'd let you know that CFS is working on the PS3

neutrino boot # dmesg
Using PS3 machine description
Page orders: linear mapping = 24, virtual = 12, io = 12 Starting Linux PPC64 #1 SMP Fri May 18 09:26:38 UTC 2007
-----------------------------------------------------
ppc64_pft_size = 0x14
physicalMemorySize = 0x8000000
ppc64_caches.dcache_line_size = 0x80 ppc64_caches.icache_line_size = 0x80
htab_address = 0x0000000000000000
htab_hash_mask = 0x1fff
-----------------------------------------------------
Linux version 2.6.22-rc1-cfs-v13 (root@localhost) (gcc version 4.1.1 (Gentoo 4.1.1-r3)) #1 SMP Fri May 18 09:26:38 UTC 2007

It feels more responsive but I shall do more testing and see if there are any real benefits

heh, an important milestone i think =B-)

Ingo