lkml.org 
[lkml]   [2011]   [Jan]   [21]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
SubjectRe: [PATCH] Wait to remove active timer when rescheduling hrtimer
From
On Fri, Jan 21, 2011 at 1:32 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
>
>
> On Fri, 21 Jan 2011, Vernon Mauery wrote:
>
>> In the current hrtimer implementation, when explicitly
>> removing a timer, the hrtimer_cancel function waits
>> until the timer is not currently running before actually
>> calling remove_hrtimer.  But in the __hrtimer_start_range_ns
>> function (called by hrtimer_start, among others), it
>> calls remove_hrtimer without checking to see if the
>> timer is currently running.  This doesn't seem to cause
>> much trouble in the vanilla kernel, but in the -RT
>> kernel, this causes a silent hang when exercising the
>> sch_htb module on a 10GbE interface.
>>
>> Signed-off-by: Vernon Mauery <vernux@us.ibm.com>
>> ---
>>  kernel/hrtimer.c |    5 +++++
>>  1 files changed, 5 insertions(+), 0 deletions(-)
>>
>> diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
>> index 0c8d7c0..c7e8ba0 100644
>> --- a/kernel/hrtimer.c
>> +++ b/kernel/hrtimer.c
>> @@ -935,6 +935,11 @@ int __hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
>>       base = lock_hrtimer_base(timer, &flags);
>>
>>       /* Remove an active timer from the queue: */
>> +     while (hrtimer_callback_running(timer)) {
>> +             unlock_hrtimer_base(timer, &flags);
>> +             hrtimer_wait_for_timer(timer);
>> +             base = lock_hrtimer_base(timer, &flags);
>> +     }
>>       ret = remove_hrtimer(timer, base);
>>
>>       /* Switch the timer base, if necessary: */
>
> Hmm, why does it hang ?

It hangs when I set up QoS on a 10GbE interface and run traffic over
it. Here is what I do:
#!/bin/bash

if [ -z "$1" ]; then
ETH=eth2
else
ETH="$1"
fi
IP=`ip addr show $ETH | grep 'inet\>' | sed 's/.*inet \([^/]*\)\/.*/\1/'`
IP=`echo $IP | sed 's/\([^.]*\)\.\([^.]*\)\.\([^.]*\)\.\([^.]*\)/\1.\2.\3.95/'`
SPEED=`ethtool $ETH | grep Speed | sed 's/[^0-9]*\([0-9]*\).*/\1/'`
case $SPEED in
10000) ZEROS=00 ;;
1000) ZEROS=0 ;;
default) ZEROS='' ;;
esac
tc qdisc del dev $ETH root >&/dev/null || :
[ "$2" == "stop" ] && exit 0
set -x
tc qdisc add dev $ETH root handle 1: htb default 30 r2q 600$ZEROS
tc class add dev $ETH parent 1: classid 1:1 htb rate 30${ZEROS}mbit
tc class add dev $ETH parent 1:1 classid 1:10 htb rate 5${ZEROS}mbit prio 1
tc class add dev $ETH parent 1:1 classid 1:20 htb rate 5${ZEROS}mbit prio 2
tc class add dev $ETH parent 1:1 classid 1:30 htb rate 8${ZEROS}mbit
set +x
echo "netperf -l 2000 -H 10.1.1.94 -t UDP_STREAM -- -m 65505"
----------------------8< snip 8<-------------------------------
After running the script, I run a netperf command similar to the one
that the script prints, that runs traffic over the interface that we
just set up QoS on. Within 10-15 seconds, the machine goes silent.
(this is on a 2.6.33.7-rt29 kernel)

My guess would be that without this patch, it is possible to have a
timer currently in the tree, not delete it and then schedule it again.
Not on this machine or on this kernel, I saw a similar problem
(caused by the same thing: using sch_htb on -rt kernel), but instead
of a silent hang, it gave me an oops that looked like this:

Unable to handle kernel NULL pointer dereference at 0000000000000010
RIP: [<ffffffff8113b38c>] rb_erase+0x1f3/0x2b1
PGD 14e150067 PUD 142d34067 PMD 0
Oops: 0000 [1] PREEMPT SMP
CPU 2
Modules linked in: sch_htb pktgen nfs nfsd lockd nfs_acl auth_rpcgss exportfs
ipmi_devintf ipmi_si ipmi_msghandler ibm_rtl ipv6 autofs4 i2c_dev i2c_core hidp
rfcomm l2cap bluetooth sunrpc dm_mirror dm_multipath scsi_dh dm_mod video
output sbs sbshc battery ac parport_pc lp parport sg bnx2 button netxen_nic
serio_raw amd64_edac edac_core pcspkr shpchp mptsas mptscsih mptbase
scsi_transport_sas sd_mod scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd
Pid: 38, comm: sirq-hrtimer/2 Not tainted 2.6.24.7-139.el5rt #1
RIP: 0010:[<ffffffff8113b38c>] [<ffffffff8113b38c>] rb_erase+0x1f3/0x2b1
RSP: 0018:ffff81014f16fe50 EFLAGS: 00010082
RAX: 0000000000000000 RBX: ffff81014640bac8 RCX: ffff810001085780
RDX: 0000000000000000 RSI: ffff8100010076a8 RDI: 0000000000000000
RBP: ffff81014f16fe60 R08: ffff81033f15dac8 R09: 0000000000000000
R10: 0000000000000002 R11: 0000000000000000 R12: ffff8100010076a8
R13: 0000000000000000 R14: 0000000000000002 R15: 0000000000000080
FS: 00007ff9960016e0(0000) GS:ffff81014fc09cc0(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000010 CR3: 000000014e188000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process sirq-hrtimer/2 (pid: 38, threadinfo ffff81014f16e000, task
ffff81014f16c300)
Stack: ffff81013a5e67d0 ffff810001007698 ffff81014f16fe90 ffffffff81054dfc
ffffffff81227401 ffff81013a5e67d0 ffff810001085640 0000000000000002
ffff81014f16fec0 ffffffff81055cbb 0000000000000002 ffffffff815005e8
Call Trace:
[<ffffffff81054dfc>] __remove_hrtimer+0x6e/0x7b
[<ffffffff81227401>] ? qdisc_watchdog+0x0/0x23
[<ffffffff81055cbb>] run_hrtimer_softirq+0x7a/0x14e
[<ffffffff81043d26>] ksoftirqd+0x16a/0x26f
[<ffffffff81043bbc>] ? ksoftirqd+0x0/0x26f
[<ffffffff81043bbc>] ? ksoftirqd+0x0/0x26f
[<ffffffff8105261c>] kthread+0x49/0x79
[<ffffffff8100d088>] child_rip+0xa/0x12
[<ffffffff810525d3>] ? kthread+0x0/0x79
[<ffffffff8100d07e>] ? child_rip+0x0/0x12

My most common experience is to just experience a silent hang, which
allows me to do very little in the way of debugging -- unless I catch
it before it goes completely silent, not even sysrq works. I have
managed to crash the machine on occasion, but the crash kernel never
seems to get very far before it dies off too... Very odd behavior. I
tried to capture a sysrq+T, but it only gave me the names of the
processes, not the backtraces, and then the per CPU info. I didn't
see anything that stuck out in the per-CPU info, but right after the
dump, the machine went completely silent again.

Sample from sysrq+T:

sshd S ffff880417e65ea8 0 3621 3204 0x00000080
Call Trace:
bash S ffff880417dd0200 0 3636 3621 0x00000080
Call Trace:
sshd S 0000000000000000 0 3637 3204 0x00000080
Call Trace:
bash S ffff880417ddc440 0 3662 3637 0x00000080
Call Trace:
top S ffff88002838af48 0 3686 3662 0x00000080
Call Trace:
netperf R running task 0 3708 3636 0x00000080
Call Trace:
Sched Debug Version: v0.09, 2.6.33.7-rt29.35.el5rt #1
now at 134835.593881 msecs
.jiffies : 4294787328
.sysctl_sched_latency : 20.000000
.sysctl_sched_min_granularity : 4.000000
.sysctl_sched_wakeup_granularity : 4.000000
.sysctl_sched_child_runs_first : 0.000000
.sysctl_sched_features : 7917179
.sysctl_sched_tunable_scaling : 1 (logaritmic)
cpu#0, 2833.945 MHz
.nr_running : 1
.load : 0
.nr_switches : 1030470
.nr_load_updates : 120033
.nr_uninterruptible : 141
.next_balance : 4294.787429
.curr->pid : 3708
.clock : 122477.541494
.cpu_load[0] : 0
.cpu_load[1] : 4
.cpu_load[2] : 56
.cpu_load[3] : 122
.cpu_load[4] : 168
.rt.rt_nr_running : 1
.rt.rt_nr_uninterruptible : 26920
.rto_schedule : 534494
.rto_schedule_tail : 0
.rto_wakeup : 0
.rto_pulled : 0
.rto_pushed : 0
.yld_count : 0
.sched_switch : 0
.sched_count : 1070624
.sched_goidle : 279923
.avg_idle : 93170
.ttwu_count : 640746
.ttwu_local : 613469
.bkl_count : 299

cfs_rq[0]:
.exec_clock : 4267.411040
.MIN_vruntime : 0.000001
.min_vruntime : 11634.164614
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : 0.000000
.nr_running : 0
.load : 0
.nr_spread_over : 12978
rt_rq[0]:
.rt_nr_running : 1
.rt_throttled : 0
.rt_time : 7.163839
.rt_runtime : 850.000000
runnable tasks:
task PID tree-key switches prio
exec-runtime sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
R netperf 3708 0.000000 206988 9
0.000000 3237.342882 2155.844073


Any ideas on this? The patch I sent fixes the problem. The idea came
from a proposed patch a long time ago that just added a hrtimer_cancel
call just before the hrtimer_start call in the sch_api.c watchdog
code. I figured if the explicit cancel before the start fixed the
problem, there was something that the cancel did that the start alone
didn't. What I found was that the cancel waits if the timer is
currently running, while start just brute-force cancels the timer.

--Vernon
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

\
 
 \ /
  Last update: 2011-01-22 00:09    [W:0.080 / U:0.260 seconds]
©2003-2014 Jasper Spaans. Advertise on this site